Update logging (now v=16) to more closely analyze all attempts to load the main db...

FossilOrigin-Name: 65b753735b8e8fb70d2b522d527426f1eb5c09339fb4b15cf69cbd2e595b160f

diff --git a/manifest b/manifest
index abeac6c0921b9cbcdbbe1f06a09942bbb59b411d..591c2be415c5b8db93ed1655ce83e265cd09b294 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Guard\sthe\sx64\sassembler\sin\swal.c\swith\s"ifdef\s__x86_64__".
-D 2024-12-06T09:36:28.866
+C Update\slogging\s(now\sv=16)\sto\smore\sclosely\sanalyze\sall\sattempts\sto\sload\sthe\smain\sdb\sschema.
+D 2024-12-06T17:52:38.851
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@@ -707,7 +707,7 @@ F sqlite3.1 acdff36db796e2d00225b911d3047d580cd136547298435426ce9d40347973cc
 F sqlite3.pc.in 48fed132e7cb71ab676105d2a4dc77127d8c1f3a
 F sqlite_cfg.h.in baf2e409c63d4e7a765e17769b6ff17c5a82bbd9cbf1e284fd2e4cefaff3fcf2
 F src/alter.c aa93e37e4a36a0525bbb2a2aeda20d2018f0aa995542c7dc658e031375e3f532
-F src/analyze.c 5d9f1574cc1423d805de4ea48ac5786a1a1e88295fd14f175e2e4ed89051cde8
+F src/analyze.c 7fda93b7952edc84282f57f56dd63d99afe428502b0289f571e698e0ce7b978a
 F src/attach.c 08235ab62ed5ccc93c22bf36e640d19effcd632319615851bccf724ec9341333
 F src/auth.c 4c1ea890e0069ad73bead5d17a5b12c34cfa4f1a24175c8147ea439b64be271c
 F src/backup.c 5c97e8023aab1ce14a42387eb3ae00ba5a0644569e3476f38661fa6f824c3523
@@ -769,7 +769,7 @@ F src/pcache.h 1497ce1b823cf00094bb0cf3bac37b345937e6f910890c626b16512316d3abf5
 F src/pcache1.c 437282ad81350c98a8592425b19e1b4e132196f7a81aef49b2ca39c50937b827
 F src/pragma.c 08472536cf1ecc38947d56f6cb2c8d8b3f6a26722451a38614c41a5b0cbcfc52
 F src/pragma.h 6ebbdee90ed56a892d2c728e27fd9c1ce48c8a28841888d0c6c147946b38cb25
-F src/prepare.c 140ce8271ba7da946668ad2e0c68fe14419319cb6c68cfcd660186557c271969
+F src/prepare.c 3476a2d3353d3a881822f888fcd04bfdf5bf62a2a0566ffca83dc42190fdae19
 F src/printf.c 9480e90343dfde2406eeb25ff072774a77453d0f57fcd6495102f915dcc26a82
 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 31cd79e80847fbaacf1987b47b055367a79744c3ccb236801e55da82dfbf21b1
+F src/sqliteInt.h a2b6836f09882cd32cca238b16ed61820b905e188a73df87438805693609030b
 F src/sqliteLimit.h 6878ab64bdeb8c24a1d762d45635e34b96da21132179023338c93f820eee6728
 F src/status.c cb11f8589a6912af2da3bb1ec509a94dd8ef27df4d4c1a97e0bcf2309ece972b
 F src/table.c 0f141b58a16de7e2fbe81c308379e7279f4c6b50eb08efeec5892794a0ba30d1
@@ -849,7 +849,7 @@ F src/vdbe.c fa31aa6525e34b51763702d246a69c3877436f0bbf6be5f6351cdcb770b9b7ab
 F src/vdbe.h b74bfd9cb1fa895e545a5286ee1cac6d75f706d325f89be0e3bf3c5107eb8a78
 F src/vdbeInt.h 92b7eabbaadbe8127741cd96e7e39c4834c2bb0b75987d5f6251975f47233690
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c be04d1494817b428842ecd73b1cdbb76dd5e4bf7f9af576ce8e4eafb9cc61b34
+F src/vdbeaux.c 92fc3d59a6f83ea73befe586d373d75db530ad41c29db66457b8dba99f127f4f
 F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797
 F src/vdbemem.c 831a244831eaa45335f9ae276b50a7a82ee10d8c46c2c72492d4eb8c98d94d89
 F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f
@@ -2250,8 +2250,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 5f9f6764e9dffef60213bbc9604940ddfc713436333c3f62ed8a090697fcbb1e
-R dc2d528d700a9f31a595b645f35f63e8
+P 5fa1699e31856a6585cc59183641c4cc99e1ccd99c384d13e9c4442e9c07f41a
+R 52059697f6646241ab7617b1a870a41c
 U dan
-Z 3df61137fb8f8d436afd0a2fa28a051e
+Z 24925713dc7dc01632d224dd295c2b53
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index d80c58f788168bf544666b5909e75eab5e4ef3db..c568f4a8181abe33b1a3d81114a9a60c601da852 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-5fa1699e31856a6585cc59183641c4cc99e1ccd99c384d13e9c4442e9c07f41a
+65b753735b8e8fb70d2b522d527426f1eb5c09339fb4b15cf69cbd2e595b160f

diff --git a/src/analyze.c b/src/analyze.c
index a2f56f30aa60aec6d4ca87239f779894b16f5c72..03a0aa891a3207166edc54fadf621fa22b3e145c 100644 (file)
--- a/src/analyze.c
+++ b/src/analyze.c
@@ -1805,6 +1805,8 @@ static int loadStatTbl(
     tRowcnt *pSpace; /* Available allocated memory space */
     u8 *pPtr;        /* Available memory as a u8 for easier manipulation */
 
+    u64 t = sqlite3STimeNow();
+
     zIndex = (char *)sqlite3_column_text(pStmt, 0);
     if( zIndex==0 ) continue;
     nSample = sqlite3_column_int(pStmt, 1);
@@ -1844,6 +1846,9 @@ static int loadStatTbl(
       pIdx->aSample[i].anDLt = pSpace; pSpace += nIdxCol;
     }
     assert( ((u8*)pSpace)-nByte==(u8*)(pIdx->aSample) );
+    if( db->aSchemaTime ){
+      db->aSchemaTime[SCHEMA_TIME_STAT4_Q1_BODY] += (sqlite3STimeNow() - t);
+    }
   }
   rc = sqlite3_finalize(pStmt);
   if( rc ) return rc;

diff --git a/src/prepare.c b/src/prepare.c
index f5ca85c33a27f42be75b18a50acea0b022288c19..9246095cb5f11542a66e0b99160f78189cbe77ce 100644 (file)
--- a/src/prepare.c
+++ b/src/prepare.c
@@ -442,7 +442,10 @@ initone_error_out:
 error_out:
   db->aSchemaTime = 0;
   sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_FINISH);
-  sqlite3SchemaTimeLog(aSchemaTime);
+  if( rc==SQLITE_OK && iDb==0 ){
+    const char *zFile = sqlite3BtreeGetFilename(pDb->pBt);
+    sqlite3SchemaTimeLog(aSchemaTime, zFile);
+  }
   if( rc ){
     if( rc==SQLITE_NOMEM || rc==SQLITE_IOERR_NOMEM ){
       sqlite3OomFault(db);

diff --git a/src/sqliteInt.h b/src/sqliteInt.h
index 903c7c1c5f84be2be693c357cb7dcb577f5c0960..c0520c199529866d891f3614b92b178a703e43a6 100644 (file)
--- a/src/sqliteInt.h
+++ b/src/sqliteInt.h
@@ -1869,21 +1869,22 @@ struct sqlite3 {
 #define SCHEMA_TIME_AFTER_STAT1 12
 #define SCHEMA_TIME_AFTER_DEFAULTS 13
 
-#define SCHEMA_TIME_AFTER_STAT4_Q1 14
-#define SCHEMA_TIME_AFTER_STAT4_Q2 15
-#define SCHEMA_TIME_AFTER_STAT4 16
+#define SCHEMA_TIME_STAT4_Q1_BODY 14
+#define SCHEMA_TIME_AFTER_STAT4_Q1 15
+#define SCHEMA_TIME_AFTER_STAT4_Q2 16
+#define SCHEMA_TIME_AFTER_STAT4 17
 
-#define SCHEMA_TIME_END_ANALYZE_LOAD 17
-#define SCHEMA_TIME_FINISH 18
+#define SCHEMA_TIME_END_ANALYZE_LOAD 18
+#define SCHEMA_TIME_FINISH 19
 
-#define SCHEMA_TIME_N 19
-#define SCHEMA_TIME_TIMEOUT (2 * 1000 * 1000)
+#define SCHEMA_TIME_N 20
+#define SCHEMA_TIME_TIMEOUT (0 * 1000 * 1000)
 
 
 
 #define sqlite3PrepareTimeSet(x,y) sqlite3CommitTimeSet(x,y)
 void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepareTime);
-void sqlite3SchemaTimeLog(u64 *aSchemaTime);
+void sqlite3SchemaTimeLog(u64 *aSchemaTime, const char *zFile);
 
 #define PREPARE_TIME_TIMEOUT (2 * 1000 * 1000)    /* 2 second timeout */
 

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index 15d655195a796fc9afcccfebf2eb4b19a161dc2b..a8beab6fbe5ffff579820c77570e6b74362d505e 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -5499,7 +5499,7 @@ void sqlite3CommitTimeLog(u64 *aCommit){
       }
       zStr = sqlite3_mprintf("%z%s%s%d%s", zStr, (zStr?", ":""),zHash,iVal,zU);
     }
-    sqlite3_log(SQLITE_WARNING, "slow commit (v=15): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=16): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }
@@ -5527,12 +5527,12 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
     }
     if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
     sqlite3_log(SQLITE_WARNING, 
-        "slow prepare (v=15): (%s) [%.*s]", zStr, nByte, zSql
+        "slow prepare (v=16): (%s) [%.*s]", zStr, nByte, zSql
     );
     sqlite3_free(zStr);
   }
 }
-void sqlite3SchemaTimeLog(u64 *aSchema){
+void sqlite3SchemaTimeLog(u64 *aSchema, const char *zFile){
   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) ){
@@ -5543,7 +5543,7 @@ void sqlite3SchemaTimeLog(u64 *aSchema){
         (aSchema[ii]==0 ? 0 : (int)(aSchema[ii] - i1))
       );
     }
-    sqlite3_log(SQLITE_WARNING, "slow schema (v=15): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow schema (%s) (v=16): (%s)", zFile, zStr);
     sqlite3_free(zStr);
   }
 }