Logging enhancements. And mark logs v=12.

FossilOrigin-Name: 853f9cf453d13cf826443b0d27331e1f4e9e06f9f4ce674f22ccadad86e20937

diff --git a/manifest b/manifest
index c2eac0ac10a3ac963803e86085a0a006b5275051..b5b7e693bca6503b94dc518006dbccd73b549719 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Experimental\schange\sto\somit\swriting\sframe\schecksums\sto\sthe\swal\sfile.
-D 2024-11-20T18:49:01.906
+C Logging\senhancements.\sAnd\smark\slogs\sv=12.
+D 2024-11-20T20:26:59.183
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@@ -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 b7efae210f5aea8d4e7b6412f70b0b1c744dc397527339f68a186bf24c04198d
+F src/vdbe.h b74bfd9cb1fa895e545a5286ee1cac6d75f706d325f89be0e3bf3c5107eb8a78
 F src/vdbeInt.h 92b7eabbaadbe8127741cd96e7e39c4834c2bb0b75987d5f6251975f47233690
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c 0e907a424bd204867bb73665cb3a71a9211d45f1bd4c411bcf3183c9b138ce35
+F src/vdbeaux.c 795a55f9c5bd2b12fae3c7db7c59348cf5a6ce5a6644ecde4efdb8e5934f29d4
 F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797
 F src/vdbemem.c 831a244831eaa45335f9ae276b50a7a82ee10d8c46c2c72492d4eb8c98d94d89
 F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f
@@ -857,7 +857,7 @@ F src/vdbetrace.c fe0bc29ebd4e02c8bc5c1945f1d2e6be5927ec12c06d89b03ef2a4def34bf8
 F src/vdbevtab.c fc46b9cbd759dc013f0b3724549cc0d71379183c667df3a5988f7e2f1bd485f3
 F src/vtab.c 5fb499d20494b7eecaadb7584634af9afcb374cb0524912b475fcb1712458a1b
 F src/vxworks.h d2988f4e5a61a4dfe82c6524dd3d6e4f2ce3cdb9
-F src/wal.c 2b1947a92536c1eeca743cd54b5fddb726040e413abd66197744b645f232fd85
+F src/wal.c 7468f953990f1fd22a64a0127e1492d8d7b422b38c3655a7bafe20f83a68ce74
 F src/wal.h 8c59ee7a835574396d7cbd04626d11fd849613e361a46e7e9519091ab03bdb29
 F src/walker.c d5006d6b005e4ea7302ad390957a8d41ed83faa177e412f89bc5600a7462a014
 F src/where.c c046dd58c3410f7b7528e1e6317cb876398557bad346d568ed8562321a7d002d
@@ -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 e6663fab61cbcb6e7955ab726821831dd55cc210550d74327265210e5bb93c2a
-R 9a6fce3789fc705965d6b202838b94f6
+P 4d3706727005397c3c9006b9ad9a2645b09533b02735ea68974c4f2df4c2e853
+R fe4209ae8ea3d2442ba5298ec1025166
 U dan
-Z 6cbcba363e01fa0e7f18f1969c59edcc
+Z ba19c0c7b0db403fd9268dd73b4106ef
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index 903e279c1990457ea365f0b76f5e1e58629a6b1f..fa292cb2f5c63695c22ca71f937854b567a34efa 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-4d3706727005397c3c9006b9ad9a2645b09533b02735ea68974c4f2df4c2e853
+853f9cf453d13cf826443b0d27331e1f4e9e06f9f4ce674f22ccadad86e20937

diff --git a/src/vdbe.h b/src/vdbe.h
index b3df6f165a853a6af6438fea6c1e4fa5764ad395..4f43413df7c0c23f3409d6f1e476414cc4a20422 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -462,21 +462,22 @@ int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr);
 #define COMMIT_TIME_BEFORE_WALINDEX 24
 
 #define COMMIT_TIME_WALINDEX_HASHGETUS 25
-#define COMMIT_TIME_WALINDEX_CLEANUPUS 26
-#define COMMIT_TIME_WALINDEX_ENTRYUS   27
-
-#define COMMIT_TIME_AFTER_WALINDEX 28
-#define COMMIT_TIME_AFTER_WALINDEXHDR 29
-#define COMMIT_TIME_WALFRAMESFLAGS 30
-#define COMMIT_TIME_AFTER_WALFRAMES 31
-#define COMMIT_TIME_BEFORE_PHASETWO 32
-#define COMMIT_TIME_AFTER_PHASETWO 33
-
-#define COMMIT_TIME_AFTER_VDBECOMMIT 34
-#define COMMIT_TIME_AFTER_HALT 35
-#define COMMIT_TIME_FINISH 36
-
-#define COMMIT_TIME_N 37
+#define COMMIT_TIME_WALINDEX_MEMSETUS 26
+#define COMMIT_TIME_WALINDEX_CLEANUPUS 27
+#define COMMIT_TIME_WALINDEX_ENTRYUS   28
+
+#define COMMIT_TIME_AFTER_WALINDEX 29
+#define COMMIT_TIME_AFTER_WALINDEXHDR 30
+#define COMMIT_TIME_WALFRAMESFLAGS 31
+#define COMMIT_TIME_AFTER_WALFRAMES 32
+#define COMMIT_TIME_BEFORE_PHASETWO 33
+#define COMMIT_TIME_AFTER_PHASETWO 34
+
+#define COMMIT_TIME_AFTER_VDBECOMMIT 35
+#define COMMIT_TIME_AFTER_HALT 36
+#define COMMIT_TIME_FINISH 37
+
+#define COMMIT_TIME_N 38
 
 /* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */
 #define COMMIT_TIME_TIMEOUT (10*1000)         /* 10ms threshold */

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index 8bb8d29c1874b10d617fa0df5d8e22ad261eb829..5dd1f66666ce3b2e3fdb8ef6abbf73eaa0d6b723 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -5487,6 +5487,7 @@ void sqlite3CommitTimeLog(u64 *aCommit){
              || ii==COMMIT_TIME_WALINDEX_HASHGETUS
              || ii==COMMIT_TIME_WALINDEX_CLEANUPUS
              || ii==COMMIT_TIME_WALINDEX_ENTRYUS
+             || ii==COMMIT_TIME_WALINDEX_MEMSETUS
       ){
         iVal = (int)aCommit[ii];
         zU = "us";
@@ -5498,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=11): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=12): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }
@@ -5526,7 +5527,7 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
     }
     if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
     sqlite3_log(SQLITE_WARNING, 
-        "slow prepare (v=11): (%s) [%.*s]", zStr, nByte, zSql
+        "slow prepare (v=12): (%s) [%.*s]", zStr, nByte, zSql
     );
     sqlite3_free(zStr);
   }
@@ -5542,7 +5543,7 @@ void sqlite3SchemaTimeLog(u64 *aSchema){
         (aSchema[ii]==0 ? 0 : (int)(aSchema[ii] - i1))
       );
     }
-    sqlite3_log(SQLITE_WARNING, "slow schema (v=11): (%s)", zStr);
+    sqlite3_log(SQLITE_WARNING, "slow schema (v=12): (%s)", zStr);
     sqlite3_free(zStr);
   }
 }

diff --git a/src/wal.c b/src/wal.c
index 9de87bf24aef38b7d6248a6c6631dbfada01ab95..d764fec427a1b2cf730d305b70736b8e9eafb683 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -1668,11 +1668,15 @@ static int walIndexAppend(Wal *pWal, int iWal, u32 iFrame, u32 iPage){
     /* If this is the first entry to be added to this hash-table, zero the
     ** entire hash table and aPgno[] array before proceeding.
     */
+    if( pWal->aCommitTime ) t = sqlite3STimeNow();
     if( idx==1 ){
       int nByte = (int)((u8*)&sLoc.aHash[HASHTABLE_NSLOT] - (u8*)sLoc.aPgno);
       assert( nByte>=0 );
       memset((void*)sLoc.aPgno, 0, nByte);
     }
+    if( pWal->aCommitTime ){
+      pWal->aCommitTime[COMMIT_TIME_WALINDEX_MEMSETUS]+=sqlite3STimeNow()-t;
+    }
 
     /* If the entry in aPgno[] is already set, then the previous writer
     ** must have exited unexpectedly in the middle of a transaction (after
@@ -1702,6 +1706,7 @@ static int walIndexAppend(Wal *pWal, int iWal, u32 iFrame, u32 iPage){
     }
 
 #ifdef SQLITE_ENABLE_EXPENSIVE_ASSERT
+    assert( this_should_not_be_enabled );
     /* Verify that the number of entries in the hash table exactly equals
     ** the number of entries in the mapping region.
     */