Extra logging for the freelist and hash table components of COMMITs of BEGIN CONCURRE...

FossilOrigin-Name: 2ba41da8c437e466c71f65d67a615293efb5a2d9da9b6e9cbb7b296221d4104a

diff --git a/manifest b/manifest
index 9e211aeef6fe2f2b0aa7e1e7e3dab11ba785bc0e..a26b8c62a800dc651bb09c1df3ba5d0d0dc137a8 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Increase\smaximum\slength\sof\ssqlite3_log()\smessages\sto\s700\sbytes.\sMark\slog\smessages\sas\sv=10.
-D 2024-11-13T14:42:32.861
+C Extra\slogging\sfor\sthe\sfreelist\sand\shash\stable\scomponents\sof\sCOMMITs\sof\sBEGIN\sCONCURRENT\stransactions.
+D 2024-11-19T17:32:03.892
 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 68f32f71c33ab571b8d706940108c448e165d0c3d7317a1b5883d2b9dfcf2512
+F src/btree.c 2664c81f217a42afadc7c010bb4a175057d5e53b99e9512234eb74817f2ad59c
 F src/btree.h bdeeb35614caa33526b603138f04c8d07a3f90a1300b5ade76848b755edf2027
 F src/btreeInt.h caa893e74d2261fb0ff1681fce998533c0552858e882bd04fc6805075f5f6e75
 F src/build.c 08697d6a4df78f8e289582eb58473445492319676f81cc4794ef4056d36ae5fd
@@ -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 e439c7b44191828413f461eac23360ffbf0513fe57d129853f690c4ea4d46746
+F src/vdbe.h b7efae210f5aea8d4e7b6412f70b0b1c744dc397527339f68a186bf24c04198d
 F src/vdbeInt.h 92b7eabbaadbe8127741cd96e7e39c4834c2bb0b75987d5f6251975f47233690
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c 4f7e3fc42eea9612ae59ff5f123280507935be53d0d2e9ea474957b30f9e1f29
+F src/vdbeaux.c 6bc54bfbfa1b03d776e2efa76828128a964efd012d86b60ec892c659523d2548
 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 c5c772a50621548398bff23df38cc338c8b874188d1fa7bf975f3381f6071126
+F src/wal.c b15990d5cc1fbc418170a5d14bc32c84b955c29ab189056ad60db31f87ea72b2
 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 e0c0176793d41bef30e093975a87170981277dac20cde08e0fd3e0b6f40dca2f
-R 40d5d8e3822854d0b02030b6b7d7027f
+P 35aa893d4537d0b3605084a1f2f5529794e82af59b8893053815d3fcb4719a27
+R 1424c980ed8c56bd0af68164564ef6ef
 U dan
-Z 1f420b344bc232a0c739cabd514cf0b5
+Z cb872ff1639c1f0cfce91c12fa6be434
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index 7e973bcf72a86bff1926f4948f155e0ea08e63cf..ca3694bfd7d21360e96954ebb55cbabdd68224e0 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-35aa893d4537d0b3605084a1f2f5529794e82af59b8893053815d3fcb4719a27
+2ba41da8c437e466c71f65d67a615293efb5a2d9da9b6e9cbb7b296221d4104a

diff --git a/src/btree.c b/src/btree.c
index 941f27910fd286e6f39b06d6d0e75f34b5e3f30f..cb8aa1195040c6a6912010dca9497df262829413 100644 (file)
--- a/src/btree.c
+++ b/src/btree.c
@@ -4561,7 +4561,7 @@ static int btreeRelocateRange(
       if( pBt->aCommitTime ) t1 = sqlite3STimeNow();
       rc = allocateBtreePage(pBt, &pFree, &dummy, iPg, BTALLOC_EXACT);
       if( pBt->aCommitTime ){
-        pBt->aCommitTime[COMMIT_TIME_RELOCATE2_ALLOCATEUS] += (sqlite3STimeNow() - t1);
+        pBt->aCommitTime[COMMIT_TIME_RELOCATE2_EXACTUS] += (sqlite3STimeNow() - t1);
       }
       if( pFree ){
         assert( sqlite3PagerPageRefcount(pFree->pDbPage)==1 );

diff --git a/src/vdbe.h b/src/vdbe.h
index 6725bb5f3bed20475f5eea42f47e158a1b5e5794..b3df6f165a853a6af6438fea6c1e4fa5764ad395 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -441,39 +441,42 @@ int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr);
 
 #define COMMIT_TIME_RELOCATE2_READUS     10
 #define COMMIT_TIME_RELOCATE2_READCOUNT  11
-#define COMMIT_TIME_RELOCATE2_ALLOCATEUS 12
-#define COMMIT_TIME_RELOCATE2_RELOCATEUS 13
+#define COMMIT_TIME_RELOCATE2_EXACTUS    12
+#define COMMIT_TIME_RELOCATE2_ALLOCATEUS 13
+#define COMMIT_TIME_RELOCATE2_RELOCATEUS 14
 
-#define COMMIT_TIME_AFTER_FIXUNLOCKED 14
+#define COMMIT_TIME_AFTER_FIXUNLOCKED 15
 
-#define COMMIT_TIME_BEFORE_WALFRAMES 15
-#define COMMIT_TIME_AFTER_CHANGECOUNTER 16
-#define COMMIT_TIME_AFTER_RESTARTLOG 17
-#define COMMIT_TIME_AFTER_WRITEHDR 18
+#define COMMIT_TIME_BEFORE_WALFRAMES 16
+#define COMMIT_TIME_AFTER_CHANGECOUNTER 17
+#define COMMIT_TIME_AFTER_RESTARTLOG 18
+#define COMMIT_TIME_AFTER_WRITEHDR 19
 
-#define COMMIT_TIME_OSWRITE 19
+#define COMMIT_TIME_OSWRITE 20
 
-#define COMMIT_TIME_AFTER_WRITEFRAMES 20
+#define COMMIT_TIME_AFTER_WRITEFRAMES 21
 
-#define COMMIT_TIME_NFRAME            21
-#define COMMIT_TIME_HASHMAPUS         22
+#define COMMIT_TIME_NFRAME            22
+#define COMMIT_TIME_HASHMAPUS         23
 
-#define COMMIT_TIME_BEFORE_WALINDEX 23
-#define COMMIT_TIME_AFTER_WALINDEX 24
-#define COMMIT_TIME_AFTER_WALINDEXHDR 25
+#define COMMIT_TIME_BEFORE_WALINDEX 24
 
-#define COMMIT_TIME_WALFRAMESFLAGS 26
+#define COMMIT_TIME_WALINDEX_HASHGETUS 25
+#define COMMIT_TIME_WALINDEX_CLEANUPUS 26
+#define COMMIT_TIME_WALINDEX_ENTRYUS   27
 
-#define COMMIT_TIME_AFTER_WALFRAMES 27
+#define COMMIT_TIME_AFTER_WALINDEX 28
+#define COMMIT_TIME_AFTER_WALINDEXHDR 29
+#define COMMIT_TIME_WALFRAMESFLAGS 30
+#define COMMIT_TIME_AFTER_WALFRAMES 31
+#define COMMIT_TIME_BEFORE_PHASETWO 32
+#define COMMIT_TIME_AFTER_PHASETWO 33
 
-#define COMMIT_TIME_BEFORE_PHASETWO 28
-#define COMMIT_TIME_AFTER_PHASETWO 29
+#define COMMIT_TIME_AFTER_VDBECOMMIT 34
+#define COMMIT_TIME_AFTER_HALT 35
+#define COMMIT_TIME_FINISH 36
 
-#define COMMIT_TIME_AFTER_VDBECOMMIT 30
-#define COMMIT_TIME_AFTER_HALT 31
-#define COMMIT_TIME_FINISH 32
-
-#define COMMIT_TIME_N 33
+#define COMMIT_TIME_N 37
 
 /* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */
 #define COMMIT_TIME_TIMEOUT (10*1000)         /* 10ms threshold */

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index 390446c585abea3bf127e081fa54aa395d0ab633..6d77ca2ef47cef0bd4fbb4dfa06c8e784efbe711 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -5483,6 +5483,10 @@ void sqlite3CommitTimeLog(u64 *aCommit){
              || ii==COMMIT_TIME_RELOCATE2_ALLOCATEUS 
              || ii==COMMIT_TIME_RELOCATE2_RELOCATEUS 
              || ii==COMMIT_TIME_HASHMAPUS 
+             || ii==COMMIT_TIME_RELOCATE2_EXACTUS 
+             || ii==COMMIT_TIME_WALINDEX_HASHGETUS
+             || ii==COMMIT_TIME_WALINDEX_CLEANUPUS
+             || ii==COMMIT_TIME_WALINDEX_ENTRYUS
       ){
         iVal = (int)aCommit[ii];
         zU = "us";

diff --git a/src/wal.c b/src/wal.c
index 6c6219e8139ce1d59eb346a7d79399431fc3683e..117781aed0cb7ed1e1120d432a7cadab5fbfa37c 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -1621,6 +1621,7 @@ static int walIndexAppend(Wal *pWal, int iWal, u32 iFrame, u32 iPage){
   int rc;                         /* Return code */
   WalHashLoc sLoc;                /* Wal-index hash table location */
   u32 iExternal;
+  u64 t;
   
   if( isWalMode2(pWal) ){
     iExternal = walExternalEncode(iWal, iFrame);
@@ -1629,7 +1630,11 @@ static int walIndexAppend(Wal *pWal, int iWal, u32 iFrame, u32 iPage){
     iExternal = iFrame;
   }
 
+  if( pWal->aCommitTime ) t = sqlite3STimeNow();
   rc = walHashGet(pWal, walFramePage(iExternal), &sLoc);
+  if( pWal->aCommitTime ){
+    pWal->aCommitTime[COMMIT_TIME_WALINDEX_HASHGETUS] += sqlite3STimeNow()-t;
+  }
 
   /* Assuming the wal-index file was successfully mapped, populate the
   ** page number array and hash table entry.
@@ -1658,17 +1663,25 @@ static int walIndexAppend(Wal *pWal, int iWal, u32 iFrame, u32 iPage){
     ** the hash-table before writing any new entries.
     */
     if( sLoc.aPgno[idx-1] ){
+      if( pWal->aCommitTime ) t = sqlite3STimeNow();
       walCleanupHash(pWal);
       assert( !sLoc.aPgno[idx-1] );
+      if( pWal->aCommitTime ){
+        pWal->aCommitTime[COMMIT_TIME_WALINDEX_CLEANUPUS]+=sqlite3STimeNow()-t;
+      }
     }
 
     /* Write the aPgno[] array entry and the hash-table slot. */
+    if( pWal->aCommitTime ) t = sqlite3STimeNow();
     nCollide = idx;
     for(iKey=walHash(iPage); sLoc.aHash[iKey]; iKey=walNextHash(iKey)){
       if( (nCollide--)==0 ) return SQLITE_CORRUPT_BKPT;
     }
     sLoc.aPgno[idx-1] = iPage;
     AtomicStore(&sLoc.aHash[iKey], (ht_slot)idx);
+    if( pWal->aCommitTime ){
+      pWal->aCommitTime[COMMIT_TIME_WALINDEX_ENTRYUS]+=sqlite3STimeNow()-t;
+    }
 
 #ifdef SQLITE_ENABLE_EXPENSIVE_ASSERT
     /* Verify that the number of entries in the hash table exactly equals