From: dan Date: Fri, 1 Nov 2024 15:20:39 +0000 (+0000) Subject: Still more logging, this time focused on the sqlite3WalFrames() function. X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=10ad8762703d03133f0b9efc51f555c3dd0e8f3f;p=thirdparty%2Fsqlite.git Still more logging, this time focused on the sqlite3WalFrames() function. FossilOrigin-Name: 52d332f0c7780acabb6a06b5fe14f654e98b64dbbba9984fb18913a97ed7fab6 --- diff --git a/manifest b/manifest index aee7bbf9af..06d8c2d235 100644 --- 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 67947343ca..bfdf51cd52 100644 --- a/manifest.uuid +++ b/manifest.uuid @@ -1 +1 @@ -7dbb43bd307b5e297e6b2deac4e1d73d8cd68e37d880a5ecf5a3918a53e99d9d +52d332f0c7780acabb6a06b5fe14f654e98b64dbbba9984fb18913a97ed7fab6 diff --git a/src/pager.c b/src/pager.c index add099f2af..9b6ff2cb14 100644 --- 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 307e9b6360..def0275b4e 100644 --- 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 02d9cfff4c..c7db14ab8c 100644 --- 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 bf524bdd2a..71c50e674e 100644 --- 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; }