Temporarily add extra sqlite3_log() calls to this version to help with debugging...

FossilOrigin-Name: 613c1ceaf4d552dc29aff090825941eaae6baed1

diff --git a/manifest b/manifest
index 311bdc5bea49c0655b14d18e568ff71979c7cf65..95dfbf5fe2cff3f9d74cd6f2d18416167cf90fba 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Experimental\spatch\srestore\sthe\sslight\sbias\sin\sbtree-balancing\simmediately\nafter\sthe\schange\sto\sreduces\sthe\samount\sof\smemcpy()\swork\sdone\sby\sbalancing.
-D 2016-07-14T20:19:24.187
+C Temporarily\sadd\sextra\ssqlite3_log()\scalls\sto\sthis\sversion\sto\shelp\swith\sdebugging\sa\sperformance\sproblem.
+D 2016-07-16T11:47:45.840
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in cf57f673d77606ab0f2d9627ca52a9ba1464146a
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -299,7 +299,7 @@ F src/vdbemem.c 31d8eabb0cd78bfeab4e5124c7363c3e9e54db9f
 F src/vdbesort.c 975aeffa99acb0991b2f288d30294756bff41438
 F src/vdbetrace.c 7e4222955e07dd707a2f360c0eb73452be1cb010
 F src/vtab.c cb0c194303fea276b48d7d4b6d970b5a96bde8de
-F src/wal.c 10e7de7ce90865a68153f001a61f1d985cd17983
+F src/wal.c e77da6efffa373cd20d248be9e86c54c634bc4fe
 F src/wal.h df01efe09c5cb8c8e391ff1715cca294f89668a4
 F src/walker.c c253b95b4ee44b21c406e2a1052636c31ea27804
 F src/where.c 4ce8c4826b7f86d080f0ed4e7a9045bb5014be77
@@ -1207,10 +1207,10 @@ F tool/vdbe_profile.tcl 67746953071a9f8f2f668b73fe899074e2c6d8c1
 F tool/warnings-clang.sh f6aa929dc20ef1f856af04a730772f59283631d4
 F tool/warnings.sh 0abfd78ceb09b7f7c27c688c8e3fe93268a13b32
 F tool/win/sqlite.vsix deb315d026cc8400325c5863eef847784a219a2f
-P face33bea1ba3a6d57780655fa827226b4d2baa9
-R 554fefe0a719f26931bb9cdfcdd471c4
-T *branch * btree-balance-bias
-T *sym-btree-balance-bias *
-T -sym-trunk *
-U drh
-Z 0e91eabd67698f71b8b9d1b306b232d2
+P 46bd9533c0b4656e9fb10eb41c9369ba8a113746
+R bce5e212270955da4d92cb60e4c49b45
+T *branch * debug
+T *sym-debug *
+T -sym-btree-balance-bias *
+U dan
+Z 9b01bf4c5271e3c2cb45a6e077ca93cf

diff --git a/manifest.uuid b/manifest.uuid
index 310b53c8ec1283ae8cfc494069ff75276703b639..0ffa9d4c07aaf4b7373647692b758bfa20012a45 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-46bd9533c0b4656e9fb10eb41c9369ba8a113746
\ No newline at end of file
+613c1ceaf4d552dc29aff090825941eaae6baed1
\ No newline at end of file

diff --git a/src/wal.c b/src/wal.c
index c0861d5be77552d55eb7988b650d20012da2493c..d49b0a3c571904ccc4941c984dfb4fec893b3525 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -1718,6 +1718,14 @@ static int walCheckpoint(
     i64 nSize;                    /* Current size of database file */
     u32 nBackfill = pInfo->nBackfill;
 
+    /* ELATDPP: Extra logging added to debug performance problem */
+    sqlite3_log(SQLITE_NOTICE, 
+        "wal: checkpoint salt1=%08x salt2=%08x "
+        "nBackfill=%d mxSafeFrame=%d mxFrame=%d",
+        pWal->hdr.aSalt[0], pWal->hdr.aSalt[1],
+        (int)nBackfill, (int)mxSafeFrame, (int)pWal->hdr.mxFrame
+    );
+
     /* Sync the WAL to disk */
     if( sync_flags ){
       rc = sqlite3OsSync(pWal->pWalFd, sync_flags);
@@ -2817,6 +2825,12 @@ int sqlite3WalFrames(
     iOffset += szFrame;
   }
 
+  /* ELATDPP: Extra logging added to debug performance problem */
+  sqlite3_log(SQLITE_NOTICE, "wal: write nFrame=%d iFrame=%d", 
+      iFrame - pWal->hdr.mxFrame, 
+      pWal->hdr.mxFrame+1
+  );
+
   /* If this is the end of a transaction, then we might need to pad
   ** the transaction and/or sync the WAL file.
   **
@@ -2921,6 +2935,10 @@ int sqlite3WalCheckpoint(
   int isChanged = 0;              /* True if a new wal-index header is loaded */
   int eMode2 = eMode;             /* Mode to pass to walCheckpoint() */
 
+  /* ELATDPP: Extra logging added to debug performance problem */
+  sqlite3_int64 t1, t2;
+  sqlite3OsCurrentTimeInt64(pWal->pVfs, &t1);
+
   assert( pWal->ckptLock==0 );
   assert( pWal->writeLock==0 );
 
@@ -2991,6 +3009,11 @@ int sqlite3WalCheckpoint(
   sqlite3WalEndWriteTransaction(pWal);
   walUnlockExclusive(pWal, WAL_CKPT_LOCK, 1);
   pWal->ckptLock = 0;
+
+  /* ELATDPP: Extra logging added to debug performance problem */
+  sqlite3OsCurrentTimeInt64(pWal->pVfs, &t2);
+  sqlite3_log(SQLITE_NOTICE, "wal: checkpoint rc=%d ms=%lld", rc, t2-t1);
+
   WALTRACE(("WAL%p: checkpoint %s\n", pWal, rc ? "failed" : "ok"));
   return (rc==SQLITE_OK && eMode!=eMode2 ? SQLITE_BUSY : rc);
 }