Add extra logging points to the code on this branch.

FossilOrigin-Name: f29ff2f308d7f7c757a8bdf9624fadbda55bd5291c18268e10d3bb7e311b229e

diff --git a/manifest b/manifest
index 21de1f507d077486124b115fa73a489415cd12b4..1a6844bf573f1066cb2db8ad2f50f3ebfe12cb4a 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Add\slogging\sto\shelp\sanalyze\sslow\s"PRAGMA\scache_size\s=\s?"\sstatements.
-D 2024-10-08T15:08:04.720
+C Add\sextra\slogging\spoints\sto\sthe\scode\son\sthis\sbranch.
+D 2024-10-10T14:31:37.100
 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 e681d91414a55bf639640f38bd7c035f477b8e482a130ea439c89e4ba8b9356d
+F src/btree.c 27981b16cd21722b4e2ef8afcbb159f9e8fb54e4b2f8187cfd4b912a13d628d5
 F src/btree.h bdeeb35614caa33526b603138f04c8d07a3f90a1300b5ade76848b755edf2027
 F src/btreeInt.h caa893e74d2261fb0ff1681fce998533c0552858e882bd04fc6805075f5f6e75
 F src/build.c 08697d6a4df78f8e289582eb58473445492319676f81cc4794ef4056d36ae5fd
@@ -767,7 +767,7 @@ F src/parse.y 8388b36e6cd15ebc5c1796cb72dd0a67a04abc446f52838ab3a2e8591487b2f1
 F src/pcache.c 588cc3c5ccaaadde689ed35ce5c5c891a1f7b1f4d1f56f6cf0143b74d8ee6484
 F src/pcache.h 1497ce1b823cf00094bb0cf3bac37b345937e6f910890c626b16512316d3abf5
 F src/pcache1.c 430b86e10b8d6ae65832a19a0016f8f65f74207687bc9501c0b15a5908bcb6ad
-F src/pragma.c 56663a75d517d77b95dcf5e6a597e8a1ce49413c4e30ea79148926cc4c1db912
+F src/pragma.c 08472536cf1ecc38947d56f6cb2c8d8b3f6a26722451a38614c41a5b0cbcfc52
 F src/pragma.h 6ebbdee90ed56a892d2c728e27fd9c1ce48c8a28841888d0c6c147946b38cb25
 F src/prepare.c c2b3221d0215d75f355e7aa46020275ed8453293dd63be398b3846e2118e7e92
 F src/printf.c 6a87534ebfb9e5346011191b1f3a7ebc457f5938c7e4feeea478ecf53f6a41b2
@@ -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 09b2035fec910b58b8a2a9a3dedd0fe919ac2487dc1effcfd2c3b4eec9edab60
+F src/sqliteInt.h 878808e2335e3ec65600e26ec12012f145c41b5662d467b94d74880387e05f68
 F src/sqliteLimit.h 6878ab64bdeb8c24a1d762d45635e34b96da21132179023338c93f820eee6728
 F src/status.c cb11f8589a6912af2da3bb1ec509a94dd8ef27df4d4c1a97e0bcf2309ece972b
 F src/table.c 0f141b58a16de7e2fbe81c308379e7279f4c6b50eb08efeec5892794a0ba30d1
@@ -846,10 +846,10 @@ F src/utf.c f23165685a67b4caf8ec08fb274cb3f319103decfb2a980b7cfd55d18dfa855e
 F src/util.c 5d1a0134cf4240648d1c6bb5cc8efaca0ea2b5d5c840985aec7e947271f04375
 F src/vacuum.c 25e407a6dc8b288fa4295b3d92fa9ce9318503e84df53cdf403a50fccbc1ba31
 F src/vdbe.c fea60cfe46d8839a08e4680d90a96898d542d3f6d7954e2e99cd92596f1a01f8
-F src/vdbe.h 7d6a7fefce6068d78e350367ee16eeaf72632163623044623d35fce88e12be66
+F src/vdbe.h 0409222debcb215b13eaabc97afb4d38e64e6eb9d6deda5b0067000d19ba2cb0
 F src/vdbeInt.h 494b7b3430fb53adef43e5fd9ede20029750f188f2dbb064e7b86cdf9fb755d7
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c d00eb15e7f46a4a9466de4bb0fd8ae98b57abfa04c1d4db19f4bdc665fbb684e
+F src/vdbeaux.c 593f95af78e249b3f4de32df9475c792ab3f82d526c97103219f2a029ae9c3dc
 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 c5391f2cc913a16695efb63f7d2320fc18b8aaefdbdffa087a2e3d26b24dc218
-R 48fb9da465c7791ce99a13be44d71147
+P cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249
+R 4927122397c1b68485053501762e9365
 U dan
-Z dcf509c08a497f2bbb5716a149310ff4
+Z 0fc8cc666acc9a587659cdfa77c14ae5
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index 11bfaabe9bfc71830175043495aaa77eb7832381..7ad1d2a5709bee5c45cae4f3b00822de836b171a 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249
+f29ff2f308d7f7c757a8bdf9624fadbda55bd5291c18268e10d3bb7e311b229e

diff --git a/src/btree.c b/src/btree.c
index c25e1760d5a5fbc0d2a230d11a3c64b9caf5416f..9c2d3116ea33d5bfb1748d79389fb2b37d449651 100644 (file)
--- a/src/btree.c
+++ b/src/btree.c
@@ -4607,6 +4607,8 @@ static int btreeFixUnlocked(Btree *p){
   Pgno nPage = btreePagecount(pBt);
   u32 nFree = get4byte(&p1[36]);
 
+  sqlite3CommitTimeSet(p->pBt->aCommitTime, COMMIT_TIME_START_FIXUNLOCKED);
+
   assert( pBt->pMap );
   rc = sqlite3PagerUpgradeSnapshot(pPager, pPage1->pDbPage);
   assert( p1==pPage1->aData );
@@ -4653,6 +4655,7 @@ static int btreeFixUnlocked(Btree *p){
 
         nCurrent = MAX(nPage, nHPage);
         pBt->nPage = nCurrent;
+        sqlite3CommitTimeSet(p->pBt->aCommitTime, COMMIT_TIME_START_RELOCATE1);
         rc = btreeRelocateRange(pBt, pMap->iFirst, iLast, &nCurrent);
 
         /* There are now no collisions with the snapshot at the head of the
@@ -4669,6 +4672,9 @@ static int btreeFixUnlocked(Btree *p){
             nFin--;
           }
           nFin = MAX(nFin, nHPage);
+          sqlite3CommitTimeSet(
+              p->pBt->aCommitTime, COMMIT_TIME_START_RELOCATE2
+          );
           rc = btreeRelocateRange(pBt, nFin+1, nCurrent, 0);
         }
 

diff --git a/src/pragma.c b/src/pragma.c
index 20fa012edb15438be91fa7dd7dd2d1d127d71e77..28a567ce9dcaa8c0140ad702df360e32f40d5234 100644 (file)
--- a/src/pragma.c
+++ b/src/pragma.c
@@ -452,11 +452,13 @@ void sqlite3Pragma(
     zRight = sqlite3NameFromToken(db, pValue);
   }
 
+  sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINAUTHCHECK);
   assert( pId2 );
   zDb = pId2->n>0 ? pDb->zDbSName : 0;
   if( sqlite3AuthCheck(pParse, SQLITE_PRAGMA, zLeft, zRight, zDb) ){
     goto pragma_out;
   }
+  sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDAUTHCHECK);
 
   /* Send an SQLITE_FCNTL_PRAGMA file-control to the underlying VFS
   ** connection.  If it returns SQLITE_OK, then assume that the VFS
@@ -504,10 +506,12 @@ void sqlite3Pragma(
     goto pragma_out;
   }
 
+  sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINLOADSCHEMA);
   /* Make sure the database schema is loaded if the pragma requires that */
   if( (pPragma->mPragFlg & PragFlg_NeedSchema)!=0 ){
     if( sqlite3ReadSchema(pParse) ) goto pragma_out;
   }
+  sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDLOADSCHEMA);
 
   /* Register the result column names for pragmas that return results */
   if( (pPragma->mPragFlg & PragFlg_NoColumns)==0

diff --git a/src/sqliteInt.h b/src/sqliteInt.h
index 75b81674c6aa630803bff4133a96acc91142f040..62a8bf8e96456cc4561408fbd8b4161f1a767a69 100644 (file)
--- a/src/sqliteInt.h
+++ b/src/sqliteInt.h
@@ -1833,15 +1833,22 @@ struct sqlite3 {
 #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 PREPARE_TIME_BEGINAUTHCHECK 3
+#define PREPARE_TIME_ENDAUTHCHECK 4
+#define PREPARE_TIME_BEGINLOADSCHEMA 5
+#define PREPARE_TIME_ENDLOADSCHEMA 6
+
+
+#define PREPARE_TIME_BEGINCACHESIZE 7
+#define PREPARE_TIME_BEGINSETCACHESIZE 8
+#define PREPARE_TIME_ENDSETCACHESIZE 9
+#define PREPARE_TIME_ENDCACHESIZE 10
+#define PREPARE_TIME_ENDPRAGMA 11
+#define PREPARE_TIME_ENDPARSE 12
+#define PREPARE_TIME_FINISH 13
+
+#define PREPARE_TIME_N 14
 
 #define sqlite3PrepareTimeSet(x,y) sqlite3CommitTimeSet(x,y)
 void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepareTime);

diff --git a/src/vdbe.h b/src/vdbe.h
index 3dcc61ebebb32919b210ebd203d50ca1798e5eca..558f45a6bb708c14d115f6b55b5b812147ca1e68 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -431,20 +431,24 @@ int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr);
 #define COMMIT_TIME_BEFORE_VDBECOMMIT 2
 
 #define COMMIT_TIME_BEFORE_PHASEONE 3
-#define COMMIT_TIME_AFTER_FIXUNLOCKED 4
-#define COMMIT_TIME_AFTER_WALFRAMES 5
+#define COMMIT_TIME_START_FIXUNLOCKED 4
+#define COMMIT_TIME_START_RELOCATE1 5
+#define COMMIT_TIME_START_RELOCATE2 6
 
-#define COMMIT_TIME_BEFORE_PHASETWO 6
-#define COMMIT_TIME_AFTER_PHASETWO 7
+#define COMMIT_TIME_AFTER_FIXUNLOCKED 7
+#define COMMIT_TIME_AFTER_WALFRAMES 8
 
-#define COMMIT_TIME_AFTER_VDBECOMMIT 8
-#define COMMIT_TIME_AFTER_HALT 9
-#define COMMIT_TIME_FINISH 10
+#define COMMIT_TIME_BEFORE_PHASETWO 9
+#define COMMIT_TIME_AFTER_PHASETWO 10
 
-#define COMMIT_TIME_N 11
+#define COMMIT_TIME_AFTER_VDBECOMMIT 11
+#define COMMIT_TIME_AFTER_HALT 12
+#define COMMIT_TIME_FINISH 13
+
+#define COMMIT_TIME_N 14
 
 /* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */
-#define COMMIT_TIME_TIMEOUT (10*1000)         /* 10ms threshold */
+#define COMMIT_TIME_TIMEOUT (0*1000)         /* 10ms threshold */
 
 void sqlite3CommitTimeLog(u64*);
 u64 sqlite3STimeNow();

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index 6715c99e023374337a1be233039a3802ec422456..ad2a2a90204065f02ec9c4ee9d66a4bdb2ded975 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=1): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=2): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }
@@ -5481,7 +5481,7 @@ u64 sqlite3STimeNow(){
   return ((u64)time.tv_sec * 1000000 + (u64)time.tv_usec);
 }
 void sqlite3CommitTimeSet(u64 *aCommit, int iCommit){
-  if( aCommit ){
+  if( aCommit && aCommit[iCommit]==0 ){
     aCommit[iCommit] = sqlite3STimeNow();
   }
 }
@@ -5499,7 +5499,7 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
     }
     if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
     sqlite3_log(SQLITE_WARNING, 
-        "slow prepare (v=1): (%s) [%.*s]", zStr, nByte, zSql
+        "slow prepare (v=2): (%s) [%.*s]", zStr, nByte, zSql
     );
     sqlite3_free(zStr);
   }