Add logging to help analyze COMMIT performance.

FossilOrigin-Name: 72404dfc0d692bc21b3263d04c9c45dda9e61eb13dc87d2014416703bdf537de

diff --git a/manifest b/manifest
index b1ce72487810740a1820c8fd766930f27ed5eb10..d7bc6a6b161006b29dbed5997e5ead47b71edb93 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Merge\sthe\slatest\strunk\senhancements,\svia\sthe\swal2\sbranch,\sinto\sthe\sbedrock\sbranch.
-D 2024-09-30T17:57:58.613
+C Add\slogging\sto\shelp\sanalyze\sCOMMIT\sperformance.
+D 2024-10-03T21:00:36.101
 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
 F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@@ -441,7 +441,7 @@ F ext/misc/urifuncs.c f71360d14fa9e7626b563f1f781c6148109462741c5235ac63ae0f8917
 F ext/misc/uuid.c 5bb2264c1b64d163efa46509544fd7500cb8769cb7c16dd52052da8d961505cf
 F ext/misc/vfslog.c 3932ab932eeb2601dbc4447cb14d445aaa9fbe43b863ef5f014401c3420afd20
 F ext/misc/vfsstat.c a85df08654743922a19410d7b1e3111de41bb7cd07d20dd16eda4e2b808d269d
-F ext/misc/vfstrace.c ac76a4ac4d907774fd423cc2b61410c756f9d0782e27cf6032e058594accaaca w src/test_vfstrace.c
+F ext/misc/vfstrace.c ac76a4ac4d907774fd423cc2b61410c756f9d0782e27cf6032e058594accaaca
 F ext/misc/vtablog.c 1100250ce8782db37c833e3a9a5c9a3ecf1af5e15b8325572b82e6e0a138ffb5
 F ext/misc/vtshim.c 1976e6dd68dd0d64508c91a6dfab8e75f8aaf6cd
 F ext/misc/wholenumber.c 0fa0c082676b7868bf2fa918e911133f2b349bcdceabd1198bba5f65b4fc0668
@@ -620,7 +620,7 @@ F ext/wasm/SQLTester/SQLTester.run.mjs c72b7fe2072d05992f7a3d8c6a1d34e95712513ce
 F ext/wasm/SQLTester/index.html 3f8a016df0776be76605abf20e815ecaafbe055abac0e1fe5ea080e7846b760d
 F ext/wasm/SQLTester/touint8array.c 2d5ece04ec1393a6a60c4bf96385bda5e1a10ad49f3038b96460fc5e5aa7e536
 F ext/wasm/api/EXPORTED_FUNCTIONS.sqlite3-api c5eaceabb9e759aaae7d3101a4a3e542f96ab2c99d89a80ce20ec18c23115f33
-F ext/wasm/api/EXPORTED_FUNCTIONS.sqlite3-extras fe40d6d758646e38f8b15f709044951e10884214f5453d35502100179c388c13 w ext/wasm/api/EXPORTED_FUNCTIONS.sqlite3-session
+F ext/wasm/api/EXPORTED_FUNCTIONS.sqlite3-extras fe40d6d758646e38f8b15f709044951e10884214f5453d35502100179c388c13
 F ext/wasm/api/EXPORTED_FUNCTIONS.sqlite3-see fb29e62082a658f0d81102488414d422c393c4b20cc2f685b216bc566237957b
 F ext/wasm/api/EXPORTED_RUNTIME_METHODS.sqlite3-api 1ec3c73e7d66e95529c3c64ac3de2470b0e9e7fbf7a5b41261c367cf4f1b7287
 F ext/wasm/api/README.md 34fe11466f9c1d81b10a0469e1114e5f1c5a6365c73d80a1a6ca639a1a358b73
@@ -714,9 +714,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 9de68aac0f5f88e553992bd46f000670d72289ce0bc41f20164c39b8d6838022
 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
@@ -845,11 +845,11 @@ F src/upsert.c 215328c3f91623c520ec8672c44323553f12caeb4f01b1090ebdca99fdf7b4f1
 F src/utf.c 7bc550af6f3ddd5f5dc82d092c41f728acb760c92e0b47f391963b01ae52569b
 F src/util.c 5d1a0134cf4240648d1c6bb5cc8efaca0ea2b5d5c840985aec7e947271f04375
 F src/vacuum.c 25e407a6dc8b288fa4295b3d92fa9ce9318503e84df53cdf403a50fccbc1ba31
-F src/vdbe.c 0f7c0fd2e821ef63a6cfaace9b46b053f99c96d9f03f1b497fe596d2ac7516e6
-F src/vdbe.h c2549a215898a390de6669cfa32adba56f0d7e17ba5a7f7b14506d6fd5f0c36a
-F src/vdbeInt.h af7d7e8291edd0b19f2cd698e60e4d4031078f9a2f2328ac8f0b7efb134f8a1d
+F src/vdbe.c fea60cfe46d8839a08e4680d90a96898d542d3f6d7954e2e99cd92596f1a01f8
+F src/vdbe.h acae49e00b2b3c04d2e093889e766635a228e2713835f97ac20d78ff9aaddde3
+F src/vdbeInt.h 6ee567f7d9be264766f62aa331c33d702abdcaeeceea2a4e81a81c35411577ba
 F src/vdbeapi.c 53c7e26a2c0821a892b20eee2cde4656e31998212f3d515576c780dfaa45fd17
-F src/vdbeaux.c 0a6842a4c70cfa29946cfc73565ddf89f85980a54d07e01a36c886bc059c2906
+F src/vdbeaux.c a41e2ba3f1a79e0dc396b1fb9196cfbd3c101fc0d96d9bca626fb291aef66701
 F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797
 F src/vdbemem.c df568ef0187e4be2788c35174f6d9b8566ab9475f9aff2d73907ed05aa5684b2
 F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f
@@ -2250,8 +2250,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 4a3386ccb80e974538a96b830f0bb3c7802f5ef5a4f2f26d01fa0732fccae9e0 59fba0288d8fb68f9b6e4936c09ae9169bc002bfe6548354504563a674000c20
-R fa192ced6f57fe693d9e42d297c534f9
+P fd6ff55141be82ba36513ba6273a60c6d8b3c496ed7890ab47cccb05bec7f7c2
+R 56c53d98cfa11e21587144100d545a4b
+T *branch * bedrock-commit-instr
+T *sym-bedrock-commit-instr *
+T -sym-bedrock *
 U dan
-Z 83fa2b380d84dcc6771d1124ae49ce40
+Z b89e00e0a5eae92f81638e3eec35afb4
 # Remove this line to create a well-formed Fossil manifest.

diff --git a/manifest.uuid b/manifest.uuid
index 3d7215319ad836afb19e2456e869eeddbbc7dc69..fd9ef5d8c1e3f50e2ae1bae5ca817491c607fd44 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-fd6ff55141be82ba36513ba6273a60c6d8b3c496ed7890ab47cccb05bec7f7c2
+72404dfc0d692bc21b3263d04c9c45dda9e61eb13dc87d2014416703bdf537de

diff --git a/src/btree.c b/src/btree.c
index b1dfe623527daba2ada6595058f478a84d8d75f6..7f02be7caffbf25a50738d68b78ce7b927251359 100644 (file)
--- a/src/btree.c
+++ b/src/btree.c
@@ -4732,6 +4732,7 @@ 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 ){
       rc = sqlite3PagerCommitPhaseOne(pBt->pPager, zSuperJrnl, 0);

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/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..2330638feb958b20c40ca656363acfa5c31829c2 100644 (file)
--- a/src/vdbe.h
+++ b/src/vdbe.h
@@ -425,4 +425,27 @@ 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_BEFORE_PHASETWO 5
+#define COMMIT_TIME_AFTER_PHASETWO 6
+
+#define COMMIT_TIME_AFTER_VDBECOMMIT 7
+#define COMMIT_TIME_AFTER_HALT 8
+#define COMMIT_TIME_FINISH 9
+
+#define COMMIT_TIME_N 10
+
+#define COMMIT_TIME_TIMEOUT (2*1000*1000)
+/* #define COMMIT_TIME_TIMEOUT 0 */
+
+void sqlite3CommitTimeLog(u64*);
+u64 sqlite3STimeNow();
+void sqlite3CommitTimeSet(u64*, int);
+
 #endif /* SQLITE_VDBE_H */

diff --git a/src/vdbeInt.h b/src/vdbeInt.h
index b26860f3a661832622d46a643e76d1b62e3a108f..12df39dd9affee173b837c4792cc8d1843a882c3 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 08296b55a63adccea1d3e9fb1964fc2c8f02b9e5..be7f783149514ead57a1c0bbe564bdf4505060f3 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,
@@ -3018,6 +3025,8 @@ static int vdbeCommit(sqlite3 *db, Vdbe *p){
         rc = sqlite3BtreeCommitPhaseTwo(pBt, 0);
       }
     }
+
+    sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_AFTER_PHASETWO);
     if( rc==SQLITE_OK ){
       sqlite3VtabCommit(db);
     }
@@ -3414,7 +3423,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 +5457,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