Add extra logging to analyze COMMIT commands.

FossilOrigin-Name: 7dbb43bd307b5e297e6b2deac4e1d73d8cd68e37d880a5ecf5a3918a53e99d9d

diff --git a/manifest b/manifest
index 0fc78d153643b4864f0dd8d85a3b732b73a8a8eb..aee7bbf9afe924b4af2e85f901c7cca7baa0ba2c 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Update\sspecial\slogging\smessages\son\sthis\sbranch\sto\ssay\s"v=6"\sinstead\sof\s"v=5".
-D 2024-10-25T18:37:00.723
+C Add\sextra\slogging\sto\sanalyze\sCOMMIT\scommands.
+D 2024-10-30T18:24:33.020
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@@ -846,10 +846,10 @@ F src/utf.c f23165685a67b4caf8ec08fb274cb3f319103decfb2a980b7cfd55d18dfa855e
 F src/util.c 5d1a0134cf4240648d1c6bb5cc8efaca0ea2b5d5c840985aec7e947271f04375
 F src/vacuum.c 25e407a6dc8b288fa4295b3d92fa9ce9318503e84df53cdf403a50fccbc1ba31
 F src/vdbe.c fea60cfe46d8839a08e4680d90a96898d542d3f6d7954e2e99cd92596f1a01f8
-F src/vdbe.h e0569d3f32eab55c97e0524f68548e83149dedd1278db69b74ba9e1aeb5c9cf8
+F src/vdbe.h 49fef91a8f19ef44e1f4a5819de9c344ea13f2363342ed9d82a20aee33e44b81
 F src/vdbeInt.h 92b7eabbaadbe8127741cd96e7e39c4834c2bb0b75987d5f6251975f47233690
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c 93d4374bbdb091a5ff348e7fe9a55dfec6e69087bffe7821d8474fdd62cc56bf
+F src/vdbeaux.c fc9738bf10a52c6271fbff6b5f1f2a7fb8daf23e8ef952c1efdf87611e04d4e0
 F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797
 F src/vdbemem.c 831a244831eaa45335f9ae276b50a7a82ee10d8c46c2c72492d4eb8c98d94d89
 F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f
@@ -857,7 +857,7 @@ F src/vdbetrace.c fe0bc29ebd4e02c8bc5c1945f1d2e6be5927ec12c06d89b03ef2a4def34bf8
 F src/vdbevtab.c fc46b9cbd759dc013f0b3724549cc0d71379183c667df3a5988f7e2f1bd485f3
 F src/vtab.c 5fb499d20494b7eecaadb7584634af9afcb374cb0524912b475fcb1712458a1b
 F src/vxworks.h d2988f4e5a61a4dfe82c6524dd3d6e4f2ce3cdb9
-F src/wal.c c1109f1e9c86fa84b65ca6e38f8db7507985993e24d43224421212f5d817a953
+F src/wal.c b2bee7bbcdfbb4f9d4765c478a45c0801814123c20624f4f4f7453a7235794da
 F src/wal.h 8c59ee7a835574396d7cbd04626d11fd849613e361a46e7e9519091ab03bdb29
 F src/walker.c d5006d6b005e4ea7302ad390957a8d41ed83faa177e412f89bc5600a7462a014
 F src/where.c c046dd58c3410f7b7528e1e6317cb876398557bad346d568ed8562321a7d002d
@@ -2249,8 +2249,8 @@ F vsixtest/vsixtest.tcl 6195aba1f12a5e10efc2b8c0009532167be5e301abe5b31385638080
 F vsixtest/vsixtest.vcxproj.data 2ed517e100c66dc455b492e1a33350c1b20fbcdc
 F vsixtest/vsixtest.vcxproj.filters 37e51ffedcdb064aad6ff33b6148725226cd608e
 F vsixtest/vsixtest_TemporaryKey.pfx e5b1b036facdb453873e7084e1cae9102ccc67a0
-P fcd68bebf27e10e4e49efad220c9f53b7a109696d8b41e24f88c02460197b93f
-R 55f19018b52b5dfe7531f40b0b39acb3
+P af4e778bd3bdf30cac3d9a6266f105a8cd71f947b8d71249ef74b8fdc0505dd7
+R 128557cbc094e3ab9c4d3b4c1019317e
 U dan
-Z 34ac8be8f57c2f9a313183f66b283f0e
+Z 44c8796ec22b939c2d8fb7f81d4f2691
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index 1c1ff244c0b2b1761b7c6c930b45c1ba6817eadc..67947343ca633e91332398abc64d3a13ed8e1f1e 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-af4e778bd3bdf30cac3d9a6266f105a8cd71f947b8d71249ef74b8fdc0505dd7
+7dbb43bd307b5e297e6b2deac4e1d73d8cd68e37d880a5ecf5a3918a53e99d9d

diff --git a/src/vdbe.h b/src/vdbe.h
index 9d4e42787056df65340a90e336f5ad96c302fedd..307e9b63604df35abd3d2831115e5e8fe85bc60f 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -440,19 +440,21 @@ int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr);
 #define COMMIT_TIME_RELOCATE2COUNT 9
 
 #define COMMIT_TIME_AFTER_FIXUNLOCKED 10
-#define COMMIT_TIME_AFTER_WALFRAMES 11
 
-#define COMMIT_TIME_BEFORE_PHASETWO 12
-#define COMMIT_TIME_AFTER_PHASETWO 13
+#define COMMIT_TIME_OSWRITE 11
+#define COMMIT_TIME_AFTER_WALFRAMES 12
 
-#define COMMIT_TIME_AFTER_VDBECOMMIT 14
-#define COMMIT_TIME_AFTER_HALT 15
-#define COMMIT_TIME_FINISH 16
+#define COMMIT_TIME_BEFORE_PHASETWO 13
+#define COMMIT_TIME_AFTER_PHASETWO 14
 
-#define COMMIT_TIME_N 17
+#define COMMIT_TIME_AFTER_VDBECOMMIT 15
+#define COMMIT_TIME_AFTER_HALT 16
+#define COMMIT_TIME_FINISH 17
+
+#define COMMIT_TIME_N 18
 
 /* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */
-#define COMMIT_TIME_TIMEOUT (10*1000)         /* 10ms threshold */
+#define COMMIT_TIME_TIMEOUT (0*1000)         /* 10ms threshold */
 
 void sqlite3CommitTimeLog(u64*);
 u64 sqlite3STimeNow();

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index bde66dae2ebae4ff7f62e9b1b3cbc8a923da37ac..02d9cfff4c1d9705189bafa2b2d232009b6b4eee 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -5469,18 +5469,22 @@ void sqlite3CommitTimeLog(u64 *aCommit){
     for(ii=1; ii<COMMIT_TIME_N; ii++){
       int iVal;
       const char *zHash = "";
+      const char *zU = "";
       if( ii==COMMIT_TIME_RELOCATE1COUNT
        || ii==COMMIT_TIME_RELOCATE2COUNT
        || ii==COMMIT_TIME_OTHERWRITERS
       ){
         iVal = (int)aCommit[ii];
         zHash = "#";
+      }else if( ii==COMMIT_TIME_OSWRITE ){
+        iVal = (int)aCommit[ii];
+        zU = "us";
       }else{
         iVal = (aCommit[ii]==0 ? 0 : (int)(aCommit[ii] - i1));
       }
-      zStr = sqlite3_mprintf("%z%s%s%d", zStr, (zStr?", ":""), zHash, iVal);
+      zStr = sqlite3_mprintf("%z%s%s%d%s", zStr, (zStr?", ":""),zHash,iVal,zU);
     }
-    sqlite3_log(SQLITE_WARNING, "slow commit (v=6): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=7): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }
@@ -5508,7 +5512,7 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
     }
     if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
     sqlite3_log(SQLITE_WARNING, 
-        "slow prepare (v=6): (%s) [%.*s]", zStr, nByte, zSql
+        "slow prepare (v=7): (%s) [%.*s]", zStr, nByte, zSql
     );
     sqlite3_free(zStr);
   }
@@ -5524,7 +5528,7 @@ void sqlite3SchemaTimeLog(u64 *aSchema){
         (aSchema[ii]==0 ? 0 : (int)(aSchema[ii] - i1))
       );
     }
-    sqlite3_log(SQLITE_WARNING, "slow schema (v=6): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow schema (v=7): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }

diff --git a/src/wal.c b/src/wal.c
index 09f5d22635b3e4fa7ccadb79c54c20d66c25daa1..bf524bdd2a8db17c5daca9d005101a72cf32547a 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -5048,6 +5048,7 @@ static int walWriteToLog(
   sqlite3_int64 iOffset      /* Start writing at this offset */
 ){
   int rc;
+  u64 t;
   if( iOffset<p->iSyncPoint && iOffset+iAmt>=p->iSyncPoint ){
     int iFirstAmt = (int)(p->iSyncPoint - iOffset);
     rc = sqlite3OsWrite(p->pFd, pContent, iFirstAmt, iOffset);
@@ -5059,7 +5060,13 @@ static int walWriteToLog(
     rc = sqlite3OsSync(p->pFd, WAL_SYNC_FLAGS(p->syncFlags));
     if( iAmt==0 || rc ) return rc;
   }
+  if( p->pWal->aCommitTime ){
+    t = sqlite3STimeNow();
+  }
   rc = sqlite3OsWrite(p->pFd, pContent, iAmt, iOffset);
+  if( p->pWal->aCommitTime ){
+    p->pWal->aCommitTime[COMMIT_TIME_OSWRITE] += (sqlite3STimeNow() - t);
+  }
   return rc;
 }