Add extra logging to SQL statements used to load the database schema on this branch...

FossilOrigin-Name: 08e1dea9c070c9a2d668d39ceb153bc8b6d172e7273f6564a374c43055e84461

diff --git a/manifest b/manifest
index 6edcc397070c00d5a2b8ff6d11273c58bc63cd1b..63253a32f426fd41122a919ca940bd95de39e929 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Fix\sa\stypo\sin\sthe\sprevious\scommit.
-D 2024-10-10T15:28:18.193
+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
 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 d7874bc885906868cd51e6c2156698f2754f02d9eee1bae2d687323c3ca8e5aa
+F src/legacy.c 40f29a5d84e5de400dd8a645626b0c620612523d07540faff8ae26cc8df3a4f6
 F src/loadext.c 7432c944ff197046d67a1207790a1b13eec4548c85a9457eb0896bb3641dfb36
 F src/main.c def50c462ce61f722196f7615d79374e2e5b9e856cce2991192faea3b9dbd33c
 F src/malloc.c 410e570b30c26cc36e3372577df50f7a96ee3eed5b2b161c6b6b48773c650c5e
@@ -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 878808e2335e3ec65600e26ec12012f145c41b5662d467b94d74880387e05f68
+F src/sqliteInt.h 8e683c99197787b23b778cc715e3398e41dc4fda7339e6fa87ac1bbfba8c20f1
 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 593f95af78e249b3f4de32df9475c792ab3f82d526c97103219f2a029ae9c3dc
+F src/vdbeaux.c 4dfb4fcad7cabf34c469fdaa41dd5f048e400fa59a72f4cdcf80649636357c5b
 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 f29ff2f308d7f7c757a8bdf9624fadbda55bd5291c18268e10d3bb7e311b229e
-R 607f1797ef1e134122bc0ac1ab5dace0
+P 6deb4794f8e24dbb946069de1e5c34fbcd4734162002f3bc7deb1a3f69adec05
+R d16d707406d8d29328720dd073b80e3d
 U dan
-Z 32c285001d194978689cb95ccaa3d7d5
+Z 5d1fe4a2a6a8ab81a8ff24dd0d57a905
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index 0765630276cc5a4f4a32e7420169ff69fc4b5d47..c16effa0b3bc3f9923f9fec5ba5ae7a18c061104 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-6deb4794f8e24dbb946069de1e5c34fbcd4734162002f3bc7deb1a3f69adec05
+08e1dea9c070c9a2d668d39ceb153bc8b6d172e7273f6564a374c43055e84461

diff --git a/src/legacy.c b/src/legacy.c
index 867587e5a2fb1a78ad7f84c557649553475557d0..6382607dea5aeccac79a11ef2f7cc3738c345936 100644 (file)
--- a/src/legacy.c
+++ b/src/legacy.c
@@ -48,6 +48,11 @@ 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;
+    }
 
     pStmt = 0;
     rc = sqlite3_prepare_v2(db, zSql, -1, &pStmt, &zLeftover);
@@ -108,6 +113,9 @@ int sqlite3_exec(
       }
 
       if( rc!=SQLITE_ROW ){
+        if( db->init.busy && (sqlite3STimeNow()-tmStart)>PREPARE_TIME_TIMEOUT ){
+          sqlite3SchemaTimeLog((Vdbe*)pStmt);
+        }
         rc = sqlite3VdbeFinalize((Vdbe *)pStmt);
         pStmt = 0;
         zSql = zLeftover;
@@ -116,6 +124,11 @@ 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/sqliteInt.h b/src/sqliteInt.h
index 62a8bf8e96456cc4561408fbd8b4161f1a767a69..eb55827bdc46d09027935cf6a263d07a2879d8d2 100644 (file)
--- a/src/sqliteInt.h
+++ b/src/sqliteInt.h
@@ -1852,6 +1852,7 @@ struct sqlite3 {
 
 #define sqlite3PrepareTimeSet(x,y) sqlite3CommitTimeSet(x,y)
 void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepareTime);
+void sqlite3SchemaTimeLog(Vdbe *pVdbe);
 
 #define PREPARE_TIME_TIMEOUT (2 * 1000 * 1000)    /* 2 second timeout */
 

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index ad2a2a90204065f02ec9c4ee9d66a4bdb2ded975..bf498468a5af1947cbb1e296b75eb41fc2f73bdc 100644 (file)
--- 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=2): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=3): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }
@@ -5499,11 +5499,25 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
     }
     if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
     sqlite3_log(SQLITE_WARNING, 
-        "slow prepare (v=2): (%s) [%.*s]", zStr, nByte, zSql
+        "slow prepare (v=3): (%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
+    );
+  }
+  sqlite3_log(SQLITE_WARNING, 
+      "slow schema query (v=3): (%s) [%s]", zStr, pVdbe->zSql
+  );
+  sqlite3_free(zStr);
+}
 
 
 #ifndef SQLITE_OMIT_VIRTUALTABLE