Update the "tserver" program to report the amount of time spent in COMMIT

commands.

FossilOrigin-Name: cf494b412c941704ff73b0d100c55eb9bd268ee156db88b3e60512d501689e8e

diff --git a/manifest b/manifest
index 5ca7d514a7d9e65fd4ad13f521420c89bed5638e..1db5272ed195a1390e8439ab18a1c86474744a33 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Merge\schanges\sfrom\sbegin-concurrent-wal2.\sAlso\smodify\sthe\sunix-excl\sshm-locks\non\sthis\sbranch\sso\sthat\sit\sis\snot\san\serror\sto\sattempt\sto\srelease\san\sEXCLUSIVE\nlock\sthat\sis\snot\sheld.
-D 2019-01-02T19:46:46.309
+C Update\sthe\s"tserver"\sprogram\sto\sreport\sthe\samount\sof\stime\sspent\sin\sCOMMIT\ncommands.
+D 2019-01-04T17:12:28.743
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F Makefile.in d8b254f8bb81bab43c340d70d17dc3babab40fcc8a348c8255881f780a45fee6
@@ -1794,8 +1794,8 @@ F tool/srcck1.c 371de5363b70154012955544f86fdee8f6e5326f
 F tool/stack_usage.tcl f8e71b92cdb099a147dad572375595eae55eca43
 F tool/symbols-mingw.sh 4dbcea7e74768305384c9fd2ed2b41bbf9f0414d
 F tool/symbols.sh c5a617b8c61a0926747a56c65f5671ef8ac0e148
-F tool/tserver.c 434336a4566415b6917d1b9cf1834cbb3a5b03756c6ad83bbe68f135f64c68e5
-F tool/tserver_test.tcl 54f4e543cbef41bf4b061e1774fa2af6c7ed89e5982316a3c10080fac6203b56
+F tool/tserver.c 17b7f0b06f4e776e26220889941a86936b3c56ad18608baadc8faa00b7bd46ee
+F tool/tserver_test.tcl 15a3933a683322d7188415997f96b10fe05e1c17edf9d6a07189cbf3cbb86862
 F tool/varint.c 5d94cb5003db9dbbcbcc5df08d66f16071aee003
 F tool/vdbe-compress.tcl 5926c71f9c12d2ab73ef35c29376e756eb68361c
 F tool/vdbe_profile.tcl 246d0da094856d72d2c12efec03250d71639d19f
@@ -1823,7 +1823,7 @@ F vsixtest/vsixtest.tcl 6a9a6ab600c25a91a7acc6293828957a386a8a93
 F vsixtest/vsixtest.vcxproj.data 2ed517e100c66dc455b492e1a33350c1b20fbcdc
 F vsixtest/vsixtest.vcxproj.filters 37e51ffedcdb064aad6ff33b6148725226cd608e
 F vsixtest/vsixtest_TemporaryKey.pfx e5b1b036facdb453873e7084e1cae9102ccc67a0
-P c3191fc8fcb0775f87f55cb8124e0c36caa54993c2a5fe770d437e4f6ee72d77 fcb7348ba190e48112a681f704313a733f7a377456e7c1d6845ba34c270d86b6
-R 7956ec08206a96fcab5ff68438fad94b
+P 86685679b4cff94704fe4b52364f25f579d98ee725407cfe3bd2bbf7ecd651a8
+R a4de690f8f0864c8cb85d828dc4c1801
 U dan
-Z 041b665514beb78a4e6ea7c8171737de
+Z 79094d27a977c73ac7234af9077413ec

diff --git a/manifest.uuid b/manifest.uuid
index 149a8ef0cc01a057d93457ed159fba9838a262ca..bd4845659ab41ba70839f761c402678c6d88dd4e 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-86685679b4cff94704fe4b52364f25f579d98ee725407cfe3bd2bbf7ecd651a8
\ No newline at end of file
+cf494b412c941704ff73b0d100c55eb9bd268ee156db88b3e60512d501689e8e
\ No newline at end of file

diff --git a/tool/tserver.c b/tool/tserver.c
index 6916a5781edf527fd7706865175ca5a03a31cbb6..3c0768714bf7e69e3f8f4ce61ed9c4725c4ca424 100644 (file)
--- a/tool/tserver.c
+++ b/tool/tserver.c
@@ -202,10 +202,13 @@ static int handle_some_sql(ClientCtx *p, const char *zSql, int nSql){
   return rc;
 }
 
+/*
+** Return a micro-seconds resolution timer.
+*/
 static sqlite3_int64 get_timer(void){
   struct timeval t;
   gettimeofday(&t, 0);
-  return ((sqlite3_int64)t.tv_usec / 1000) + ((sqlite3_int64)t.tv_sec * 1000);
+  return (sqlite3_int64)t.tv_usec + ((sqlite3_int64)t.tv_sec * 1000000);
 }
 
 static void clear_sql(ClientCtx *p){
@@ -238,6 +241,7 @@ static int handle_run_command(ClientCtx *p){
   int nBusy = 0;
   sqlite3_int64 t0 = get_timer();
   sqlite3_int64 t1 = t0;
+  sqlite3_int64 tCommit = 0;
   int nT1 = 0;
   int nTBusy1 = 0;
   int rc = SQLITE_OK;
@@ -246,7 +250,6 @@ static int handle_run_command(ClientCtx *p){
   g.nRun++;
   pthread_mutex_unlock(&g.ckpt_mutex);
 
-
   for(j=0; (p->nRepeat<=0 || j<p->nRepeat) && rc==SQLITE_OK; j++){
     sqlite3_int64 t2;
 
@@ -257,12 +260,13 @@ static int handle_run_command(ClientCtx *p){
       ** the SQL statement (which is always "COMMIT" in this case). */
       if( p->aPrepare[i].flags & TSERVER_CLIENTSQL_MUTEX ){
         sqlite3_mutex_enter(g.commit_mutex);
+        tCommit -= get_timer();
       }
 
       /* Execute the statement */
       if( p->aPrepare[i].flags & TSERVER_CLIENTSQL_INTEGRITY ){
         sqlite3_step(pStmt);
-        if( sqlite3_stricmp("ok", sqlite3_column_text(pStmt, 0)) ){
+        if( sqlite3_stricmp("ok", (const char*)sqlite3_column_text(pStmt, 0)) ){
           send_message(p, "error - integrity_check failed: %s\n", 
               sqlite3_column_text(pStmt, 0)
           );
@@ -274,6 +278,7 @@ static int handle_run_command(ClientCtx *p){
 
       /* Relinquish the g.commit_mutex mutex if required. */
       if( p->aPrepare[i].flags & TSERVER_CLIENTSQL_MUTEX ){
+        tCommit += get_timer();
         sqlite3_mutex_leave(g.commit_mutex);
       }
 
@@ -293,18 +298,18 @@ static int handle_run_command(ClientCtx *p){
     }
 
     t2 = get_timer();
-    if( t2>=(t1+1000) ){
-      int nMs = (t2 - t1);
-      int nDone = (j+1 - nBusy - nT1);
+    if( t2>=(t1+1000000) ){
+      sqlite3_int64 nUs = (t2 - t1);
+      sqlite3_int64 nDone = (j+1 - nBusy - nT1);
 
       rc = send_message(
-          p, "(%d done @ %d per second, %d busy)\n", 
-          nDone, (1000*nDone + nMs/2) / nMs, nBusy - nTBusy1
-          );
+          p, "(%d done @ %lld per second, %d busy)\n", 
+          (int)nDone, (1000000*nDone + nUs/2) / nUs, nBusy - nTBusy1
+      );
       t1 = t2;
       nT1 = j+1 - nBusy;
       nTBusy1 = nBusy;
-      if( p->nSecond>0 && (p->nSecond*1000)<=t1-t0 ) break;
+      if( p->nSecond>0 && ((sqlite3_int64)p->nSecond*1000000)<=t1-t0 ) break;
     }
 
     /* Global checkpoint handling. */
@@ -336,10 +341,12 @@ static int handle_run_command(ClientCtx *p){
   }
 
   if( rc==SQLITE_OK ){
-    int nMs = (int)(get_timer() - t0);
+    int nMs = (get_timer() - t0) / 1000;
     send_message(p, "ok (%d/%d SQLITE_BUSY)\n", nBusy, j);
     if( p->nRepeat<=0 ){
-      send_message(p, "### ok %d busy %d ms %d\n", j-nBusy, nBusy, nMs);
+      send_message(p, "### ok %d busy %d ms %d commit-ms %d\n", 
+          j-nBusy, nBusy, nMs, (int)(tCommit / 1000)
+      );
     }
   }
   clear_sql(p);

diff --git a/tool/tserver_test.tcl b/tool/tserver_test.tcl
index 3ef1a905983aa163ba85f05f53146e690fa6f84e..1ea69ecb8b485326b1f673207df80d0e8f1f472a 100644 (file)
--- a/tool/tserver_test.tcl
+++ b/tool/tserver_test.tcl
@@ -151,7 +151,7 @@ proc create_test_database {} {
 set ::tserver {}
 proc tserver_start {} {
   global O
-  set cmd "|$O(-tserver) -vfs unix "
+  set cmd "|$O(-tserver) -vfs unix-excl "
   if {$O(-mode)=="wal2"} {
     append cmd " -walautocheckpoint 0 "
   }