Trying to find out why CPU is idle while it should be working hard!!

git-svn-id: http://svn.pjsip.org/repos/pjproject/trunk@257 74dad513-b988-da41-8d7b-12977e46ad98

3 files changed, 16 insertions, 9 deletions

diff --git a/pjsip-apps/build/pjsip_perf.dsp b/pjsip-apps/build/pjsip_perf.dsp
index 0dd95772..2c258619 100644
--- a/pjsip-apps/build/pjsip_perf.dsp
+++ b/pjsip-apps/build/pjsip_perf.dsp
@@ -74,7 +74,7 @@ BSC32=bscmake.exe
 # ADD BSC32 /nologo
 LINK32=link.exe
 # ADD BASE LINK32 kernel32.lib user32.lib gdi32.lib winspool.lib comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib uuid.lib odbc32.lib odbccp32.lib kernel32.lib user32.lib gdi32.lib winspool.lib comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib uuid.lib odbc32.lib odbccp32.lib /nologo /subsystem:console /debug /machine:I386 /pdbtype:sept
-# ADD LINK32 netapi32.lib mswsock.lib ws2_32.lib kernel32.lib user32.lib gdi32.lib winspool.lib comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib uuid.lib odbc32.lib odbccp32.lib kernel32.lib user32.lib gdi32.lib winspool.lib comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib uuid.lib odbc32.lib odbccp32.lib /nologo /subsystem:console /debug /machine:I386 /out:"..\bin\pjsip-perf-i386-win32-vc6d.exe" /pdbtype:sept
+# ADD LINK32 netapi32.lib mswsock.lib ws2_32.lib kernel32.lib user32.lib gdi32.lib winspool.lib comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib uuid.lib odbc32.lib odbccp32.lib kernel32.lib user32.lib gdi32.lib winspool.lib comdlg32.lib advapi32.lib shell32.lib ole32.lib oleaut32.lib uuid.lib odbc32.lib odbccp32.lib /nologo /subsystem:console /profile /debug /machine:I386 /out:"..\bin\pjsip-perf-i386-win32-vc6d.exe"
 
 !ENDIF 
 
diff --git a/pjsip-apps/src/pjsip-perf/main.c b/pjsip-apps/src/pjsip-perf/main.c
index 91817e2c..df75c2d8 100644
--- a/pjsip-apps/src/pjsip-perf/main.c
+++ b/pjsip-apps/src/pjsip-perf/main.c
@@ -366,18 +366,27 @@ static void completion_cb(void *token, pj_bool_t success)
 	pj_gettimeofday(&batch->end_time);
 	elapsed = sess_elapsed = batch->end_time;
 
+	/* Batch time. */
 	PJ_TIME_VAL_SUB(elapsed, batch->start_time);
-	PJ_TIME_VAL_SUB(sess_elapsed, settings.session->start_time);
 	msec = PJ_TIME_VAL_MSEC(elapsed);
 	if (msec == 0) msec = 1;
 
-	PJ_LOG(3,(THIS_FILE, "%02d:%02d:%02d: %d tasks in %d.%ds (%d tasks/sec)",
+	/* Session time */
+	PJ_TIME_VAL_SUB(sess_elapsed, settings.session->start_time);
+
+	/* Spawn time */
+	PJ_TIME_VAL_SUB(batch->spawned_time, batch->start_time);
+
+	PJ_LOG(3,(THIS_FILE, "%02d:%02d:%02d: %d tasks in %d.%ds (%d tasks/sec), "
+			     "spawn=time=%d.%d",
 			     (sess_elapsed.sec / 3600),
 			     (sess_elapsed.sec % 3600) / 60,
 			     (sess_elapsed.sec % 60),
 			     batch->rate,
 			     elapsed.sec, elapsed.msec,
-			     batch->rate * 1000 / msec));
+			     batch->rate * 1000 / msec,
+			     batch->spawned_time.sec,
+			     batch->spawned_time.msec));
 
 	if (!settings.session->stopping) {
 	    pj_time_val interval;
@@ -407,7 +416,6 @@ static void spawn_batch( pj_timer_heap_t *timer_heap,
     batch *batch;
     pj_status_t status = PJ_SUCCESS;
     pjsip_cred_info cred_info[1];
-    pj_time_val now, spawn_time, sess_time;
 
     unsigned i;
 
@@ -423,6 +431,7 @@ static void spawn_batch( pj_timer_heap_t *timer_heap,
     batch->started = 0;
     batch->success = 0;
     batch->failed = 0;
+    pj_gettimeofday(&batch->start_time);
 
     pj_list_push_back(&sess->active_list, batch);
 
@@ -446,10 +455,7 @@ static void spawn_batch( pj_timer_heap_t *timer_heap,
 	batch->started++;
     }
 
-    pj_gettimeofday(&now);
-    spawn_time = sess_time = now;
-    PJ_TIME_VAL_SUB(spawn_time, batch->start_time);
-    PJ_TIME_VAL_SUB(sess_time, sess->start_time);
+    pj_gettimeofday(&batch->spawned_time);
 
     sess->total_created += batch->started;
     
diff --git a/pjsip-apps/src/pjsip-perf/pjsip_perf.h b/pjsip-apps/src/pjsip-perf/pjsip_perf.h
index 103ea205..f84a37f3 100644
--- a/pjsip-apps/src/pjsip-perf/pjsip_perf.h
+++ b/pjsip-apps/src/pjsip-perf/pjsip_perf.h
@@ -40,6 +40,7 @@ struct batch
     unsigned	 success;
     unsigned	 failed;
     pj_time_val	 start_time;
+    pj_time_val	 spawned_time;
     pj_time_val	 end_time;
 };