From: dan Date: Tue, 8 Oct 2024 15:08:04 +0000 (+0000) Subject: Add logging to help analyze slow "PRAGMA cache_size = ?" statements. X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=1c55a2d5cb0542e7e49084917e21e2436debd01b;p=thirdparty%2Fsqlite.git Add logging to help analyze slow "PRAGMA cache_size = ?" statements. FossilOrigin-Name: cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249 --- diff --git a/manifest b/manifest index 029aaf5429..21de1f507d 100644 --- a/manifest +++ b/manifest @@ -1,5 +1,5 @@ -C Add\slogging\sto\shelp\sanalyze\scommit\sperformance. -D 2024-10-07T16:11:10.335 +C Add\slogging\sto\shelp\sanalyze\sslow\s"PRAGMA\scache_size\s=\s?"\sstatements. +D 2024-10-08T15:08:04.720 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 c0db29ff599f43af49b83e26754641e606bf75fd9f9f460333616d98b59badfa +F src/btree.c e681d91414a55bf639640f38bd7c035f477b8e482a130ea439c89e4ba8b9356d F src/btree.h bdeeb35614caa33526b603138f04c8d07a3f90a1300b5ade76848b755edf2027 F src/btreeInt.h caa893e74d2261fb0ff1681fce998533c0552858e882bd04fc6805075f5f6e75 F src/build.c 08697d6a4df78f8e289582eb58473445492319676f81cc4794ef4056d36ae5fd @@ -767,9 +767,9 @@ F src/parse.y 8388b36e6cd15ebc5c1796cb72dd0a67a04abc446f52838ab3a2e8591487b2f1 F src/pcache.c 588cc3c5ccaaadde689ed35ce5c5c891a1f7b1f4d1f56f6cf0143b74d8ee6484 F src/pcache.h 1497ce1b823cf00094bb0cf3bac37b345937e6f910890c626b16512316d3abf5 F src/pcache1.c 430b86e10b8d6ae65832a19a0016f8f65f74207687bc9501c0b15a5908bcb6ad -F src/pragma.c d206a9a757faceb812183faa2ed328145795c8067a44f981b0478736f68d4144 +F src/pragma.c 56663a75d517d77b95dcf5e6a597e8a1ce49413c4e30ea79148926cc4c1db912 F src/pragma.h 6ebbdee90ed56a892d2c728e27fd9c1ce48c8a28841888d0c6c147946b38cb25 -F src/prepare.c d99931f45416652895e502328ca49fe782cfc4e1ebdcda13b3736d991ebf42ce +F src/prepare.c c2b3221d0215d75f355e7aa46020275ed8453293dd63be398b3846e2118e7e92 F src/printf.c 6a87534ebfb9e5346011191b1f3a7ebc457f5938c7e4feeea478ecf53f6a41b2 F src/random.c 9bd018738ec450bf35d28050b4b33fa9a6eebf3aaefb1a1cff42dc14a7725673 F src/resolve.c 2c127880c0634962837f16f2f48a295e514357af959330cc038de73015d5b5e8 @@ -779,7 +779,7 @@ F src/shell.c.in 40de636c1d90fb8a9ca7f49dc8f50d930f1b60736e73aca5eb37c4c7d0e47f9 F src/sqlite.h.in b7ff496637807ae88b2557039fc940518db328bf5d5621e2f7c048dfba32a52b F src/sqlite3.rc 5121c9e10c3964d5755191c80dd1180c122fc3a8 F src/sqlite3ext.h 3f046c04ea3595d6bfda99b781926b17e672fd6d27da2ba6d8d8fc39981dcb54 -F src/sqliteInt.h 913fb7b1b99ca00708eef5d99503f8f9d71b302e057572a9d7f56071ea7b79a6 +F src/sqliteInt.h 09b2035fec910b58b8a2a9a3dedd0fe919ac2487dc1effcfd2c3b4eec9edab60 F src/sqliteLimit.h 6878ab64bdeb8c24a1d762d45635e34b96da21132179023338c93f820eee6728 F src/status.c cb11f8589a6912af2da3bb1ec509a94dd8ef27df4d4c1a97e0bcf2309ece972b F src/table.c 0f141b58a16de7e2fbe81c308379e7279f4c6b50eb08efeec5892794a0ba30d1 @@ -849,7 +849,7 @@ F src/vdbe.c fea60cfe46d8839a08e4680d90a96898d542d3f6d7954e2e99cd92596f1a01f8 F src/vdbe.h 7d6a7fefce6068d78e350367ee16eeaf72632163623044623d35fce88e12be66 F src/vdbeInt.h 494b7b3430fb53adef43e5fd9ede20029750f188f2dbb064e7b86cdf9fb755d7 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df -F src/vdbeaux.c 606cadbcc312419ef3dc062c8aca2a350f0b89fd75e372534dba44d07503b007 +F src/vdbeaux.c d00eb15e7f46a4a9466de4bb0fd8ae98b57abfa04c1d4db19f4bdc665fbb684e F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797 F src/vdbemem.c 831a244831eaa45335f9ae276b50a7a82ee10d8c46c2c72492d4eb8c98d94d89 F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f @@ -2249,11 +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 cf8f155280100c1a5b79b118875a93686a554d8be55114277f4f7b20cfd7835a -R 61734104557d860aec28424b091f8914 -T *branch * cf8f1552-commit-instr -T *sym-cf8f1552-commit-instr * -T -sym-bedrock * +P c5391f2cc913a16695efb63f7d2320fc18b8aaefdbdffa087a2e3d26b24dc218 +R 48fb9da465c7791ce99a13be44d71147 U dan -Z fd413eb71e4f18403b5529b00f31e3cd +Z dcf509c08a497f2bbb5716a149310ff4 # Remove this line to create a well-formed Fossil manifest. diff --git a/manifest.uuid b/manifest.uuid index 31ddfece80..11bfaabe9b 100644 --- a/manifest.uuid +++ b/manifest.uuid @@ -1 +1 @@ -c5391f2cc913a16695efb63f7d2320fc18b8aaefdbdffa087a2e3d26b24dc218 +cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249 diff --git a/src/btree.c b/src/btree.c index 4bf8724564..c25e1760d5 100644 --- a/src/btree.c +++ b/src/btree.c @@ -3228,7 +3228,9 @@ int sqlite3BtreeSetCacheSize(Btree *p, int mxPage){ BtShared *pBt = p->pBt; assert( sqlite3_mutex_held(p->db->mutex) ); sqlite3BtreeEnter(p); + sqlite3PrepareTimeSet(p->db->aPrepareTime, PREPARE_TIME_BEGINSETCACHESIZE); sqlite3PagerSetCachesize(pBt->pPager, mxPage); + sqlite3PrepareTimeSet(p->db->aPrepareTime, PREPARE_TIME_ENDSETCACHESIZE); sqlite3BtreeLeave(p); return SQLITE_OK; } diff --git a/src/pragma.c b/src/pragma.c index 5631aa3c51..20fa012edb 100644 --- a/src/pragma.c +++ b/src/pragma.c @@ -426,6 +426,7 @@ void sqlite3Pragma( Vdbe *v = sqlite3GetVdbe(pParse); /* Prepared statement */ const PragmaName *pPragma; /* The pragma */ + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINPRAGMA); if( v==0 ) return; sqlite3VdbeRunOnlyOnce(v); pParse->nMem = 2; @@ -866,6 +867,7 @@ void sqlite3Pragma( */ case PragTyp_CACHE_SIZE: { assert( sqlite3SchemaMutexHeld(db, iDb, 0) ); + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINCACHESIZE); if( !zRight ){ returnSingleInt(v, pDb->pSchema->cache_size); }else{ @@ -873,6 +875,7 @@ void sqlite3Pragma( pDb->pSchema->cache_size = size; sqlite3BtreeSetCacheSize(pDb->pBt, pDb->pSchema->cache_size); } + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDCACHESIZE); break; } @@ -2759,6 +2762,7 @@ void sqlite3Pragma( pragma_out: sqlite3DbFree(db, zLeft); sqlite3DbFree(db, zRight); + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDPRAGMA); } #ifndef SQLITE_OMIT_VIRTUALTABLE /***************************************************************************** diff --git a/src/prepare.c b/src/prepare.c index df9c98f743..6d7e3c6863 100644 --- a/src/prepare.c +++ b/src/prepare.c @@ -782,14 +782,18 @@ static int sqlite3Prepare( } zSqlCopy = sqlite3DbStrNDup(db, zSql, nBytes); if( zSqlCopy ){ + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINPARSE); sqlite3RunParser(&sParse, zSqlCopy); + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDPARSE); sParse.zTail = &zSql[sParse.zTail-zSqlCopy]; sqlite3DbFree(db, zSqlCopy); }else{ sParse.zTail = &zSql[nBytes]; } }else{ + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINPARSE); sqlite3RunParser(&sParse, zSql); + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDPARSE); } assert( 0==sParse.nQueryLoop ); @@ -850,6 +854,12 @@ static int sqlite3LockAndPrepare( ){ int rc; int cnt = 0; + u64 *aPrepareSave = db->aPrepareTime; + + u64 aPrepareTime[PREPARE_TIME_N]; + memset(aPrepareTime, 0, sizeof(aPrepareTime)); + sqlite3PrepareTimeSet(aPrepareTime, PREPARE_TIME_START); + db->aPrepareTime = aPrepareTime; #ifdef SQLITE_ENABLE_API_ARMOR if( ppStmt==0 ) return SQLITE_MISUSE_BKPT; @@ -875,6 +885,11 @@ static int sqlite3LockAndPrepare( db->busyHandler.nBusy = 0; sqlite3_mutex_leave(db->mutex); assert( rc==SQLITE_OK || (*ppStmt)==0 ); + + db->aPrepareTime = aPrepareSave; + sqlite3PrepareTimeSet(aPrepareTime, PREPARE_TIME_FINISH); + sqlite3PrepareTimeLog(zSql, nBytes, aPrepareTime); + return rc; } diff --git a/src/sqliteInt.h b/src/sqliteInt.h index b9d5ff8c04..75b81674c6 100644 --- a/src/sqliteInt.h +++ b/src/sqliteInt.h @@ -1826,8 +1826,29 @@ struct sqlite3 { */ u32 aCommit[5]; #endif + + u64 *aPrepareTime; }; +#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 sqlite3PrepareTimeSet(x,y) sqlite3CommitTimeSet(x,y) +void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepareTime); + +#define PREPARE_TIME_TIMEOUT (2 * 1000 * 1000) /* 2 second timeout */ + + /* ** Candidate values for sqlite3.eConcurrent */ diff --git a/src/vdbeaux.c b/src/vdbeaux.c index e86b3874f9..6715c99e02 100644 --- a/src/vdbeaux.c +++ b/src/vdbeaux.c @@ -5485,6 +5485,25 @@ void sqlite3CommitTimeSet(u64 *aCommit, int iCommit){ aCommit[iCommit] = sqlite3STimeNow(); } } +void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){ + u64 i1 = aPrepare[PREPARE_TIME_START]; + assert( PREPARE_TIME_START==0 && PREPARE_TIME_FINISH==PREPARE_TIME_N-1 ); + if( aPrepare[PREPARE_TIME_FINISH]>(i1+PREPARE_TIME_TIMEOUT) ){ + int nByte = nSql; + char *zStr = 0; + int ii; + for(ii=1; ii