From 45537554fa44359054c5de3aa4e714bb7de37e4b Mon Sep 17 00:00:00 2001 From: dan Date: Fri, 8 Nov 2024 17:09:34 +0000 Subject: [PATCH] Even more detailed logging of slow COMMIT statements. FossilOrigin-Name: 3a45387a09398db8efdb2b6ecd773fa30970e61e5242823e04a2e968d1c93c10 --- manifest | 20 ++++++++++---------- manifest.uuid | 2 +- src/btree.c | 21 +++++++++++++++++++++ src/pager.c | 8 ++++++++ src/vdbe.h | 44 ++++++++++++++++++++++++++------------------ src/vdbeaux.c | 15 +++++++++++---- src/wal.c | 11 ++++++++++- 7 files changed, 87 insertions(+), 34 deletions(-) diff --git a/manifest b/manifest index 1a6a8f0b99..60629f5ae6 100644 --- 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 cf3d673f46..289cd4bd87 100644 --- a/manifest.uuid +++ b/manifest.uuid @@ -1 +1 @@ -492a0a85438586a8ccd9629239304f4df3f2c6391ec05dd9837b7a553313d632 +3a45387a09398db8efdb2b6ecd773fa30970e61e5242823e04a2e968d1c93c10 diff --git a/src/btree.c b/src/btree.c index f308abff3f..c0ee2a0ca9 100644 --- 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 || iNewaCommitTime ) 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 9b6ff2cb14..da5de56052 100644 --- 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 def0275b4e..6725bb5f3b 100644 --- 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 f497e6b0bf..a866603ae1 100644 --- 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 71c50e674e..adfd7f4aef 100644 --- 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); -- 2.47.2