Browse code

c4w: add more time measurement

Török Edvin authored on 2011/02/10 20:42:39
Showing 1 changed files
... ...
@@ -831,6 +831,7 @@ struct scan_ctx {
831 831
     int entryfd;
832 832
     instance *inst;
833 833
     DWORD cb_times;
834
+    DWORD copy_times;
834 835
 };
835 836
 
836 837
 int CLAMAPI Scan_ScanObjectByHandle(CClamAVScanner *pScanner, HANDLE object, int *pScanStatus, PCLAM_SCAN_INFO_LIST *pInfoList) {
... ...
@@ -879,6 +880,7 @@ int CLAMAPI Scan_ScanObjectByHandle(CClamAVScanner *pScanner, HANDLE object, int
879 879
     sctx.entryfd = fd;
880 880
     sctx.inst = inst;
881 881
     sctx.cb_times = 0;
882
+    sctx.copy_times = 0;
882 883
     logg("*Scan_ScanObjectByHandle (instance %p) invoking cl_scandesc with clamav context %p\n", inst, &sctx);
883 884
     perf = GetTickCount();
884 885
     res = cl_scandesc_callback(fd, &virname, NULL, engine, inst->scanopts, &sctx);
... ...
@@ -919,7 +921,7 @@ int CLAMAPI Scan_ScanObjectByHandle(CClamAVScanner *pScanner, HANDLE object, int
919 919
 
920 920
     perf = GetTickCount() - perf;
921 921
     close(fd);
922
-    logg("*Scan_ScanObjectByHandle (instance %p): cl_scandesc returned %d in %u ms (%d ms own)\n", inst, res, perf, perf - sctx.cb_times);
922
+    logg("*Scan_ScanObjectByHandle (instance %p): cl_scandesc returned %d in %u ms (%d ms own, %d ms copy)\n", inst, res, perf, perf - sctx.cb_time - sctx.copy_times, sctx.copy_times);
923 923
 
924 924
     if(lock_instances())
925 925
 	FAIL(CL_ELOCK, "failed to lock instances for instance %p", pScanner);
... ...
@@ -992,7 +994,7 @@ cl_error_t prescan_cb(int fd, void *context) {
992 992
     CLAM_SCAN_INFO si;
993 993
     CLAM_ACTION act;
994 994
     HANDLE fdhdl;
995
-    DWORD perf;
995
+    DWORD perf, perf2 = 0;
996 996
 
997 997
     if(!context) {
998 998
 	logg("!prescan_cb called with NULL clamav context\n");
... ...
@@ -1009,6 +1011,7 @@ cl_error_t prescan_cb(int fd, void *context) {
1009 1009
     si.pInnerObjectPath = NULL;
1010 1010
 
1011 1011
     if(si.scanPhase == SCAN_PHASE_PRESCAN) {
1012
+	perf2 = GetTickCount();
1012 1013
 	long fpos;
1013 1014
 	int rsz;
1014 1015
 	while(1) {
... ...
@@ -1051,6 +1054,8 @@ cl_error_t prescan_cb(int fd, void *context) {
1051 1051
 	SetFilePointer(fdhdl, 0, NULL, FILE_BEGIN);
1052 1052
 	si.object = fdhdl;
1053 1053
 	si.objectId = (HANDLE)_get_osfhandle(fd);
1054
+	perf2 = GetTickCount() - perf2;
1055
+	sctx.copy_times -= perf2;
1054 1056
     } else { /* SCAN_PHASE_INITIAL */
1055 1057
 	si.object = INVALID_HANDLE_VALUE;
1056 1058
 	si.objectId = INVALID_HANDLE_VALUE;
... ...
@@ -1060,7 +1065,7 @@ cl_error_t prescan_cb(int fd, void *context) {
1060 1060
     inst->scancb(&si, &act, inst->scancb_ctx);
1061 1061
     perf = GetTickCount() - perf;
1062 1062
     sctx->cb_times += perf;
1063
-    logg("*prescan_cb (clamav context %p, instance %p) callback completed with %u in %u ms\n", context, inst, act, perf);
1063
+    logg("*prescan_cb (clamav context %p, instance %p) callback completed with %u in %u + %u ms\n", context, inst, act, perf, perf2);
1064 1064
     switch(act) {
1065 1065
 	case CLAM_ACTION_SKIP:
1066 1066
 	    logg("*prescan_cb (clamav context %p, instance %p) cb result: SKIP\n", context, inst);