Extra logging to debug slow commit statements.

FossilOrigin-Name: 9cafae1fff34ff45772910d6f2a19d08038edea4327234f577f6da30e5baa558

diff --git a/manifest b/manifest
index 491c75a9658360e526e59214b3054b8535ccdef3..aef900725e01d33428b96bb248d432b978fbc798 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Add\sstill\smore\slogging\sto\sdetermine\swhy\sschema\sloads\sare\sso\sslow\sin\ssome\scircumstances.
-D 2024-10-22T16:26:14.924
+C Extra\slogging\sto\sdebug\sslow\scommit\sstatements.
+D 2024-10-23T17:16:59.865
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@@ -713,7 +713,7 @@ F src/auth.c 4c1ea890e0069ad73bead5d17a5b12c34cfa4f1a24175c8147ea439b64be271c
 F src/backup.c 5c97e8023aab1ce14a42387eb3ae00ba5a0644569e3476f38661fa6f824c3523
 F src/bitvec.c 501daeef838fa82a9fb53540d72f29e3d9172c8867f1e19f94f681e2e20b966e
 F src/btmutex.c 79a43670447eacc651519a429f6ece9fd638563cf95b469d6891185ddae2b522
-F src/btree.c 27981b16cd21722b4e2ef8afcbb159f9e8fb54e4b2f8187cfd4b912a13d628d5
+F src/btree.c 19e6f78bc14bcbebce2f274e3c774d4e3a6406b9f484106eba3432ecbfc9a155
 F src/btree.h bdeeb35614caa33526b603138f04c8d07a3f90a1300b5ade76848b755edf2027
 F src/btreeInt.h caa893e74d2261fb0ff1681fce998533c0552858e882bd04fc6805075f5f6e75
 F src/build.c 08697d6a4df78f8e289582eb58473445492319676f81cc4794ef4056d36ae5fd
@@ -779,7 +779,7 @@ F src/shell.c.in 40de636c1d90fb8a9ca7f49dc8f50d930f1b60736e73aca5eb37c4c7d0e47f9
 F src/sqlite.h.in b7ff496637807ae88b2557039fc940518db328bf5d5621e2f7c048dfba32a52b
 F src/sqlite3.rc 5121c9e10c3964d5755191c80dd1180c122fc3a8
 F src/sqlite3ext.h 3f046c04ea3595d6bfda99b781926b17e672fd6d27da2ba6d8d8fc39981dcb54
-F src/sqliteInt.h 0c3db4598b7b9c6aced18496bd6b1f6f56f2d739ff30297e5051093f1b4cfcc2
+F src/sqliteInt.h 55838cada3b79d88a891e557759f444f2a007c77f61f7a731d00d1df6d95e555
 F src/sqliteLimit.h 6878ab64bdeb8c24a1d762d45635e34b96da21132179023338c93f820eee6728
 F src/status.c cb11f8589a6912af2da3bb1ec509a94dd8ef27df4d4c1a97e0bcf2309ece972b
 F src/table.c 0f141b58a16de7e2fbe81c308379e7279f4c6b50eb08efeec5892794a0ba30d1
@@ -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 ed70dc763f22fe856884cc065473061bfe9954bd221daaf3ac517f01c33d0b0f
-F src/vdbeInt.h 494b7b3430fb53adef43e5fd9ede20029750f188f2dbb064e7b86cdf9fb755d7
+F src/vdbe.h e0569d3f32eab55c97e0524f68548e83149dedd1278db69b74ba9e1aeb5c9cf8
+F src/vdbeInt.h 92b7eabbaadbe8127741cd96e7e39c4834c2bb0b75987d5f6251975f47233690
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c 16323344b313db01298573fd52816f20501311a36aa825f5f0bd7afa2fd811a2
+F src/vdbeaux.c c73029037e1b007d09b181ce28072f5acb72ade3c1cf5223a76f5f9d22eb9d3c
 F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797
 F src/vdbemem.c 831a244831eaa45335f9ae276b50a7a82ee10d8c46c2c72492d4eb8c98d94d89
 F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f
@@ -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 08e1dea9c070c9a2d668d39ceb153bc8b6d172e7273f6564a374c43055e84461
-R 94bb34a3eda8f372bde8de70614acb52
+P d02ec06e5bde7c8dc0f21ca2bfc44597aca015854d5656f851f4518476d04381
+R b65017689ad2d81f5d73f6e135fe482d
 U dan
-Z a1cf697854d2ed08ac2ba1f2daa0689c
+Z 612ec018a1f7656f6d7836af43be4910
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index e88be74e9fac8dbe3a1741d6f4786b22b68e4a2e..349b8dbdb81e2b321a7a4cd06fbae50043f0a170 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-d02ec06e5bde7c8dc0f21ca2bfc44597aca015854d5656f851f4518476d04381
+9cafae1fff34ff45772910d6f2a19d08038edea4327234f577f6da30e5baa558

diff --git a/src/btree.c b/src/btree.c
index 9c2d3116ea33d5bfb1748d79389fb2b37d449651..c2c76ebc3ba36d005546cab351c64e400f78e0fd 100644 (file)
--- a/src/btree.c
+++ b/src/btree.c
@@ -4672,6 +4672,11 @@ static int btreeFixUnlocked(Btree *p){
             nFin--;
           }
           nFin = MAX(nFin, nHPage);
+          if( p->pBt->aCommitTime ){
+            p->pBt->aCommitTime[COMMIT_TIME_OTHERWRITERS] = (1+nHPage-pMap->iFirst);
+            p->pBt->aCommitTime[COMMIT_TIME_RELOCATE1COUNT] = (1+iLast-pMap->iFirst);
+            p->pBt->aCommitTime[COMMIT_TIME_RELOCATE2COUNT] = (nFin - nCurrent);
+          }
           sqlite3CommitTimeSet(
               p->pBt->aCommitTime, COMMIT_TIME_START_RELOCATE2
           );

diff --git a/src/sqliteInt.h b/src/sqliteInt.h
index d0501bb68318ad70664b301373c04bbfafbb8121..bf02a9d2f01f8ab4c5af620082cd04f8098f90be 100644 (file)
--- a/src/sqliteInt.h
+++ b/src/sqliteInt.h
@@ -1868,7 +1868,7 @@ struct sqlite3 {
 #define SCHEMA_TIME_FINISH 12
 
 #define SCHEMA_TIME_N 13
-#define SCHEMA_TIME_TIMEOUT (1 * 1000 * 1000)
+#define SCHEMA_TIME_TIMEOUT (2 * 1000 * 1000)
 
 
 

diff --git a/src/vdbe.h b/src/vdbe.h
index aca1b2dce237cfc81c8e1a8f6ecf2840e89e82be..9d4e42787056df65340a90e336f5ad96c302fedd 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -435,17 +435,21 @@ int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr);
 #define COMMIT_TIME_START_RELOCATE1 5
 #define COMMIT_TIME_START_RELOCATE2 6
 
-#define COMMIT_TIME_AFTER_FIXUNLOCKED 7
-#define COMMIT_TIME_AFTER_WALFRAMES 8
+#define COMMIT_TIME_OTHERWRITERS 7
+#define COMMIT_TIME_RELOCATE1COUNT 8
+#define COMMIT_TIME_RELOCATE2COUNT 9
 
-#define COMMIT_TIME_BEFORE_PHASETWO 9
-#define COMMIT_TIME_AFTER_PHASETWO 10
+#define COMMIT_TIME_AFTER_FIXUNLOCKED 10
+#define COMMIT_TIME_AFTER_WALFRAMES 11
 
-#define COMMIT_TIME_AFTER_VDBECOMMIT 11
-#define COMMIT_TIME_AFTER_HALT 12
-#define COMMIT_TIME_FINISH 13
+#define COMMIT_TIME_BEFORE_PHASETWO 12
+#define COMMIT_TIME_AFTER_PHASETWO 13
 
-#define COMMIT_TIME_N 14
+#define COMMIT_TIME_AFTER_VDBECOMMIT 14
+#define COMMIT_TIME_AFTER_HALT 15
+#define COMMIT_TIME_FINISH 16
+
+#define COMMIT_TIME_N 17
 
 /* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */
 #define COMMIT_TIME_TIMEOUT (10*1000)         /* 10ms threshold */

diff --git a/src/vdbeInt.h b/src/vdbeInt.h
index 2e9679a8eee58d9175a13f4087afd21f23a2f442..09cbc75408fed681d3ae350aac92eda264967371 100644 (file)
--- a/src/vdbeInt.h
+++ b/src/vdbeInt.h
@@ -137,8 +137,6 @@ struct VdbeCursor {
   ** static element declared in the structure.  nField total array slots for
   ** aType[] and nField+1 array slots for aOffset[] */
   u32 aType[1];           /* Type values record decode.  MUST BE LAST */
-
-  u8 *aCommit;
 };
 
 /* Return true if P is a null-only cursor

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index 04910280e721be2b5b167e5ca5b3d57e4423a895..ae1ec35c9e8ed7d6a1e6af468507981736a154eb 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -5467,11 +5467,20 @@ void sqlite3CommitTimeLog(u64 *aCommit){
     char *zStr = 0;
     int ii;
     for(ii=1; ii<COMMIT_TIME_N; ii++){
-      zStr = sqlite3_mprintf("%z%s%d", zStr, (zStr?", ":""), 
-        (aCommit[ii]==0 ? 0 : (int)(aCommit[ii] - i1))
-      );
+      int iVal;
+      const char *zHash = "";
+      if( ii==COMMIT_TIME_RELOCATE1COUNT
+       || ii==COMMIT_TIME_RELOCATE2COUNT
+       || ii==COMMIT_TIME_OTHERWRITERS
+      ){
+        iVal = (int)aCommit[ii];
+        zHash = "#";
+      }else{
+        iVal = (aCommit[ii]==0 ? 0 : (int)(aCommit[ii] - i1));
+      }
+      zStr = sqlite3_mprintf("%z%s%s%d", zStr, (zStr?", ":""), zHash, iVal);
     }
-    sqlite3_log(SQLITE_WARNING, "slow commit (v=4): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=5): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }
@@ -5499,7 +5508,7 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
     }
     if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
     sqlite3_log(SQLITE_WARNING, 
-        "slow prepare (v=4): (%s) [%.*s]", zStr, nByte, zSql
+        "slow prepare (v=5): (%s) [%.*s]", zStr, nByte, zSql
     );
     sqlite3_free(zStr);
   }
@@ -5515,7 +5524,7 @@ void sqlite3SchemaTimeLog(u64 *aSchema){
         (aSchema[ii]==0 ? 0 : (int)(aSchema[ii] - i1))
       );
     }
-    sqlite3_log(SQLITE_WARNING, "slow schema (v=4): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow schema (v=5): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }