Even more detailed logging of slow COMMIT statements.

FossilOrigin-Name: 3a45387a09398db8efdb2b6ecd773fa30970e61e5242823e04a2e968d1c93c10

diff --git a/manifest b/manifest
index 1a6a8f0b999bb3bee6d3274b2905340e065a54db..60629f5ae6edfb071d0b58bdde06304240f5fbef 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Update\slog\smessages\sto\ssay\s"v=8"\sinstead\sof\s"v=7".
-D 2024-11-01T15:25:34.381
+C Even\smore\sdetailed\slogging\sof\sslow\sCOMMIT\sstatements.
+D 2024-11-08T17:09:34.894
 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 8fa849747d6b919518419f97afd73247362abd6633a33f39f68208ef0a61e212
+F src/btree.c 2ec90dfb60fc026d00a2736e0ec6483b5e6759d0809964602773ef4f3c3fd550
 F src/btree.h bdeeb35614caa33526b603138f04c8d07a3f90a1300b5ade76848b755edf2027
 F src/btreeInt.h caa893e74d2261fb0ff1681fce998533c0552858e882bd04fc6805075f5f6e75
 F src/build.c 08697d6a4df78f8e289582eb58473445492319676f81cc4794ef4056d36ae5fd
@@ -761,7 +761,7 @@ F src/os_setup.h 6011ad7af5db4e05155f385eb3a9b4470688de6f65d6166b8956e58a3d87210
 F src/os_unix.c e33663c5a819e2c8532eedcefb1ea1ad7c1f0c9ac42e2149f632a642c2f9e621
 F src/os_win.c 6ff43bac175bd9ed79e7c0f96840b139f2f51d01689a638fd05128becf94908a
 F src/os_win.h 7b073010f1451abe501be30d12f6bc599824944a
-F src/pager.c 752bc91907e7345965b0dafa5d73320769563f2a2721cc9441340bd4d8f83432
+F src/pager.c 0a82bdc31f09ab22fca997c9afb527ef52ec95a96f0013fdf9d7673ba25cbbbc
 F src/pager.h 60eded76163c6a09d2b73cc40de117012d62f6d1222614c9261d07a73e20ac2e
 F src/parse.y 8388b36e6cd15ebc5c1796cb72dd0a67a04abc446f52838ab3a2e8591487b2f1
 F src/pcache.c 588cc3c5ccaaadde689ed35ce5c5c891a1f7b1f4d1f56f6cf0143b74d8ee6484
@@ -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 ab45731ea0b7be4a5546011a50ba30e488d234c6950af79f220bec1a9fcd71a4
+F src/vdbe.h e439c7b44191828413f461eac23360ffbf0513fe57d129853f690c4ea4d46746
 F src/vdbeInt.h 92b7eabbaadbe8127741cd96e7e39c4834c2bb0b75987d5f6251975f47233690
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c 49159972b9769bf82b6abbcbb3baa7fcaae8e0b16f85d3c99dcee3b94f2b09c8
+F src/vdbeaux.c 158f4d16d172f4ff125d4c2c7b2bb10d5ccd6bf4625f97ea8a3fea9ea359facf
 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 67618e8d2b4eb79f0609f15486ddd6bef5709c206eaf8e69bad61f88f8e536ac
+F src/wal.c f7310528e03cdb3a27d945176ea2283d63e5311a7b691e264415f60fc817e52a
 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 52d332f0c7780acabb6a06b5fe14f654e98b64dbbba9984fb18913a97ed7fab6
-R 2695a2a6519e5edb943fcdd8b90655ff
+P 492a0a85438586a8ccd9629239304f4df3f2c6391ec05dd9837b7a553313d632
+R d991cbdeeb5fc92b3fc69dc783bdecdb
 U dan
-Z 6bda0fab1dbe51baa4faeccad7c86af9
+Z 84fadaaa017854e6f13dffb1681bb1d2
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index cf3d673f46a274c871c658149d31eb254d1fb3f5..289cd4bd877de2c2713e39bb50dece581a435b50 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-492a0a85438586a8ccd9629239304f4df3f2c6391ec05dd9837b7a553313d632
+3a45387a09398db8efdb2b6ecd773fa30970e61e5242823e04a2e968d1c93c10

diff --git a/src/btree.c b/src/btree.c
index f308abff3ff53930ce253c4ad99f34a6b06072d4..c0ee2a0ca923c62f134097b90354a88e074faf95 100644 (file)
--- a/src/btree.c
+++ b/src/btree.c
@@ -4557,27 +4557,46 @@ static int btreeRelocateRange(
 
     if( pEntry->eType==PTRMAP_FREEPAGE ){
       Pgno dummy;
+      u64 t1;
+      if( pBt->aCommitTime ) t1 = sqlite3STimeNow();
       rc = allocateBtreePage(pBt, &pFree, &dummy, iPg, BTALLOC_EXACT);
+      if( pBt->aCommitTime ){
+        pBt->aCommitTime[COMMIT_TIME_RELOCATE2_ALLOCATEUS] += (sqlite3STimeNow() - t1);
+      }
       if( pFree ){
         assert( sqlite3PagerPageRefcount(pFree->pDbPage)==1 );
         sqlite3PcacheDrop(pFree->pDbPage);
       }
       assert( rc!=SQLITE_OK || dummy==iPg );
     }else if( pnCurrent ){
+      u64 t1;
       btreeGetPage(pBt, iPg, &pPg, 0);
       assert( sqlite3PagerIswriteable(pPg->pDbPage) );
       assert( sqlite3PagerPageRefcount(pPg->pDbPage)==1 );
       iNew = ++(*pnCurrent);
       if( iNew==PENDING_BYTE_PAGE(pBt) ) iNew = ++(*pnCurrent);
+      if( pBt->aCommitTime ) t1 = sqlite3STimeNow();
       rc = relocatePage(pBt, pPg, pEntry->eType, pEntry->parent, iNew, 1);
+      if( pBt->aCommitTime ){
+        pBt->aCommitTime[COMMIT_TIME_RELOCATE2_RELOCATEUS] += (sqlite3STimeNow() - t1);
+      }
       releasePageNotNull(pPg);
     }else{
+      u64 t1;
+      if( pBt->aCommitTime ) t1 = sqlite3STimeNow();
       rc = allocateBtreePage(pBt, &pFree, &iNew, iFirst-1, BTALLOC_LE);
+      if( pBt->aCommitTime ){
+        pBt->aCommitTime[COMMIT_TIME_RELOCATE2_ALLOCATEUS] += (sqlite3STimeNow() - t1);
+      }
       assert( rc!=SQLITE_OK || iNew<iFirst );
       if( rc==SQLITE_OK ){
         releasePage(pFree);
         btreeGetPage(pBt, iPg, &pPg, 0);
+        if( pBt->aCommitTime ) t1 = sqlite3STimeNow();
         rc = relocatePage(pBt, pPg, pEntry->eType, pEntry->parent,iNew,1);
+        if( pBt->aCommitTime ){
+          pBt->aCommitTime[COMMIT_TIME_RELOCATE2_RELOCATEUS] += (sqlite3STimeNow() - t1);
+        }
         releasePage(pPg);
       }
     }
@@ -4680,7 +4699,9 @@ static int btreeFixUnlocked(Btree *p){
           sqlite3CommitTimeSet(
               p->pBt->aCommitTime, COMMIT_TIME_START_RELOCATE2
           );
+          sqlite3PagerSetCommitTime(pBt->pPager, pBt->aCommitTime);
           rc = btreeRelocateRange(pBt, nFin+1, nCurrent, 0);
+          sqlite3PagerSetCommitTime(pBt->pPager, 0);
         }
 
         put4byte(&p1[28], nFin);

diff --git a/src/pager.c b/src/pager.c
index 9b6ff2cb149a8a1f81e6a1b731cde97743d04ebc..da5de560525dab6aea9c5c9dcf0d030a7497bd96 100644 (file)
--- a/src/pager.c
+++ b/src/pager.c
@@ -3051,6 +3051,7 @@ end_playback:
 static int readDbPage(PgHdr *pPg){
   Pager *pPager = pPg->pPager; /* Pager object associated with page pPg */
   int rc = SQLITE_OK;          /* Return code */
+  u64 t1 = 0;
 
 #ifndef SQLITE_OMIT_WAL
   u32 iFrame = 0;              /* Frame of WAL containing pgno */
@@ -3062,6 +3063,9 @@ static int readDbPage(PgHdr *pPg){
     rc = sqlite3WalFindFrame(pPager->pWal, pPg->pgno, &iFrame);
     if( rc ) return rc;
   }
+  if( pPager->aCommitTime ){
+    t1 = sqlite3STimeNow();
+  }
   if( iFrame ){
     rc = sqlite3WalReadFrame(pPager->pWal, iFrame,pPager->pageSize,pPg->pData);
   }else
@@ -3073,6 +3077,10 @@ static int readDbPage(PgHdr *pPg){
       rc = SQLITE_OK;
     }
   }
+  if( pPager->aCommitTime ){
+    pPager->aCommitTime[COMMIT_TIME_RELOCATE2_READUS] += (sqlite3STimeNow() - t1);
+    pPager->aCommitTime[COMMIT_TIME_RELOCATE2_READCOUNT]++;
+  }
 
   if( pPg->pgno==1 ){
     if( rc ){

diff --git a/src/vdbe.h b/src/vdbe.h
index def0275b4ed97dc632e812d66d47c1a076a14558..6725bb5f3bed20475f5eea42f47e158a1b5e5794 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -439,33 +439,41 @@ int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr);
 #define COMMIT_TIME_RELOCATE1COUNT 8
 #define COMMIT_TIME_RELOCATE2COUNT 9
 
-#define COMMIT_TIME_AFTER_FIXUNLOCKED 10
+#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_BEFORE_WALFRAMES 11
-#define COMMIT_TIME_AFTER_CHANGECOUNTER 13
-#define COMMIT_TIME_AFTER_RESTARTLOG 14
-#define COMMIT_TIME_AFTER_WRITEHDR 15
+#define COMMIT_TIME_AFTER_FIXUNLOCKED 14
 
-#define COMMIT_TIME_OSWRITE 16
+#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_AFTER_WRITEFRAMES 17
+#define COMMIT_TIME_OSWRITE 19
 
-#define COMMIT_TIME_BEFORE_WALINDEX 18
-#define COMMIT_TIME_AFTER_WALINDEX 19
-#define COMMIT_TIME_AFTER_WALINDEXHDR 20
+#define COMMIT_TIME_AFTER_WRITEFRAMES 20
 
-#define COMMIT_TIME_WALFRAMESFLAGS 21
+#define COMMIT_TIME_NFRAME            21
+#define COMMIT_TIME_HASHMAPUS         22
 
-#define COMMIT_TIME_AFTER_WALFRAMES 22
+#define COMMIT_TIME_BEFORE_WALINDEX 23
+#define COMMIT_TIME_AFTER_WALINDEX 24
+#define COMMIT_TIME_AFTER_WALINDEXHDR 25
 
-#define COMMIT_TIME_BEFORE_PHASETWO 23
-#define COMMIT_TIME_AFTER_PHASETWO 24
+#define COMMIT_TIME_WALFRAMESFLAGS 26
 
-#define COMMIT_TIME_AFTER_VDBECOMMIT 25
-#define COMMIT_TIME_AFTER_HALT 26
-#define COMMIT_TIME_FINISH 27
+#define COMMIT_TIME_AFTER_WALFRAMES 27
 
-#define COMMIT_TIME_N 28
+#define COMMIT_TIME_BEFORE_PHASETWO 28
+#define COMMIT_TIME_AFTER_PHASETWO 29
+
+#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_TIMEOUT (2*1000*1000) */
 #define COMMIT_TIME_TIMEOUT (10*1000)         /* 10ms threshold */

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index f497e6b0bf3be9b69d2ae9bf4c063817d081eca1..a866603ae127d8ec604075ef21cda20b23cf3247 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -5473,10 +5473,17 @@ void sqlite3CommitTimeLog(u64 *aCommit){
       if( ii==COMMIT_TIME_RELOCATE1COUNT
        || ii==COMMIT_TIME_RELOCATE2COUNT
        || ii==COMMIT_TIME_OTHERWRITERS
+       || ii==COMMIT_TIME_NFRAME
+       || ii==COMMIT_TIME_RELOCATE2_READCOUNT
       ){
         iVal = (int)aCommit[ii];
         zHash = "#";
-      }else if( ii==COMMIT_TIME_OSWRITE ){
+      }else if( ii==COMMIT_TIME_OSWRITE 
+             || ii==COMMIT_TIME_RELOCATE2_READUS 
+             || ii==COMMIT_TIME_RELOCATE2_ALLOCATEUS 
+             || ii==COMMIT_TIME_RELOCATE2_RELOCATEUS 
+             || ii==COMMIT_TIME_HASHMAPUS 
+      ){
         iVal = (int)aCommit[ii];
         zU = "us";
       }else if( ii==COMMIT_TIME_WALFRAMESFLAGS ){
@@ -5487,7 +5494,7 @@ void sqlite3CommitTimeLog(u64 *aCommit){
       }
       zStr = sqlite3_mprintf("%z%s%s%d%s", zStr, (zStr?", ":""),zHash,iVal,zU);
     }
-    sqlite3_log(SQLITE_WARNING, "slow commit (v=8): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=9): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }
@@ -5515,7 +5522,7 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
     }
     if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
     sqlite3_log(SQLITE_WARNING, 
-        "slow prepare (v=8): (%s) [%.*s]", zStr, nByte, zSql
+        "slow prepare (v=9): (%s) [%.*s]", zStr, nByte, zSql
     );
     sqlite3_free(zStr);
   }
@@ -5531,7 +5538,7 @@ void sqlite3SchemaTimeLog(u64 *aSchema){
         (aSchema[ii]==0 ? 0 : (int)(aSchema[ii] - i1))
       );
     }
-    sqlite3_log(SQLITE_WARNING, "slow schema (v=8): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow schema (v=9): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }

diff --git a/src/wal.c b/src/wal.c
index 71c50e674eacb50c1bcd8fac8660834d290f4ba3..adfd7f4aef06b3c7b4354b18a13e612aa8d3b1a3 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -1065,7 +1065,13 @@ static int walIndexPage(
 ){
   SEH_INJECT_FAULT;
   if( pWal->nWiData<=iPage || (*ppPage = pWal->apWiData[iPage])==0 ){
-    return walIndexPageRealloc(pWal, iPage, ppPage);
+    int rc;
+    u64 t1;
+    if( pWal->aCommitTime ) t1 = sqlite3STimeNow();
+    rc = walIndexPageRealloc(pWal, iPage, ppPage);
+    if( pWal->aCommitTime ){
+      pWal->aCommitTime[COMMIT_TIME_HASHMAPUS] += sqlite3STimeNow() - t1;
+    }
   }
   return SQLITE_OK;
 }
@@ -5181,6 +5187,7 @@ static int walFrames(
   WalIndexHdr *pLive;             /* Pointer to shared header */
   int iApp;
   int bWal2 = isWalMode2(pWal);
+  int nFrame = 0;
 
   int logFlags = 0;
 
@@ -5396,6 +5403,7 @@ static int walFrames(
     if( (p->flags & PGHDR_WAL_APPEND)==0 ) continue;
     iFrame++;
     rc = walIndexAppend(pWal, iApp, iFrame, p->pgno);
+    nFrame++;
   }
   assert( pLast!=0 || nExtra==0 );
   while( rc==SQLITE_OK && nExtra>0 ){
@@ -5403,6 +5411,7 @@ static int walFrames(
     nExtra--;
     rc = walIndexAppend(pWal, iApp, iFrame, pLast->pgno);
   }
+  if( pWal->aCommitTime ) pWal->aCommitTime[COMMIT_TIME_NFRAME] = nFrame;
 
   sqlite3CommitTimeSet(pWal->aCommitTime, COMMIT_TIME_AFTER_WALINDEX);