From 6b1569576363aaac1432b365e5980d555245f98e Mon Sep 17 00:00:00 2001 From: Florent De Neve Date: Thu, 10 Oct 2024 13:23:36 -0400 Subject: [PATCH] Update SQLite debug logging --- libstuff/sqlite3.c | 65 ++++++++++++++++++++++++++++++---------------- libstuff/sqlite3.h | 2 +- 2 files changed, 44 insertions(+), 23 deletions(-) diff --git a/libstuff/sqlite3.c b/libstuff/sqlite3.c index d14ab53f6..16be8c7ef 100644 --- a/libstuff/sqlite3.c +++ b/libstuff/sqlite3.c @@ -18,7 +18,7 @@ ** separate file. This file contains only code for the core SQLite library. ** ** The content in this amalgamation comes from Fossil check-in -** cd6f585cadfe40778c3bf59dfbfa5f02c50c. +** 6deb4794f8e24dbb946069de1e5c34fbcd47. */ #define SQLITE_CORE 1 #define SQLITE_AMALGAMATION 1 @@ -465,7 +465,7 @@ extern "C" { */ #define SQLITE_VERSION "3.47.0" #define SQLITE_VERSION_NUMBER 3047000 -#define SQLITE_SOURCE_ID "2024-10-08 15:08:04 cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249" +#define SQLITE_SOURCE_ID "2024-10-10 15:28:18 6deb4794f8e24dbb946069de1e5c34fbcd4734162002f3bc7deb1a3f69adec05" /* ** CAPI3REF: Run-Time Library Version Numbers @@ -17441,17 +17441,21 @@ SQLITE_PRIVATE int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr) #define COMMIT_TIME_BEFORE_VDBECOMMIT 2 #define COMMIT_TIME_BEFORE_PHASEONE 3 -#define COMMIT_TIME_AFTER_FIXUNLOCKED 4 -#define COMMIT_TIME_AFTER_WALFRAMES 5 +#define COMMIT_TIME_START_FIXUNLOCKED 4 +#define COMMIT_TIME_START_RELOCATE1 5 +#define COMMIT_TIME_START_RELOCATE2 6 -#define COMMIT_TIME_BEFORE_PHASETWO 6 -#define COMMIT_TIME_AFTER_PHASETWO 7 +#define COMMIT_TIME_AFTER_FIXUNLOCKED 7 +#define COMMIT_TIME_AFTER_WALFRAMES 8 -#define COMMIT_TIME_AFTER_VDBECOMMIT 8 -#define COMMIT_TIME_AFTER_HALT 9 -#define COMMIT_TIME_FINISH 10 +#define COMMIT_TIME_BEFORE_PHASETWO 9 +#define COMMIT_TIME_AFTER_PHASETWO 10 -#define COMMIT_TIME_N 11 +#define COMMIT_TIME_AFTER_VDBECOMMIT 11 +#define COMMIT_TIME_AFTER_HALT 12 +#define COMMIT_TIME_FINISH 13 + +#define COMMIT_TIME_N 14 /* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */ #define COMMIT_TIME_TIMEOUT (10*1000) /* 10ms threshold */ @@ -18162,15 +18166,22 @@ struct sqlite3 { #define PREPARE_TIME_START 0 #define PREPARE_TIME_BEGINPARSE 1 #define PREPARE_TIME_BEGINPRAGMA 2 -#define PREPARE_TIME_BEGINCACHESIZE 3 -#define PREPARE_TIME_BEGINSETCACHESIZE 4 -#define PREPARE_TIME_ENDSETCACHESIZE 5 -#define PREPARE_TIME_ENDCACHESIZE 6 -#define PREPARE_TIME_ENDPRAGMA 7 -#define PREPARE_TIME_ENDPARSE 8 -#define PREPARE_TIME_FINISH 9 -#define PREPARE_TIME_N 10 +#define PREPARE_TIME_BEGINAUTHCHECK 3 +#define PREPARE_TIME_ENDAUTHCHECK 4 +#define PREPARE_TIME_BEGINLOADSCHEMA 5 +#define PREPARE_TIME_ENDLOADSCHEMA 6 + + +#define PREPARE_TIME_BEGINCACHESIZE 7 +#define PREPARE_TIME_BEGINSETCACHESIZE 8 +#define PREPARE_TIME_ENDSETCACHESIZE 9 +#define PREPARE_TIME_ENDCACHESIZE 10 +#define PREPARE_TIME_ENDPRAGMA 11 +#define PREPARE_TIME_ENDPARSE 12 +#define PREPARE_TIME_FINISH 13 + +#define PREPARE_TIME_N 14 #define sqlite3PrepareTimeSet(x,y) sqlite3CommitTimeSet(x,y) SQLITE_PRIVATE void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepareTime); @@ -77355,6 +77366,8 @@ static int btreeFixUnlocked(Btree *p){ Pgno nPage = btreePagecount(pBt); u32 nFree = get4byte(&p1[36]); + sqlite3CommitTimeSet(p->pBt->aCommitTime, COMMIT_TIME_START_FIXUNLOCKED); + assert( pBt->pMap ); rc = sqlite3PagerUpgradeSnapshot(pPager, pPage1->pDbPage); assert( p1==pPage1->aData ); @@ -77401,6 +77414,7 @@ static int btreeFixUnlocked(Btree *p){ nCurrent = MAX(nPage, nHPage); pBt->nPage = nCurrent; + sqlite3CommitTimeSet(p->pBt->aCommitTime, COMMIT_TIME_START_RELOCATE1); rc = btreeRelocateRange(pBt, pMap->iFirst, iLast, &nCurrent); /* There are now no collisions with the snapshot at the head of the @@ -77417,6 +77431,9 @@ static int btreeFixUnlocked(Btree *p){ nFin--; } nFin = MAX(nFin, nHPage); + sqlite3CommitTimeSet( + p->pBt->aCommitTime, COMMIT_TIME_START_RELOCATE2 + ); rc = btreeRelocateRange(pBt, nFin+1, nCurrent, 0); } @@ -93170,7 +93187,7 @@ SQLITE_PRIVATE void sqlite3CommitTimeLog(u64 *aCommit){ (aCommit[ii]==0 ? 0 : (int)(aCommit[ii] - i1)) ); } - sqlite3_log(SQLITE_WARNING, "slow commit (v=1): (%s)", zStr); + sqlite3_log(SQLITE_WARNING, "slow commit (v=2): (%s)", zStr); sqlite3_free(zStr); } } @@ -93180,7 +93197,7 @@ SQLITE_PRIVATE u64 sqlite3STimeNow(){ return ((u64)time.tv_sec * 1000000 + (u64)time.tv_usec); } SQLITE_PRIVATE void sqlite3CommitTimeSet(u64 *aCommit, int iCommit){ - if( aCommit ){ + if( aCommit && aCommit[iCommit]==0 ){ aCommit[iCommit] = sqlite3STimeNow(); } } @@ -93198,7 +93215,7 @@ SQLITE_PRIVATE void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrep } if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); } sqlite3_log(SQLITE_WARNING, - "slow prepare (v=1): (%s) [%.*s]", zStr, nByte, zSql + "slow prepare (v=2): (%s) [%.*s]", zStr, nByte, zSql ); sqlite3_free(zStr); } @@ -142532,11 +142549,13 @@ SQLITE_PRIVATE void sqlite3Pragma( zRight = sqlite3NameFromToken(db, pValue); } + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINAUTHCHECK); assert( pId2 ); zDb = pId2->n>0 ? pDb->zDbSName : 0; if( sqlite3AuthCheck(pParse, SQLITE_PRAGMA, zLeft, zRight, zDb) ){ goto pragma_out; } + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDAUTHCHECK); /* Send an SQLITE_FCNTL_PRAGMA file-control to the underlying VFS ** connection. If it returns SQLITE_OK, then assume that the VFS @@ -142584,10 +142603,12 @@ SQLITE_PRIVATE void sqlite3Pragma( goto pragma_out; } + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINLOADSCHEMA); /* Make sure the database schema is loaded if the pragma requires that */ if( (pPragma->mPragFlg & PragFlg_NeedSchema)!=0 ){ if( sqlite3ReadSchema(pParse) ) goto pragma_out; } + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDLOADSCHEMA); /* Register the result column names for pragmas that return results */ if( (pPragma->mPragFlg & PragFlg_NoColumns)==0 @@ -257549,7 +257570,7 @@ static void fts5SourceIdFunc( ){ assert( nArg==0 ); UNUSED_PARAM2(nArg, apUnused); - sqlite3_result_text(pCtx, "fts5: 2024-10-08 15:08:04 cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249", -1, SQLITE_TRANSIENT); + sqlite3_result_text(pCtx, "fts5: 2024-10-10 15:28:18 6deb4794f8e24dbb946069de1e5c34fbcd4734162002f3bc7deb1a3f69adec05", -1, SQLITE_TRANSIENT); } /* diff --git a/libstuff/sqlite3.h b/libstuff/sqlite3.h index a67aa06aa..e485be1cb 100644 --- a/libstuff/sqlite3.h +++ b/libstuff/sqlite3.h @@ -148,7 +148,7 @@ extern "C" { */ #define SQLITE_VERSION "3.47.0" #define SQLITE_VERSION_NUMBER 3047000 -#define SQLITE_SOURCE_ID "2024-10-08 15:08:04 cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249" +#define SQLITE_SOURCE_ID "2024-10-10 15:28:18 6deb4794f8e24dbb946069de1e5c34fbcd4734162002f3bc7deb1a3f69adec05" /* ** CAPI3REF: Run-Time Library Version Numbers