Browse code

c4w: log how much time we took without the callbacks too.

Török Edvin authored on 2010/12/08 18:23:58
Showing 1 changed files
... ...
@@ -693,6 +693,7 @@ int CLAMAPI Scan_ScanObject(CClamAVScanner *pScanner, const wchar_t *pObjectPath
693 693
 struct scan_ctx {
694 694
     int entryfd;
695 695
     instance *inst;
696
+    DWORD cb_times;
696 697
 };
697 698
 
698 699
 int CLAMAPI Scan_ScanObjectByHandle(CClamAVScanner *pScanner, HANDLE object, int *pScanStatus, PCLAM_SCAN_INFO_LIST *pInfoList) {
... ...
@@ -740,6 +741,7 @@ int CLAMAPI Scan_ScanObjectByHandle(CClamAVScanner *pScanner, HANDLE object, int
740 740
 
741 741
     sctx.entryfd = fd;
742 742
     sctx.inst = inst;
743
+    sctx.cb_times = 0;
743 744
     logg("Scan_ScanObjectByHandle (instance %p) invoking cl_scandesc with clamav context %p\n", inst, &sctx);
744 745
     perf = GetTickCount();
745 746
     res = cl_scandesc_callback(fd, &virname, NULL, engine, inst->scanopts, &sctx);
... ...
@@ -772,13 +774,14 @@ int CLAMAPI Scan_ScanObjectByHandle(CClamAVScanner *pScanner, HANDLE object, int
772 772
 	cbperf = GetTickCount();
773 773
 	inst->scancb(&si, &act, inst->scancb_ctx);
774 774
 	cbperf = GetTickCount() - cbperf;
775
+	sctx.cb_times += cbperf;
775 776
 	logg("final_cb (clamav context %p, instance %p) callback completed with %u (result ignored) in %u ms\n", &sctx, inst, act, cbperf);
776 777
 	SetFilePointer(duphdl, lo, &hi, FILE_BEGIN);
777 778
     } while(0);
778 779
 
779 780
     perf = GetTickCount() - perf;
780 781
     close(fd);
781
-    logg("Scan_ScanObjectByHandle (instance %p): cl_scandesc returned %d in %u ms\n", inst, res, perf);
782
+    logg("Scan_ScanObjectByHandle (instance %p): cl_scandesc returned %d in %u ms (%d ms own)\n", inst, res, perf, perf - sctx.cb_times);
782 783
 
783 784
     if(lock_instances())
784 785
 	FAIL(CL_ELOCK, "failed to lock instances for instance %p", pScanner);
... ...
@@ -871,6 +874,7 @@ cl_error_t prescan_cb(int fd, void *context) {
871 871
     perf = GetTickCount();
872 872
     inst->scancb(&si, &act, inst->scancb_ctx);
873 873
     perf = GetTickCount() - perf;
874
+    sctx->cb_times += perf;
874 875
     logg("prescan_cb (clamav context %p, instance %p) callback completed with %u in %u ms\n", context, inst, act, perf);
875 876
     SetFilePointer(fdhdl, lo, &hi, FILE_BEGIN);
876 877
     switch(act) {
... ...
@@ -928,6 +932,7 @@ cl_error_t postscan_cb(int fd, int result, const char *virname, void *context) {
928 928
     perf = GetTickCount();
929 929
     inst->scancb(&si, &act, inst->scancb_ctx);
930 930
     perf = GetTickCount() - perf;
931
+    sctx->cb_times += perf;
931 932
     logg("postscan_cb (clamav context %p, instance %p) callback completed with %u in %u ms\n", context, inst, act, perf);
932 933
     SetFilePointer(fdhdl, lo, &hi, FILE_BEGIN);
933 934
     switch(act) {