From 0e8d63cbab625c7f26db0dab55f9bf7c717adacd Mon Sep 17 00:00:00 2001 From: dan Date: Wed, 20 Nov 2024 20:26:59 +0000 Subject: [PATCH] Logging enhancements. And mark logs v=12. FossilOrigin-Name: 853f9cf453d13cf826443b0d27331e1f4e9e06f9f4ce674f22ccadad86e20937 --- manifest | 16 ++++++++-------- manifest.uuid | 2 +- src/vdbe.h | 25 +++++++++++++------------ src/vdbeaux.c | 7 ++++--- src/wal.c | 5 +++++ 5 files changed, 31 insertions(+), 24 deletions(-) diff --git a/manifest b/manifest index c2eac0ac10..b5b7e693bc 100644 --- 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 903e279c19..fa292cb2f5 100644 --- a/manifest.uuid +++ b/manifest.uuid @@ -1 +1 @@ -4d3706727005397c3c9006b9ad9a2645b09533b02735ea68974c4f2df4c2e853 +853f9cf453d13cf826443b0d27331e1f4e9e06f9f4ce674f22ccadad86e20937 diff --git a/src/vdbe.h b/src/vdbe.h index b3df6f165a..4f43413df7 100644 --- 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_WALINDEX_MEMSETUS 26 +#define COMMIT_TIME_WALINDEX_CLEANUPUS 27 +#define COMMIT_TIME_WALINDEX_ENTRYUS 28 -#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_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 34 -#define COMMIT_TIME_AFTER_HALT 35 -#define COMMIT_TIME_FINISH 36 +#define COMMIT_TIME_AFTER_VDBECOMMIT 35 +#define COMMIT_TIME_AFTER_HALT 36 +#define COMMIT_TIME_FINISH 37 -#define COMMIT_TIME_N 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 8bb8d29c18..5dd1f66666 100644 --- 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 9de87bf24a..d764fec427 100644 --- 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. */