Add logging to help analyze slow "PRAGMA cache_size = ?" statements.

FossilOrigin-Name: cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249

diff --git a/manifest b/manifest
index 029aaf542907264c8b845db831bc2ef5b6ae96f3..21de1f507d077486124b115fa73a489415cd12b4 100644 (file)
--- 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 31ddfece803fefa60d292fafbd18be97bd2eb64c..11bfaabe9bfc71830175043495aaa77eb7832381 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-c5391f2cc913a16695efb63f7d2320fc18b8aaefdbdffa087a2e3d26b24dc218
+cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249

diff --git a/src/btree.c b/src/btree.c
index 4bf87245641d76f3737a79ab8020748cdcc266b9..c25e1760d5a5fbc0d2a230d11a3c64b9caf5416f 100644 (file)
--- 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 5631aa3c5114fb08bc42db550aa8df48b9cf8c82..20fa012edb15438be91fa7dd7dd2d1d127d71e77 100644 (file)
--- 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 df9c98f7438eb08c1c631202c7f34b5bac94d25d..6d7e3c68630da6027226f106f8ec99a2c422ff85 100644 (file)
--- 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 b9d5ff8c04a907c10f48d3e970253ac7a3b67f72..75b81674c6aa630803bff4133a96acc91142f040 100644 (file)
--- 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 e86b3874f97cc7e9b03adbbb878ed57bb9b84ce0..6715c99e023374337a1be233039a3802ec422456 100644 (file)
--- 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<PREPARE_TIME_N; ii++){
+      zStr = sqlite3_mprintf("%z%s%d", zStr, (zStr?", ":""), 
+        (aPrepare[ii]==0 ? 0 : (int)(aPrepare[ii] - i1))
+      );
+    }
+    if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
+    sqlite3_log(SQLITE_WARNING, 
+        "slow prepare (v=1): (%s) [%.*s]", zStr, nByte, zSql
+    );
+    sqlite3_free(zStr);
+  }
+}
 
 
 #ifndef SQLITE_OMIT_VIRTUALTABLE