Add logging to help analyze commit performance.

FossilOrigin-Name: c5391f2cc913a16695efb63f7d2320fc18b8aaefdbdffa087a2e3d26b24dc218

diff --git a/manifest b/manifest
index ec7d7b6f49d9c3b277e948835e6fc1bf85fa0a55..029aaf542907264c8b845db831bc2ef5b6ae96f3 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Update\sthe\sbedrock\sbranch\sto\sinclude\sall\sof\sthe\slatest\strunk\senhancements.
-D 2024-09-04T16:54:56.048
+C Add\slogging\sto\shelp\sanalyze\scommit\sperformance.
+D 2024-10-07T16:11:10.335
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@@ -713,9 +713,9 @@ F src/auth.c 4c1ea890e0069ad73bead5d17a5b12c34cfa4f1a24175c8147ea439b64be271c
 F src/backup.c 5c97e8023aab1ce14a42387eb3ae00ba5a0644569e3476f38661fa6f824c3523
 F src/bitvec.c 501daeef838fa82a9fb53540d72f29e3d9172c8867f1e19f94f681e2e20b966e
 F src/btmutex.c 79a43670447eacc651519a429f6ece9fd638563cf95b469d6891185ddae2b522
-F src/btree.c e3853ede380e7cf37f5e3724409c6dceb2c768a03677dd0abdb6e1c149d411c6
+F src/btree.c c0db29ff599f43af49b83e26754641e606bf75fd9f9f460333616d98b59badfa
 F src/btree.h bdeeb35614caa33526b603138f04c8d07a3f90a1300b5ade76848b755edf2027
-F src/btreeInt.h bb28bf05e6206befd5f5fd2ed3825fc6382979fa4a83bf50f1875a0d3404111b
+F src/btreeInt.h caa893e74d2261fb0ff1681fce998533c0552858e882bd04fc6805075f5f6e75
 F src/build.c 08697d6a4df78f8e289582eb58473445492319676f81cc4794ef4056d36ae5fd
 F src/callback.c db3a45e376deff6a16c0058163fe0ae2b73a2945f3f408ca32cf74960b28d490
 F src/complete.c a3634ab1e687055cd002e11b8f43eb75c17da23e
@@ -761,8 +761,8 @@ F src/os_setup.h 6011ad7af5db4e05155f385eb3a9b4470688de6f65d6166b8956e58a3d87210
 F src/os_unix.c e33663c5a819e2c8532eedcefb1ea1ad7c1f0c9ac42e2149f632a642c2f9e621
 F src/os_win.c 6ff43bac175bd9ed79e7c0f96840b139f2f51d01689a638fd05128becf94908a
 F src/os_win.h 7b073010f1451abe501be30d12f6bc599824944a
-F src/pager.c bfcfab4b210c602f77b601b07b6c4627e994e97218cb905ff73ab0231efd078f
-F src/pager.h dd6ade22dd303a8ca6c34f1ff0f299add7191c1bff65f0289b7fd7c3460f9551
+F src/pager.c aae9cdf124548f2867608d481acc854b9b58e769c53b574350ae4ba5dde190f8
+F src/pager.h 60eded76163c6a09d2b73cc40de117012d62f6d1222614c9261d07a73e20ac2e
 F src/parse.y 8388b36e6cd15ebc5c1796cb72dd0a67a04abc446f52838ab3a2e8591487b2f1
 F src/pcache.c 588cc3c5ccaaadde689ed35ce5c5c891a1f7b1f4d1f56f6cf0143b74d8ee6484
 F src/pcache.h 1497ce1b823cf00094bb0cf3bac37b345937e6f910890c626b16512316d3abf5
@@ -845,11 +845,11 @@ F src/upsert.c 215328c3f91623c520ec8672c44323553f12caeb4f01b1090ebdca99fdf7b4f1
 F src/utf.c f23165685a67b4caf8ec08fb274cb3f319103decfb2a980b7cfd55d18dfa855e
 F src/util.c 5d1a0134cf4240648d1c6bb5cc8efaca0ea2b5d5c840985aec7e947271f04375
 F src/vacuum.c 25e407a6dc8b288fa4295b3d92fa9ce9318503e84df53cdf403a50fccbc1ba31
-F src/vdbe.c 0f7c0fd2e821ef63a6cfaace9b46b053f99c96d9f03f1b497fe596d2ac7516e6
-F src/vdbe.h c2549a215898a390de6669cfa32adba56f0d7e17ba5a7f7b14506d6fd5f0c36a
-F src/vdbeInt.h 949669dfd8a41550d27dcb905b494f2ccde9a2e6c1b0b04daa1227e2e74c2b2c
+F src/vdbe.c fea60cfe46d8839a08e4680d90a96898d542d3f6d7954e2e99cd92596f1a01f8
+F src/vdbe.h 7d6a7fefce6068d78e350367ee16eeaf72632163623044623d35fce88e12be66
+F src/vdbeInt.h 494b7b3430fb53adef43e5fd9ede20029750f188f2dbb064e7b86cdf9fb755d7
 F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
-F src/vdbeaux.c 994c81eaed3b8305613ba707170ab55a9026ca0cfb8191989edc11ece6373519
+F src/vdbeaux.c 606cadbcc312419ef3dc062c8aca2a350f0b89fd75e372534dba44d07503b007
 F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797
 F src/vdbemem.c 831a244831eaa45335f9ae276b50a7a82ee10d8c46c2c72492d4eb8c98d94d89
 F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f
@@ -857,8 +857,8 @@ F src/vdbetrace.c fe0bc29ebd4e02c8bc5c1945f1d2e6be5927ec12c06d89b03ef2a4def34bf8
 F src/vdbevtab.c fc46b9cbd759dc013f0b3724549cc0d71379183c667df3a5988f7e2f1bd485f3
 F src/vtab.c 5fb499d20494b7eecaadb7584634af9afcb374cb0524912b475fcb1712458a1b
 F src/vxworks.h d2988f4e5a61a4dfe82c6524dd3d6e4f2ce3cdb9
-F src/wal.c eb62325a874ff07aceb83fea2db85d36a49d472073b0df5a25782dafbfb7492c
-F src/wal.h 8d02ab8c2a93a941f5898eb3345bf711c1d3f8f86f4be8d5428fb6c074962d8a
+F src/wal.c c1109f1e9c86fa84b65ca6e38f8db7507985993e24d43224421212f5d817a953
+F src/wal.h 8c59ee7a835574396d7cbd04626d11fd849613e361a46e7e9519091ab03bdb29
 F src/walker.c d5006d6b005e4ea7302ad390957a8d41ed83faa177e412f89bc5600a7462a014
 F src/where.c c046dd58c3410f7b7528e1e6317cb876398557bad346d568ed8562321a7d002d
 F src/whereInt.h a5d079c346a658b7a6e9e47bb943d021e02fa1e6aed3b964ca112112a4892192
@@ -2249,8 +2249,11 @@ F vsixtest/vsixtest.tcl 6195aba1f12a5e10efc2b8c0009532167be5e301abe5b31385638080
 F vsixtest/vsixtest.vcxproj.data 2ed517e100c66dc455b492e1a33350c1b20fbcdc
 F vsixtest/vsixtest.vcxproj.filters 37e51ffedcdb064aad6ff33b6148725226cd608e
 F vsixtest/vsixtest_TemporaryKey.pfx e5b1b036facdb453873e7084e1cae9102ccc67a0
-P ff94464cec871bd90634e7e1e4252954eb68e77037dd290b0fbf7747c9b19308 9f530343717a891d57013c5fb58f30e422da391815a7cc79ed8beb1196c89faa
-R a1ecfb325245852a018dcbc57997f57a
-U drh
-Z b7ad2ce93a9728b7a6f18d7ba0fe6b4e
+P cf8f155280100c1a5b79b118875a93686a554d8be55114277f4f7b20cfd7835a
+R 61734104557d860aec28424b091f8914
+T *branch * cf8f1552-commit-instr
+T *sym-cf8f1552-commit-instr *
+T -sym-bedrock *
+U dan
+Z fd413eb71e4f18403b5529b00f31e3cd
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index eca469b99f6e21843214ebacedfa478dcd5fd7a2..31ddfece803fefa60d292fafbd18be97bd2eb64c 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-cf8f155280100c1a5b79b118875a93686a554d8be55114277f4f7b20cfd7835a
+c5391f2cc913a16695efb63f7d2320fc18b8aaefdbdffa087a2e3d26b24dc218

diff --git a/src/btree.c b/src/btree.c
index b1dfe623527daba2ada6595058f478a84d8d75f6..4bf87245641d76f3737a79ab8020748cdcc266b9 100644 (file)
--- a/src/btree.c
+++ b/src/btree.c
@@ -4732,9 +4732,12 @@ int sqlite3BtreeCommitPhaseOne(Btree *p, const char *zSuperJrnl){
 #endif
     if( rc==SQLITE_OK && ISCONCURRENT && p->db->eConcurrent==CONCURRENT_OPEN ){
       rc = btreeFixUnlocked(p);
+      sqlite3CommitTimeSet(p->pBt->aCommitTime, COMMIT_TIME_AFTER_FIXUNLOCKED);
     }
     if( rc==SQLITE_OK ){
+      sqlite3PagerSetCommitTime(pBt->pPager, p->pBt->aCommitTime);
       rc = sqlite3PagerCommitPhaseOne(pBt->pPager, zSuperJrnl, 0);
+      sqlite3PagerSetCommitTime(pBt->pPager, 0);
     }
 #ifndef SQLITE_OMIT_CONCURRENT
     if( rc==SQLITE_OK ){
@@ -4839,7 +4842,9 @@ int sqlite3BtreeCommitPhaseTwo(Btree *p, int bCleanup){
     BtShared *pBt = p->pBt;
     assert( pBt->inTransaction==TRANS_WRITE );
     assert( pBt->nTransaction>0 );
+    sqlite3PagerSetCommitTime(pBt->pPager, p->pBt->aCommitTime);
     rc = sqlite3PagerCommitPhaseTwo(pBt->pPager);
+    sqlite3PagerSetCommitTime(pBt->pPager, 0);
     if( rc!=SQLITE_OK && bCleanup==0 ){
       sqlite3BtreeLeave(p);
       return rc;

diff --git a/src/btreeInt.h b/src/btreeInt.h
index 7a806638bd7702e91cb045cc5c75470ac59c8ad5..93000c21a629e68b8a5fef01a151dd85db744895 100644 (file)
--- a/src/btreeInt.h
+++ b/src/btreeInt.h
@@ -470,6 +470,8 @@ struct BtShared {
   BtreePtrmap *pMap;
 #endif
   int nPreformatSize;   /* Size of last cell written by TransferRow() */
+
+  u64 *aCommitTime;
 };
 
 /*

diff --git a/src/pager.c b/src/pager.c
index 18418875201a873cc6d94bfbaec14322f25899da..add099f2af3323f23193440199112fd1f37bb37f 100644 (file)
--- a/src/pager.c
+++ b/src/pager.c
@@ -703,6 +703,7 @@ struct Pager {
   Wal *pWal;                  /* Write-ahead log used by "journal_mode=wal" */
   char *zWal;                 /* File name for write-ahead log */
 #endif
+  u64 *aCommitTime;
 };
 
 /*
@@ -6654,6 +6655,7 @@ int sqlite3PagerCommitPhaseOne(
       assert( rc==SQLITE_OK );
       if( ALWAYS(pList) ){
         rc = pagerWalFrames(pPager, pList, pPager->dbSize, 1);
+        sqlite3CommitTimeSet(pPager->aCommitTime, COMMIT_TIME_AFTER_WALFRAMES);
       }
       sqlite3PagerUnref(pPageOne);
       if( rc==SQLITE_OK ){
@@ -6827,6 +6829,10 @@ commit_phase_one_exit:
   return rc;
 }
 
+void sqlite3PagerSetCommitTime(Pager *pPager, u64 *aCommitTime){
+  pPager->aCommitTime = aCommitTime;
+  sqlite3WalSetCommitTime(pPager->pWal, aCommitTime);
+}
 
 /*
 ** When this function is called, the database file has been completely

diff --git a/src/pager.h b/src/pager.h
index 5828c37f86ae0d4d048277cefe93961a8745eaf9..8ce3fde0535d855b058abab4339d14e6cee8e5c4 100644 (file)
--- a/src/pager.h
+++ b/src/pager.h
@@ -280,4 +280,6 @@ int sqlite3PagerWalInfo(Pager*, u32 *pnPrior, u32 *pnFrame);
 int sqlite3PagerWalSystemErrno(Pager*);
 #endif
 
+void sqlite3PagerSetCommitTime(Pager *pPager, u64 *aCommitTime);
+
 #endif /* SQLITE_PAGER_H */

diff --git a/src/vdbe.c b/src/vdbe.c
index 0247561c8b9a7e3936c2efd11e2da423eefdf5d6..a40da93b2166cd92b74d3165287a7e0db999ee26 100644 (file)
--- a/src/vdbe.c
+++ b/src/vdbe.c
@@ -3955,6 +3955,11 @@ case OP_AutoCommit: {
   assert( p->bIsReader );
 
   if( desiredAutoCommit!=db->autoCommit ){
+
+    u64 aCommit[COMMIT_TIME_N];
+    memset(aCommit, 0, sizeof(aCommit));
+    sqlite3CommitTimeSet(aCommit, COMMIT_TIME_START);
+
     if( iRollback ){
       assert( desiredAutoCommit==1 );
       sqlite3RollbackAll(db, SQLITE_ABORT_ROLLBACK);
@@ -3979,7 +3984,11 @@ case OP_AutoCommit: {
     }else{
       db->autoCommit = (u8)desiredAutoCommit;
     }
+    sqlite3CommitTimeSet(aCommit, COMMIT_TIME_BEFORE_HALT);
+    p->aCommitTime = aCommit;
     hrc = sqlite3VdbeHalt(p);
+    p->aCommitTime = 0;
+    sqlite3CommitTimeSet(aCommit, COMMIT_TIME_AFTER_HALT);
     if( (hrc & 0xFF)==SQLITE_BUSY ){
       p->pc = (int)(pOp - aOp);
       db->autoCommit = (u8)(1-desiredAutoCommit);
@@ -3995,6 +4004,8 @@ case OP_AutoCommit: {
     }else{
       rc = SQLITE_ERROR;
     }
+    sqlite3CommitTimeSet(aCommit, COMMIT_TIME_FINISH);
+    if( desiredAutoCommit ) sqlite3CommitTimeLog(aCommit);
     goto vdbe_return;
   }else{
     sqlite3VdbeError(p,

diff --git a/src/vdbe.h b/src/vdbe.h
index f40f68d24b89a90b37a371e55b963e364c9bf76f..3dcc61ebebb32919b210ebd203d50ca1798e5eca 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -425,4 +425,29 @@ void sqlite3VdbePrintOp(FILE*, int, VdbeOp*);
 int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr);
 #endif
 
+
+#define COMMIT_TIME_START 0
+#define COMMIT_TIME_BEFORE_HALT 1
+#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_BEFORE_PHASETWO 6
+#define COMMIT_TIME_AFTER_PHASETWO 7
+
+#define COMMIT_TIME_AFTER_VDBECOMMIT 8
+#define COMMIT_TIME_AFTER_HALT 9
+#define COMMIT_TIME_FINISH 10
+
+#define COMMIT_TIME_N 11
+
+/* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */
+#define COMMIT_TIME_TIMEOUT (10*1000)         /* 10ms threshold */
+
+void sqlite3CommitTimeLog(u64*);
+u64 sqlite3STimeNow();
+void sqlite3CommitTimeSet(u64*, int);
+
 #endif /* SQLITE_VDBE_H */

diff --git a/src/vdbeInt.h b/src/vdbeInt.h
index 2a23c3f2855acb271ea462b98ae01613eed1996a..2e9679a8eee58d9175a13f4087afd21f23a2f442 100644 (file)
--- a/src/vdbeInt.h
+++ b/src/vdbeInt.h
@@ -137,6 +137,8 @@ struct VdbeCursor {
   ** static element declared in the structure.  nField total array slots for
   ** aType[] and nField+1 array slots for aOffset[] */
   u32 aType[1];           /* Type values record decode.  MUST BE LAST */
+
+  u8 *aCommit;
 };
 
 /* Return true if P is a null-only cursor
@@ -514,6 +516,7 @@ struct Vdbe {
   int nScan;              /* Entries in aScan[] */
   ScanStatus *aScan;      /* Scan definitions for sqlite3_stmt_scanstatus() */
 #endif
+  u64 *aCommitTime;
 };
 
 /*

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index 4caa6debb913f8fe863186851031475e324650de..e86b3874f97cc7e9b03adbbb878ed57bb9b84ce0 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -15,6 +15,8 @@
 #include "sqliteInt.h"
 #include "vdbeInt.h"
 
+#include "btreeInt.h"
+
 /* Forward references */
 static void freeEphemeralFunction(sqlite3 *db, FuncDef *pDef);
 static void vdbeFreeOpArray(sqlite3 *, Op *, int);
@@ -3000,13 +3002,18 @@ static int vdbeCommit(sqlite3 *db, Vdbe *p){
   if( 0==sqlite3Strlen30(sqlite3BtreeGetFilename(db->aDb[0].pBt))
    || nTrans<=1
   ){
+    sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_BEFORE_PHASEONE);
     for(i=0; rc==SQLITE_OK && i<db->nDb; i++){
       Btree *pBt = db->aDb[i].pBt;
       if( pBt ){
+        pBt->pBt->aCommitTime = p->aCommitTime;
         rc = sqlite3BtreeCommitPhaseOne(pBt, 0);
+        pBt->pBt->aCommitTime = 0;
       }
     }
 
+    sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_BEFORE_PHASETWO);
+
     /* Do the commit only if all databases successfully complete phase 1.
     ** If one of the BtreeCommitPhaseOne() calls fails, this indicates an
     ** IO error while deleting or truncating a journal file. It is unlikely,
@@ -3015,9 +3022,13 @@ static int vdbeCommit(sqlite3 *db, Vdbe *p){
     for(i=0; rc==SQLITE_OK && i<db->nDb; i++){
       Btree *pBt = db->aDb[i].pBt;
       if( pBt ){
+        pBt->pBt->aCommitTime = p->aCommitTime;
         rc = sqlite3BtreeCommitPhaseTwo(pBt, 0);
+        pBt->pBt->aCommitTime = 0;
       }
     }
+
+    sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_AFTER_PHASETWO);
     if( rc==SQLITE_OK ){
       sqlite3VtabCommit(db);
     }
@@ -3414,7 +3425,9 @@ int sqlite3VdbeHalt(Vdbe *p){
           ** or hit an 'OR FAIL' constraint and there are no deferred foreign
           ** key constraints to hold up the transaction. This means a commit
           ** is required. */
+          sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_BEFORE_VDBECOMMIT);
           rc = vdbeCommit(db, p);
+          sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_AFTER_VDBECOMMIT);
         }
         if( (rc & 0xFF)==SQLITE_BUSY && p->readOnly ){
           sqlite3VdbeLeave(p);
@@ -5446,6 +5459,34 @@ int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr){
 }
 #endif /* SQLITE_ENABLE_CURSOR_HINTS && SQLITE_DEBUG */
 
+#include <sys/time.h>
+void sqlite3CommitTimeLog(u64 *aCommit){
+  u64 i1 = aCommit[COMMIT_TIME_START];
+  assert( COMMIT_TIME_START==0 && COMMIT_TIME_FINISH==COMMIT_TIME_N-1 );
+  if( aCommit[COMMIT_TIME_FINISH]>(i1+COMMIT_TIME_TIMEOUT) ){
+    char *zStr = 0;
+    int ii;
+    for(ii=1; ii<COMMIT_TIME_N; ii++){
+      zStr = sqlite3_mprintf("%z%s%d", zStr, (zStr?", ":""), 
+        (aCommit[ii]==0 ? 0 : (int)(aCommit[ii] - i1))
+      );
+    }
+    sqlite3_log(SQLITE_WARNING, "slow commit (v=1): (%s)", zStr);
+    sqlite3_free(zStr);
+  }
+}
+u64 sqlite3STimeNow(){
+  struct timeval time;
+  gettimeofday(&time, 0);
+  return ((u64)time.tv_sec * 1000000 + (u64)time.tv_usec);
+}
+void sqlite3CommitTimeSet(u64 *aCommit, int iCommit){
+  if( aCommit ){
+    aCommit[iCommit] = sqlite3STimeNow();
+  }
+}
+
+
 #ifndef SQLITE_OMIT_VIRTUALTABLE
 /*
 ** Transfer error message text from an sqlite3_vtab.zErrMsg (text stored

diff --git a/src/wal.c b/src/wal.c
index cf1b895cacf4f8030df8a4dc6e5002aba8e0d757..09f5d22635b3e4fa7ccadb79c54c20d66c25daa1 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -810,6 +810,7 @@ struct Wal {
 #ifdef SQLITE_ENABLE_SETLK_TIMEOUT
   sqlite3 *db;
 #endif
+  u64 *aCommitTime;
 };
 
 /*
@@ -5822,4 +5823,10 @@ int sqlite3WalJournalMode(Wal *pWal){
   return (isWalMode2(pWal) ? PAGER_JOURNALMODE_WAL2 : PAGER_JOURNALMODE_WAL);
 }
 
+void sqlite3WalSetCommitTime(Wal *pWal, u64 *aCommitTime){
+  if( pWal ){
+    pWal->aCommitTime = aCommitTime;
+  }
+}
+
 #endif /* #ifndef SQLITE_OMIT_WAL */

diff --git a/src/wal.h b/src/wal.h
index cfe3dc2f6966ff25c2628c22d0c567ccf3f53fd0..6202ab5a9b31d08c2e6f69847c0d1fcc0cc9f92a 100644 (file)
--- a/src/wal.h
+++ b/src/wal.h
@@ -175,5 +175,7 @@ int sqlite3WalInfo(Wal *pWal, u32 *pnPrior, u32 *pnFrame);
 /* sqlite3_wal_info() data */
 int sqlite3WalInfo(Wal *pWal, u32 *pnPrior, u32 *pnFrame);
 
+void sqlite3WalSetCommitTime(Wal *pWal, u64 *aCommitTime);
+
 #endif /* ifndef SQLITE_OMIT_WAL */
 #endif /* SQLITE_WAL_H */