From: dan <Dan Kennedy>
Date: Tue, 22 Oct 2024 16:26:14 +0000 (+0000)
Subject: Add still more logging to determine why schema loads are so slow in some circumstances.
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=b9cdea7c98a7fda220366182a627a819d75bd3a8;p=thirdparty%2Fsqlite.git

Add still more logging to determine why schema loads are so slow in some circumstances.

FossilOrigin-Name: d02ec06e5bde7c8dc0f21ca2bfc44597aca015854d5656f851f4518476d04381
---

diff --git a/manifest b/manifest
index 63253a32f4..491c75a965 100644
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Add\sextra\slogging\sto\sSQL\sstatements\sused\sto\sload\sthe\sdatabase\sschema\son\sthis\sbranch.\sThis\srequires\sSQLITE_ENABLE_STMT_SCANSTATUS.
-D 2024-10-21T11:49:04.907
+C Add\sstill\smore\slogging\sto\sdetermine\swhy\sschema\sloads\sare\sso\sslow\sin\ssome\scircumstances.
+D 2024-10-22T16:26:14.924
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@@ -735,7 +735,7 @@ F src/hwtime.h f9c2dfb84dce7acf95ce6d289e46f5f9d3d1afd328e53da8f8e9008e3b3caae6
 F src/in-operator.md 10cd8f4bcd225a32518407c2fb2484089112fd71
 F src/insert.c f8d1a0f8ee258411009c6b7f2d93170e351bd19f5ad89d57e1180644297cbe70
 F src/json.c 68a98c020c22127f2d65f08855f7fc7460ff352a6ce0b543d8931dde83319c22
-F src/legacy.c 40f29a5d84e5de400dd8a645626b0c620612523d07540faff8ae26cc8df3a4f6
+F src/legacy.c 5fff8efbb4f20396136beb913fff323686cff8f6f5d7d728189f68e98f7310bb
 F src/loadext.c 7432c944ff197046d67a1207790a1b13eec4548c85a9457eb0896bb3641dfb36
 F src/main.c def50c462ce61f722196f7615d79374e2e5b9e856cce2991192faea3b9dbd33c
 F src/malloc.c 410e570b30c26cc36e3372577df50f7a96ee3eed5b2b161c6b6b48773c650c5e
@@ -769,7 +769,7 @@ F src/pcache.h 1497ce1b823cf00094bb0cf3bac37b345937e6f910890c626b16512316d3abf5
 F src/pcache1.c 430b86e10b8d6ae65832a19a0016f8f65f74207687bc9501c0b15a5908bcb6ad
 F src/pragma.c 08472536cf1ecc38947d56f6cb2c8d8b3f6a26722451a38614c41a5b0cbcfc52
 F src/pragma.h 6ebbdee90ed56a892d2c728e27fd9c1ce48c8a28841888d0c6c147946b38cb25
-F src/prepare.c c2b3221d0215d75f355e7aa46020275ed8453293dd63be398b3846e2118e7e92
+F src/prepare.c 140ce8271ba7da946668ad2e0c68fe14419319cb6c68cfcd660186557c271969
 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 8e683c99197787b23b778cc715e3398e41dc4fda7339e6fa87ac1bbfba8c20f1
+F src/sqliteInt.h 0c3db4598b7b9c6aced18496bd6b1f6f56f2d739ff30297e5051093f1b4cfcc2
 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 ed70dc763f22fe856884cc065473061bfe9954bd221daaf3ac517f01c33d0b0f
 F src/vdbeInt.h 494b7b3430fb53adef43e5fd9ede20029750f188f2dbb064e7b86cdf9fb755d7
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c 4dfb4fcad7cabf34c469fdaa41dd5f048e400fa59a72f4cdcf80649636357c5b
+F src/vdbeaux.c 16323344b313db01298573fd52816f20501311a36aa825f5f0bd7afa2fd811a2
 F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797
 F src/vdbemem.c 831a244831eaa45335f9ae276b50a7a82ee10d8c46c2c72492d4eb8c98d94d89
 F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f
@@ -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 6deb4794f8e24dbb946069de1e5c34fbcd4734162002f3bc7deb1a3f69adec05
-R d16d707406d8d29328720dd073b80e3d
+P 08e1dea9c070c9a2d668d39ceb153bc8b6d172e7273f6564a374c43055e84461
+R 94bb34a3eda8f372bde8de70614acb52
 U dan
-Z 5d1fe4a2a6a8ab81a8ff24dd0d57a905
+Z a1cf697854d2ed08ac2ba1f2daa0689c
 # Remove this line to create a well-formed Fossil manifest.
diff --git a/manifest.uuid b/manifest.uuid
index c16effa0b3..e88be74e9f 100644
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-08e1dea9c070c9a2d668d39ceb153bc8b6d172e7273f6564a374c43055e84461
+d02ec06e5bde7c8dc0f21ca2bfc44597aca015854d5656f851f4518476d04381
diff --git a/src/legacy.c b/src/legacy.c
index 6382607dea..4146e3a18d 100644
--- a/src/legacy.c
+++ b/src/legacy.c
@@ -48,12 +48,8 @@ int sqlite3_exec(
   while( rc==SQLITE_OK && zSql[0] ){
     int nCol = 0;
     char **azVals = 0;
-    i64 tmStart = sqlite3STimeNow();
-    u64 svFlags = db->flags;
-    if( db->init.busy ){
-      db->flags |= SQLITE_StmtScanStatus;
-    }
 
+    sqlite3PrepareTimeSet(db->aSchemaTime, SCHEMA_TIME_BEFORE_PREPARE);
     pStmt = 0;
     rc = sqlite3_prepare_v2(db, zSql, -1, &pStmt, &zLeftover);
     assert( rc==SQLITE_OK || pStmt==0 );
@@ -67,6 +63,7 @@ int sqlite3_exec(
     }
     callbackIsInit = 0;
 
+    sqlite3PrepareTimeSet(db->aSchemaTime, SCHEMA_TIME_BEFORE_STEP);
     while( 1 ){
       int i;
       rc = sqlite3_step(pStmt);
@@ -112,10 +109,8 @@ int sqlite3_exec(
         }
       }
 
+      sqlite3PrepareTimeSet(db->aSchemaTime, SCHEMA_TIME_BEFORE_FINALIZE);
       if( rc!=SQLITE_ROW ){
-        if( db->init.busy && (sqlite3STimeNow()-tmStart)>PREPARE_TIME_TIMEOUT ){
-          sqlite3SchemaTimeLog((Vdbe*)pStmt);
-        }
         rc = sqlite3VdbeFinalize((Vdbe *)pStmt);
         pStmt = 0;
         zSql = zLeftover;
@@ -124,11 +119,6 @@ int sqlite3_exec(
       }
     }
 
-    if( db->init.busy ){
-      /* Clear the SQLITE_StmtScanStatus flag if it was clear at the top
-      ** of this loop.  */
-      db->flags &= (~SQLITE_StmtScanStatus | svFlags);
-    }
     sqlite3DbFree(db, azCols);
     azCols = 0;
   }
diff --git a/src/prepare.c b/src/prepare.c
index 6d7e3c6863..f5ca85c33a 100644
--- a/src/prepare.c
+++ b/src/prepare.c
@@ -209,6 +209,11 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
   int openedTransaction = 0;
   int mask = ((db->mDbFlags & DBFLAG_EncodingFixed) | ~DBFLAG_EncodingFixed);
 
+  u64 aSchemaTime[SCHEMA_TIME_N];
+  memset(aSchemaTime, 0, sizeof(aSchemaTime));
+  db->aSchemaTime = aSchemaTime;
+  sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_START);
+
   assert( (db->mDbFlags & DBFLAG_SchemaKnownOk)==0 );
   assert( iDb>=0 && iDb<db->nDb );
   assert( db->aDb[iDb].pSchema );
@@ -243,6 +248,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
     goto error_out;
   }
 
+  sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_CREATE_1);
+
   /* Create a cursor to hold the database open
   */
   pDb = &db->aDb[iDb];
@@ -266,6 +273,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
     openedTransaction = 1;
   }
 
+  sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_OPEN_TRANS);
+
   /* Get the database meta information.
   **
   ** Meta values are as follows:
@@ -291,6 +300,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
   }
   pDb->pSchema->schema_cookie = meta[BTREE_SCHEMA_VERSION-1];
 
+  sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_GET_META);
+
   /* If opening a non-empty database, check the text encoding. For the
   ** main database, set sqlite3.enc to the encoding of the main database.
   ** For an attached db, it is an error if the encoding is not the same
@@ -326,6 +337,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
   }
   pDb->pSchema->enc = ENC(db);
 
+  sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_FIX_ENCODING);
+
   if( pDb->pSchema->cache_size==0 ){
 #ifndef SQLITE_OMIT_DEPRECATED
     size = sqlite3AbsInt32(meta[BTREE_DEFAULT_CACHE_SIZE-1]);
@@ -337,6 +350,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
     sqlite3BtreeSetCacheSize(pDb->pBt, pDb->pSchema->cache_size);
   }
 
+  sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_SETCACHESIZE);
+
   /*
   ** file_format==1    Version 3.0.0.
   ** file_format==2    Version 3.1.3.  // ALTER TABLE ADD COLUMN
@@ -377,6 +392,7 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
       xAuth = db->xAuth;
       db->xAuth = 0;
 #endif
+      sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_BEGIN_EXEC);
       rc = sqlite3_exec(db, zSql, sqlite3InitCallback, &initData, 0);
 #ifndef SQLITE_OMIT_AUTHORIZATION
       db->xAuth = xAuth;
@@ -384,11 +400,13 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
 #endif
     if( rc==SQLITE_OK ) rc = initData.rc;
     sqlite3DbFree(db, zSql);
+    sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_BEGIN_ANALYZE_LOAD);
 #ifndef SQLITE_OMIT_ANALYZE
     if( rc==SQLITE_OK ){
       sqlite3AnalysisLoad(db, iDb);
     }
 #endif
+    sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_END_ANALYZE_LOAD);
   }
   assert( pDb == &(db->aDb[iDb]) );
   if( db->mallocFailed ){
@@ -422,6 +440,9 @@ initone_error_out:
   sqlite3BtreeLeave(pDb->pBt);
 
 error_out:
+  db->aSchemaTime = 0;
+  sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_FINISH);
+  sqlite3SchemaTimeLog(aSchemaTime);
   if( rc ){
     if( rc==SQLITE_NOMEM || rc==SQLITE_IOERR_NOMEM ){
       sqlite3OomFault(db);
diff --git a/src/sqliteInt.h b/src/sqliteInt.h
index eb55827bdc..d0501bb683 100644
--- a/src/sqliteInt.h
+++ b/src/sqliteInt.h
@@ -1828,6 +1828,7 @@ struct sqlite3 {
 #endif
 
   u64 *aPrepareTime;
+  u64 *aSchemaTime;
 };
 
 #define PREPARE_TIME_START 0
@@ -1850,9 +1851,30 @@ struct sqlite3 {
 
 #define PREPARE_TIME_N 14
 
+
+
+#define SCHEMA_TIME_START 0
+#define SCHEMA_TIME_AFTER_CREATE_1 1
+#define SCHEMA_TIME_AFTER_OPEN_TRANS 2
+#define SCHEMA_TIME_AFTER_GET_META 3
+#define SCHEMA_TIME_AFTER_FIX_ENCODING 4
+#define SCHEMA_TIME_AFTER_SETCACHESIZE 5
+#define SCHEMA_TIME_BEGIN_EXEC 6
+#define SCHEMA_TIME_BEFORE_STEP 7
+#define SCHEMA_TIME_BEFORE_PREPARE 8
+#define SCHEMA_TIME_BEFORE_FINALIZE 9
+#define SCHEMA_TIME_BEGIN_ANALYZE_LOAD 10
+#define SCHEMA_TIME_END_ANALYZE_LOAD 11
+#define SCHEMA_TIME_FINISH 12
+
+#define SCHEMA_TIME_N 13
+#define SCHEMA_TIME_TIMEOUT (1 * 1000 * 1000)
+
+
+
 #define sqlite3PrepareTimeSet(x,y) sqlite3CommitTimeSet(x,y)
 void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepareTime);
-void sqlite3SchemaTimeLog(Vdbe *pVdbe);
+void sqlite3SchemaTimeLog(u64 *aSchemaTime);
 
 #define PREPARE_TIME_TIMEOUT (2 * 1000 * 1000)    /* 2 second timeout */
 
diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index bf498468a5..04910280e7 100644
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -5471,7 +5471,7 @@ void sqlite3CommitTimeLog(u64 *aCommit){
         (aCommit[ii]==0 ? 0 : (int)(aCommit[ii] - i1))
       );
     }
-    sqlite3_log(SQLITE_WARNING, "slow commit (v=3): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=4): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }
@@ -5499,24 +5499,25 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
     }
     if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
     sqlite3_log(SQLITE_WARNING, 
-        "slow prepare (v=3): (%s) [%.*s]", zStr, nByte, zSql
+        "slow prepare (v=4): (%s) [%.*s]", zStr, nByte, zSql
     );
     sqlite3_free(zStr);
   }
 }
-void sqlite3SchemaTimeLog(Vdbe *pVdbe){
-  int ii;
-  char *zStr = 0;
-  for(ii=0; ii<pVdbe->nOp; ii++){
-    VdbeOp *pOp = &pVdbe->aOp[ii];
-    zStr = sqlite3_mprintf("%z%s(%s %lld %lld)", zStr, (zStr?" ":""),
-        (char*)sqlite3OpcodeName(pOp->opcode), pOp->nExec, pOp->nCycle
-    );
+void sqlite3SchemaTimeLog(u64 *aSchema){
+  u64 i1 = aSchema[SCHEMA_TIME_START];
+  assert( SCHEMA_TIME_START==0 && SCHEMA_TIME_FINISH==SCHEMA_TIME_N-1 );
+  if( aSchema[SCHEMA_TIME_FINISH]>(i1+SCHEMA_TIME_TIMEOUT) ){
+    char *zStr = 0;
+    int ii;
+    for(ii=1; ii<SCHEMA_TIME_N; ii++){
+      zStr = sqlite3_mprintf("%z%s%d", zStr, (zStr?", ":""), 
+        (aSchema[ii]==0 ? 0 : (int)(aSchema[ii] - i1))
+      );
+    }
+    sqlite3_log(SQLITE_WARNING, "slow schema (v=4): (%s)", zStr);
+    sqlite3_free(zStr);
   }
-  sqlite3_log(SQLITE_WARNING, 
-      "slow schema query (v=3): (%s) [%s]", zStr, pVdbe->zSql
-  );
-  sqlite3_free(zStr);
 }