Still more logging, this time focused on the sqlite3WalFrames() function.

FossilOrigin-Name: 52d332f0c7780acabb6a06b5fe14f654e98b64dbbba9984fb18913a97ed7fab6

diff --git a/manifest b/manifest
index aee7bbf9afe924b4af2e85f901c7cca7baa0ba2c..06d8c2d2357336c520a6055db4c120ab484cdd33 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Add\sextra\slogging\sto\sanalyze\sCOMMIT\scommands.
-D 2024-10-30T18:24:33.020
+C Still\smore\slogging,\sthis\stime\sfocused\son\sthe\ssqlite3WalFrames()\sfunction.
+D 2024-11-01T15:20:39.932
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@@ -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 aae9cdf124548f2867608d481acc854b9b58e769c53b574350ae4ba5dde190f8
+F src/pager.c 752bc91907e7345965b0dafa5d73320769563f2a2721cc9441340bd4d8f83432
 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 49fef91a8f19ef44e1f4a5819de9c344ea13f2363342ed9d82a20aee33e44b81
+F src/vdbe.h ab45731ea0b7be4a5546011a50ba30e488d234c6950af79f220bec1a9fcd71a4
 F src/vdbeInt.h 92b7eabbaadbe8127741cd96e7e39c4834c2bb0b75987d5f6251975f47233690
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c fc9738bf10a52c6271fbff6b5f1f2a7fb8daf23e8ef952c1efdf87611e04d4e0
+F src/vdbeaux.c 0bbb62779e4aa003e59bd51e207aa283433502f058b932cad4caf05fdffa4307
 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 b2bee7bbcdfbb4f9d4765c478a45c0801814123c20624f4f4f7453a7235794da
+F src/wal.c 67618e8d2b4eb79f0609f15486ddd6bef5709c206eaf8e69bad61f88f8e536ac
 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 af4e778bd3bdf30cac3d9a6266f105a8cd71f947b8d71249ef74b8fdc0505dd7
-R 128557cbc094e3ab9c4d3b4c1019317e
+P 7dbb43bd307b5e297e6b2deac4e1d73d8cd68e37d880a5ecf5a3918a53e99d9d
+R 2d5406f04a8b29be72aaf237c2ed3e98
 U dan
-Z 44c8796ec22b939c2d8fb7f81d4f2691
+Z d9a4d0b205fe7c4831128ad62199c9e9
 # Remove this line to create a well-formed Fossil manifest.

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

diff --git a/src/pager.c b/src/pager.c
index add099f2af3323f23193440199112fd1f37bb37f..9b6ff2cb149a8a1f81e6a1b731cde97743d04ebc 100644 (file)
--- a/src/pager.c
+++ b/src/pager.c
@@ -3264,6 +3264,7 @@ static int pagerWalFrames(
   pPager->aStat[PAGER_STAT_WRITE] += nList;
 
   if( pList->pgno==1 ) pager_write_changecounter(pList);
+  sqlite3CommitTimeSet(pPager->aCommitTime, COMMIT_TIME_AFTER_CHANGECOUNTER);
   rc = sqlite3WalFrames(pPager->pWal,
       pPager->pageSize, pList, nTruncate, isCommit, pPager->walSyncFlags
   );
@@ -6654,6 +6655,7 @@ int sqlite3PagerCommitPhaseOne(
       }
       assert( rc==SQLITE_OK );
       if( ALWAYS(pList) ){
+        sqlite3CommitTimeSet(pPager->aCommitTime, COMMIT_TIME_BEFORE_WALFRAMES);
         rc = pagerWalFrames(pPager, pList, pPager->dbSize, 1);
         sqlite3CommitTimeSet(pPager->aCommitTime, COMMIT_TIME_AFTER_WALFRAMES);
       }

diff --git a/src/vdbe.h b/src/vdbe.h
index 307e9b63604df35abd3d2831115e5e8fe85bc60f..def0275b4ed97dc632e812d66d47c1a076a14558 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -441,20 +441,34 @@ int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr);
 
 #define COMMIT_TIME_AFTER_FIXUNLOCKED 10
 
-#define COMMIT_TIME_OSWRITE 11
-#define COMMIT_TIME_AFTER_WALFRAMES 12
+#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_BEFORE_PHASETWO 13
-#define COMMIT_TIME_AFTER_PHASETWO 14
+#define COMMIT_TIME_OSWRITE 16
 
-#define COMMIT_TIME_AFTER_VDBECOMMIT 15
-#define COMMIT_TIME_AFTER_HALT 16
-#define COMMIT_TIME_FINISH 17
+#define COMMIT_TIME_AFTER_WRITEFRAMES 17
 
-#define COMMIT_TIME_N 18
+#define COMMIT_TIME_BEFORE_WALINDEX 18
+#define COMMIT_TIME_AFTER_WALINDEX 19
+#define COMMIT_TIME_AFTER_WALINDEXHDR 20
+
+#define COMMIT_TIME_WALFRAMESFLAGS 21
+
+#define COMMIT_TIME_AFTER_WALFRAMES 22
+
+#define COMMIT_TIME_BEFORE_PHASETWO 23
+#define COMMIT_TIME_AFTER_PHASETWO 24
+
+#define COMMIT_TIME_AFTER_VDBECOMMIT 25
+#define COMMIT_TIME_AFTER_HALT 26
+#define COMMIT_TIME_FINISH 27
+
+#define COMMIT_TIME_N 28
 
 /* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */
-#define COMMIT_TIME_TIMEOUT (0*1000)         /* 10ms threshold */
+#define COMMIT_TIME_TIMEOUT (10*1000)         /* 10ms threshold */
 
 void sqlite3CommitTimeLog(u64*);
 u64 sqlite3STimeNow();

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index 02d9cfff4c1d9705189bafa2b2d232009b6b4eee..c7db14ab8c6f4530938b9e52b1ea99438ebb9876 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -5479,6 +5479,9 @@ void sqlite3CommitTimeLog(u64 *aCommit){
       }else if( ii==COMMIT_TIME_OSWRITE ){
         iVal = (int)aCommit[ii];
         zU = "us";
+      }else if( ii==COMMIT_TIME_WALFRAMESFLAGS ){
+        iVal = (int)aCommit[ii];
+        zHash = "flags=";
       }else{
         iVal = (aCommit[ii]==0 ? 0 : (int)(aCommit[ii] - i1));
       }

diff --git a/src/wal.c b/src/wal.c
index bf524bdd2a8db17c5daca9d005101a72cf32547a..71c50e674eacb50c1bcd8fac8660834d290f4ba3 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -5182,6 +5182,8 @@ static int walFrames(
   int iApp;
   int bWal2 = isWalMode2(pWal);
 
+  int logFlags = 0;
+
   assert( pList );
   assert( pWal->writeLock );
 
@@ -5202,6 +5204,8 @@ static int walFrames(
     return rc;
   }
 
+  sqlite3CommitTimeSet(pWal->aCommitTime, COMMIT_TIME_AFTER_RESTARTLOG);
+
   /* If this is the first frame written into the log, write the WAL
   ** header to the start of the WAL file. See comments at the top of
   ** this source file for a description of the WAL header format.
@@ -5217,6 +5221,7 @@ static int walFrames(
   }
 #endif
 
+  logFlags |= (iFrame==0 ? 0x01 : 0x00);
   if( iFrame==0 ){
     u32 iCkpt = 0;
     u8 aWalHdr[WAL_HDRSIZE];      /* Buffer to assemble wal-header in */
@@ -5270,6 +5275,7 @@ static int walFrames(
   if( (int)pWal->szPage!=szPage ){
     return SQLITE_CORRUPT_BKPT;  /* TH3 test case: cov1/corrupt155.test */
   }
+  sqlite3CommitTimeSet(pWal->aCommitTime, COMMIT_TIME_AFTER_WRITEHDR);
 
   /* Setup information needed to write frames into the WAL */
   w.pWal = pWal;
@@ -5281,6 +5287,7 @@ static int walFrames(
   szFrame = szPage + WAL_FRAME_HDRSIZE;
 
   /* Write all frames into the log file exactly once */
+  logFlags |= (iFirst==0 ? 0x00 : 0x02);
   for(p=pList; p; p=p->pDirty){
     int nDbSize;   /* 0 normally.  Positive == commit flag */
 
@@ -5319,8 +5326,10 @@ static int walFrames(
     p->flags |= PGHDR_WAL_APPEND;
   }
 
+  sqlite3CommitTimeSet(pWal->aCommitTime, COMMIT_TIME_AFTER_WRITEFRAMES);
 
   /* Recalculate checksums within the wal file if required. */
+  logFlags |= (pWal->iReCksum==0 ? 0x00 : 0x04);
   if( isCommit && pWal->iReCksum ){
     rc = walRewriteChecksums(pWal, iFrame);
     if( rc ) return rc;
@@ -5340,6 +5349,7 @@ static int walFrames(
   ** sector boundary is synced; the part of the last frame that extends
   ** past the sector boundary is written after the sync.
   */
+  logFlags |= (WAL_SYNC_FLAGS(sync_flags)==0 ? 0x00 : 0x08);
   if( isCommit && WAL_SYNC_FLAGS(sync_flags)!=0 ){
     int bSync = 1;
     if( pWal->padToSectorBoundary ){
@@ -5374,6 +5384,8 @@ static int walFrames(
     pWal->truncateOnCommit = 0;
   }
 
+  sqlite3CommitTimeSet(pWal->aCommitTime, COMMIT_TIME_BEFORE_WALINDEX);
+
   /* Append data to the wal-index. It is not necessary to lock the
   ** wal-index to do this as the SQLITE_SHM_WRITE lock held on the wal-index
   ** guarantees that there are no other writers, and no data that may
@@ -5392,6 +5404,8 @@ static int walFrames(
     rc = walIndexAppend(pWal, iApp, iFrame, pLast->pgno);
   }
 
+  sqlite3CommitTimeSet(pWal->aCommitTime, COMMIT_TIME_AFTER_WALINDEX);
+
   if( rc==SQLITE_OK ){
     /* Update the private copy of the header. */
     pWal->hdr.szPage = (u16)((szPage&0xff00) | (szPage>>16));
@@ -5419,6 +5433,11 @@ static int walFrames(
     }
   }
 
+  sqlite3CommitTimeSet(pWal->aCommitTime, COMMIT_TIME_AFTER_WALINDEXHDR);
+  if( pWal->aCommitTime ){
+    pWal->aCommitTime[COMMIT_TIME_WALFRAMESFLAGS] = logFlags;
+  }
+
   WALTRACE(("WAL%p: frame write %s\n", pWal, rc ? "failed" : "ok"));
   return rc;
 }