Add WALTRACE() macros to help with debugging and analysis.

FossilOrigin-Name: 765c33181a7b9d99b452ce750d69f217b3c81a5d

manifest

@@ -1,5 +1,8 @@
-C Another\sminor\sfix\sto\scheckpoint\son\sthe\sWAL\sbranch.
+-----BEGIN PGP SIGNED MESSAGE-----
-D 2010-05-31T12:02:31
+Hash: SHA1
+
+C Add\sWALTRACE()\smacros\sto\shelp\swith\sdebugging\sand\sanalysis.
+D 2010-05-31T12:15:19
 F Makefile.arm-wince-mingw32ce-gcc fcd5e9cd67fe88836360bb4f9ef4cb7f8e2fb5a0
 F Makefile.in a5cad1f8f3e021356bfcc6c77dc16f6f1952bbc3
 F Makefile.linux-gcc d53183f4aa6a9192d249731c90dbdffbd2c68654
@@ -175,7 +178,7 @@ F src/sqliteLimit.h 196e2f83c3b444c4548fc1874f52f84fdbda40f3
 F src/status.c 4df6fe7dce2d256130b905847c6c60055882bdbe
 F src/table.c 2cd62736f845d82200acfa1287e33feb3c15d62e
 F src/tclsqlite.c 6bc5fbde634b9cb42b3d29d674fa6cd0c22c0881
-F src/test1.c 7e82b944b123360f6637e0c76699713619fb0742
+F src/test1.c c6f5faf649bea873685c27f6030c5ab6b2ec782a
 F src/test2.c 31f1b9d076b4774a22d2605d0af1f34e14a9a7bd
 F src/test3.c 4c21700c73a890a47fc685c1097bfb661346ac94
 F src/test4.c ad03bb987ddedce928f4258c1e7fa4109a73497d
@@ -224,7 +227,7 @@ F src/vdbeblob.c 5327132a42a91e8b7acfb60b9d2c3b1c5c863e0e
 F src/vdbemem.c 2a82f455f6ca6f78b59fb312f96054c04ae0ead1
 F src/vdbetrace.c 864cef96919323482ebd9986f2132435115e9cc2
 F src/vtab.c a0f8a40274e4261696ef57aa806de2776ab72cda
-F src/wal.c ae5ff8e4dacef83bdb3ef724aed521b0b7099009
+F src/wal.c 880542c13b78c8c3480a1ca85c4893e01164392d
 F src/wal.h 1c1c9feb629b7f4afcbe0b47f80f47c5551d3a02
 F src/walker.c 3112bb3afe1d85dc52317cb1d752055e9a781f8f
 F src/where.c 75fee9e255b62f773fcadd1d1f25b6f63ac7a356
@@ -815,7 +818,14 @@ F tool/speedtest2.tcl ee2149167303ba8e95af97873c575c3e0fab58ff
 F tool/speedtest8.c 2902c46588c40b55661e471d7a86e4dd71a18224
 F tool/speedtest8inst1.c 293327bc76823f473684d589a8160bde1f52c14e
 F tool/vdbe-compress.tcl d70ea6d8a19e3571d7ab8c9b75cba86d1173ff0f
-P b499dbc88a67b4200b5f527be88be4ac90f7043f
+P 853f1e3f7720af2723b552bdf086bb106e6e93fe
-R 8b2822c04a077192242cb1cc9fb013c5
+R 120f65861720c5d4229e92e8bd223686
-U dan
+U drh
-Z ea3b19fcc0f2d8c43d059369744c24bb
+Z 5164efe54d9bd042fe1bad6aa9fe9dc9
+-----BEGIN PGP SIGNATURE-----
+Version: GnuPG v1.4.6 (GNU/Linux)
+
+iD8DBQFMA6haoxKgR168RlERAtHPAJ413tpB3ORA2MgPN4oQbrLuYBHg0wCfaWeG
+n630VhFDz8zIhJw1pFxWTdU=
+=JKTG
+-----END PGP SIGNATURE-----

manifest.uuid

@@ -1 +1 @@
-853f1e3f7720af2723b552bdf086bb106e6e93fe
+765c33181a7b9d99b452ce750d69f217b3c81a5d

src/test1.c

@@ -5136,6 +5136,7 @@ int Sqlitetest1_Init(Tcl_Interp *interp){
   extern int sqlite3WhereTrace;
   extern int sqlite3OSTrace;
   extern int sqlite3VdbeAddopTrace;
+  extern int sqlite3WalTrace;
 #endif
 #ifdef SQLITE_TEST
   extern char sqlite3_query_plan[];
@@ -5203,6 +5204,8 @@ int Sqlitetest1_Init(Tcl_Interp *interp){
       (char*)&sqlite3WhereTrace, TCL_LINK_INT);
   Tcl_LinkVar(interp, "sqlite_os_trace",
       (char*)&sqlite3OSTrace, TCL_LINK_INT);
+  Tcl_LinkVar(interp, "sqlite_wal_trace",
+      (char*)&sqlite3WalTrace, TCL_LINK_INT);
 #endif
 #ifndef SQLITE_OMIT_DISKIO
   Tcl_LinkVar(interp, "sqlite_opentemp_count",

src/wal.c

@@ -223,6 +223,19 @@
 
 #include "wal.h"
 
+/*
+** Trace output macros
+*/
+#if defined(SQLITE_TEST) || defined(SQLITE_DEBUG)
+int sqlite3WalTrace = 0;
+#endif
+#if defined(SQLITE_TEST) && defined(SQLITE_DEBUG)
+# define WALTRACE(X)  if(sqlite3WalTrace) sqlite3DebugPrintf X
+#else
+# define WALTRACE(X)
+#endif
+
+
 /*
 ** Indices of various locking bytes.   WAL_NREADER is the number
 ** of available reader locks and should be at least 3.
@@ -580,30 +593,62 @@ static int walDecodeFrame(
 #define HASHTABLE_NSLOT      (HASHTABLE_NPAGE*2)  /* Must be a power of 2 */
 #define HASHTABLE_NBYTE      (sizeof(HASHTABLE_DATATYPE)*HASHTABLE_NSLOT)
 
+#if defined(SQLITE_TEST) && defined(SQLITE_DEBUG)
+/*
+** Names of locks.
+*/
+static const char *walLockName(int lockIdx){
+  if( lockIdx==WAL_WRITE_LOCK ){
+    return "WRITE-LOCK";
+  }else if( lockIdx==WAL_CKPT_LOCK ){
+    return "CKPT-LOCK";
+  }else if( lockIdx==WAL_RECOVER_LOCK ){
+    return "RECOVER-LOCK";
+  }else{
+    static char zName[15];
+    sqlite3_snprintf(sizeof(zName), zName, "READ-LOCK[%d]",
+                     lockIdx-WAL_READ_LOCK(0));
+    return zName;
+  }
+}
+#endif /*defined(SQLITE_TEST) || defined(SQLITE_DEBUG) */
+    
+
 /*
 ** Set or release locks.
 **
 ** In locking_mode=EXCLUSIVE, all of these routines become no-ops.
 */
 static int walLockShared(Wal *pWal, int lockIdx){
+  int rc;
   if( pWal->exclusiveMode ) return SQLITE_OK;
-  return sqlite3OsShmLock(pWal->pDbFd, lockIdx, 1,
+  rc = sqlite3OsShmLock(pWal->pDbFd, lockIdx, 1,
-                          SQLITE_SHM_LOCK | SQLITE_SHM_SHARED);
+                        SQLITE_SHM_LOCK | SQLITE_SHM_SHARED);
+  WALTRACE(("WAL%p: acquire SHARED-%s %s\n", pWal,
+            walLockName(lockIdx), rc ? "failed" : "ok"));
+  return rc;
 }
 static void walUnlockShared(Wal *pWal, int lockIdx){
   if( pWal->exclusiveMode ) return;
   (void)sqlite3OsShmLock(pWal->pDbFd, lockIdx, 1,
                          SQLITE_SHM_UNLOCK | SQLITE_SHM_SHARED);
+  WALTRACE(("WAL%p: release SHARED-%s\n", pWal, walLockName(lockIdx)));
 }
 static int walLockExclusive(Wal *pWal, int lockIdx, int n){
+  int rc;
   if( pWal->exclusiveMode ) return SQLITE_OK;
-  return sqlite3OsShmLock(pWal->pDbFd, lockIdx, n,
+  rc = sqlite3OsShmLock(pWal->pDbFd, lockIdx, n,
-                          SQLITE_SHM_LOCK | SQLITE_SHM_EXCLUSIVE);
+                        SQLITE_SHM_LOCK | SQLITE_SHM_EXCLUSIVE);
+  WALTRACE(("WAL%p: acquire EXCLUSIVE-%s cnt=%d %s\n", pWal,
+            walLockName(lockIdx), n, rc ? "failed" : "ok"));
+  return rc;
 }
 static void walUnlockExclusive(Wal *pWal, int lockIdx, int n){
   if( pWal->exclusiveMode ) return;
   (void)sqlite3OsShmLock(pWal->pDbFd, lockIdx, n,
                          SQLITE_SHM_UNLOCK | SQLITE_SHM_EXCLUSIVE);
+  WALTRACE(("WAL%p: release EXCLUSIVE-%s cnt=%d\n", pWal,
+             walLockName(lockIdx), n));
 }
 
 /*
@@ -913,6 +958,7 @@ static int walIndexRecover(Wal *pWal){
   if( rc ){
     return rc;
   }
+  WALTRACE(("WAL%p: recovery begin...\n", pWal));
 
   memset(&pWal->hdr, 0, sizeof(WalIndexHdr));
 
@@ -1007,6 +1053,7 @@ finished:
   }
 
 recovery_error:
+  WALTRACE(("WAL%p: recovery %s\n", pWal, rc ? "failed" : "ok"));
   walUnlockExclusive(pWal, WAL_ALL_BUT_WRITE, SQLITE_SHM_NLOCK-1);
   return rc;
 }
@@ -1095,6 +1142,7 @@ int sqlite3WalOpen(
     sqlite3_free(pRet);
   }else{
     *ppWal = pRet;
+    WALTRACE(("WAL%d: opened\n", pRet));
   }
   return rc;
 }
@@ -1439,6 +1487,7 @@ int sqlite3WalClose(
     if( isDelete ){
       sqlite3OsDelete(pWal->pVfs, pWal->zWalName, 0);
     }
+    WALTRACE(("WAL%p: closed\n", pWal));
     sqlite3_free(pWal);
   }
   return rc;
@@ -2092,6 +2141,13 @@ int sqlite3WalFrames(
   assert( pWal->writeLock );
   assert( pWal->pWiData==0 );
 
+#if defined(SQLITE_TEST) && defined(SQLITE_DEBUG)
+  { int cnt; for(cnt=0, p=pList; p; p=p->pDirty, cnt++){}
+    WALTRACE(("WAL%p: frame write begin. %d frames. mxFrame=%d. %s\n",
+              pWal, cnt, pWal->hdr.mxFrame, isCommit ? "Commit" : "Spill"));
+  }
+#endif
+
   /* If this is the first frame written into the log, write the WAL
   ** header to the start of the WAL file. See comments at the top of
   ** this source file for a description of the WAL header format.
@@ -2107,6 +2163,7 @@ int sqlite3WalFrames(
     sqlite3Put4byte(&aWalHdr[12], pWal->nCkpt);
     memcpy(&aWalHdr[16], pWal->hdr.aSalt, 8);
     rc = sqlite3OsWrite(pWal->pWalFd, aWalHdr, sizeof(aWalHdr), 0);
+    WALTRACE(("WAL%p: wal-header write %s\n", pWal, rc ? "failed" : "ok"));
     if( rc!=SQLITE_OK ){
       return rc;
     }
@@ -2198,6 +2255,7 @@ int sqlite3WalFrames(
   }
 
   walIndexUnmap(pWal);
+  WALTRACE(("WAL%p: frame write %s\n", pWal, rc ? "failed" : "ok"));
   return rc;
 }
 
@@ -2220,6 +2278,7 @@ int sqlite3WalCheckpoint(
   assert( pWal->pWiData==0 );
   assert( pWal->ckptLock==0 );
 
+  WALTRACE(("WAL%p: checkpoint begins\n", pWal));
   rc = walLockExclusive(pWal, WAL_CKPT_LOCK, 1);
   if( rc ){
     /* Usually this is SQLITE_BUSY meaning that another thread or process
@@ -2248,6 +2307,7 @@ int sqlite3WalCheckpoint(
   walIndexUnmap(pWal);
   walUnlockExclusive(pWal, WAL_CKPT_LOCK, 1);
   pWal->ckptLock = 0;
+  WALTRACE(("WAL%p: checkpoint %s\n", pWal, rc ? "failed" : "ok"));
   return rc;
 }