Changes which attempt to address an obscure SQLITE_PROTOCOL error.

FossilOrigin-Name: 1725aa7501fa97283a397d4c7cf206f35c6e6bb5
Pull over all the latest trunk changes.
2011-02-19 14:19:17 +00:00 · 2011-01-18 17:34:39 +00:00 · 2011-01-05 12:50:18 +00:00
3 changed files with 67 additions and 29 deletions
@@ -1,8 +1,8 @@
 -----BEGIN PGP SIGNED MESSAGE-----
 Hash: SHA1

-C Do\snot\suse\smutexes\sin\sthe\spcache\simplementation\sunless\nSQLITE_ENABLE_MEMORY_MANAGMENT\sis\sdefined.\s\sThis\sis\sa\sperformance\senhancement.\nA\sside\seffect\sis\sthat\spcaches\swill\snot\ssteal\spages\sfrom\sone\sanother\sunless\nENABLE_MEMORY_MANAGEMENT\sis\sset,\sor\sunless\sSQLITE_THREADSAFE=0.
-D 2011-01-18T17:03:26.554
+C Changes\swhich\sattempt\sto\saddress\san\sobscure\sSQLITE_PROTOCOL\serror.
+D 2011-02-19T14:19:17.314
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in de6498556d536ae60bb8bb10e8c1ba011448658c
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -240,7 +240,7 @@ F src/vdbeblob.c 18955f0ee6b133cd08e1592010cb9a6b11e9984c
 F src/vdbemem.c 411649a35686f54268ccabeda175322c4697f5a6
 F src/vdbetrace.c 864cef96919323482ebd9986f2132435115e9cc2
 F src/vtab.c b297e8fa656ab5e66244ab15680d68db0adbec30
-F src/wal.c dbca424f71678f663a286ab2a98f947af1d412a7
+F src/wal.c cb338d8f80dece4189ce62b435b53528f4b2d2a7
 F src/wal.h c1aac6593a0b02b15dc625987e619edeab39292e
 F src/walker.c 3112bb3afe1d85dc52317cb1d752055e9a781f8f
 F src/where.c af069e6b53234118014dabfece96a9515b69d76b
@@ -899,14 +899,14 @@ F tool/speedtest2.tcl ee2149167303ba8e95af97873c575c3e0fab58ff
 F tool/speedtest8.c 2902c46588c40b55661e471d7a86e4dd71a18224
 F tool/speedtest8inst1.c 293327bc76823f473684d589a8160bde1f52c14e
 F tool/vdbe-compress.tcl d70ea6d8a19e3571d7ab8c9b75cba86d1173ff0f
-P 56417a3386fc84dd36bf1488e88149b1ac6a0d02 2dc98d29995bef51108e99aa8f7a56427cf9e1d7
-R ae7dd673c03c5cec18f064cfaf72f5a8
+P ca86d04be158df89f474e5b82ce3418d282074d7
+R 8b3d99323c46204fea0ea724d430cb5f
 U drh
-Z 325abbc955397207600330822401f3ff
+Z 9d0e6478a1d3388663538b3f4c4b6e71
 -----BEGIN PGP SIGNATURE-----
 Version: GnuPG v1.4.6 (GNU/Linux)

-iD8DBQFNNcfhoxKgR168RlERAkQlAJ4goobzjFc2tVGaK8jIdVviHMW2TwCfYV8B
-rrsRGD/Sjq/hNYcI1Uavg6U=
-=JG+V
+iD8DBQFNX9FooxKgR168RlERAvuxAJ48VDRP7OeedmVUn0DlNMsLqhjIzACfXrx1
+rn10uZfDJ4qrpkis/50ZxM4=
+=24hC
 -----END PGP SIGNATURE-----
@@ -1 +1 @@
-e5ca59e63b18ac45a8c82ca39dc8cce1c4ce903c
+1725aa7501fa97283a397d4c7cf206f35c6e6bb5
@@ -253,6 +253,21 @@ int sqlite3WalTrace = 0;
 # define WALTRACE(X)
 #endif

+/*
+** WAL tracing logic added to search for an SQLITE_PROTOCOL error.
+*/
+static void walTrace(const char *zFormat, ...){
+  va_list ap;
+  char zMsg[100];
+  va_start(ap, zFormat);
+  sqlite3_vsnprintf(sizeof(zMsg), zMsg, zFormat, ap);
+  va_end(ap);
+#ifdef SQLITE_WAL_TRACE
+  fprintf(stdout, "WALTRACE: [%s]\n", zMsg); fflush(stdout);
+#endif
+  sqlite3_log(99, "%s", zMsg);
+}
+
 /*
 ** The maximum (and only) versions of the wal and wal-index formats
 ** that may be interpreted by this version of SQLite.
@@ -511,6 +526,7 @@ static int walIndexPage(Wal *pWal, int iPage, volatile u32 **ppPage){
    apNew = (volatile u32 **)sqlite3_realloc((void *)pWal->apWiData, nByte);
    if( !apNew ){
      *ppPage = 0;
+      walTrace("realloc(%d) in walIndexPage()", nByte);
      return SQLITE_NOMEM;
    }
    memset((void*)&apNew[pWal->nWiData], 0,
@@ -529,6 +545,7 @@ static int walIndexPage(Wal *pWal, int iPage, volatile u32 **ppPage){
          pWal->writeLock, (void volatile **)&pWal->apWiData[iPage]
      );
    }
+    if( rc ) walTrace("xShmMap():%d in walIndexPage(iPage=%d)",rc,iPage);
  }

  *ppPage = pWal->apWiData[iPage];
@@ -1860,6 +1877,7 @@ static int walIndexReadHdr(Wal *pWal, int *pChanged){
  assert( badHdr==0 || pWal->writeLock==0 );
  if( badHdr && SQLITE_OK==(rc = walLockExclusive(pWal, WAL_WRITE_LOCK, 1)) ){
    pWal->writeLock = 1;
+    walTrace("trying walIndexTryHdr w/lock");
    if( SQLITE_OK==(rc = walIndexPage(pWal, 0, &page0)) ){
      badHdr = walIndexTryHdr(pWal, pChanged);
      if( badHdr ){
@@ -1867,13 +1885,16 @@ static int walIndexReadHdr(Wal *pWal, int *pChanged){
        ** a WRITE lock, it can only mean that the header is corrupted and
        ** needs to be reconstructed.  So run recovery to do exactly that.
        */
+        walTrace("walIndexTryHdr() failed w/lock");
        rc = walIndexRecover(pWal);
+        if( rc ) walTrace("walIndexRecover():%d", rc);
        *pChanged = 1;
      }
    }
    pWal->writeLock = 0;
    walUnlockExclusive(pWal, WAL_WRITE_LOCK, 1);
  }
+  else if(badHdr) walTrace("walLockExcl():%d in walIndexReadHdr()", rc);

  /* If the header is read successfully, check the version number to make
  ** sure the wal-index was not constructed with some future format that
@@ -1951,10 +1972,29 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){

  assert( pWal->readLock<0 );     /* Not currently locked */

-  /* Take steps to avoid spinning forever if there is a protocol error. */
+  /* Take steps to avoid spinning forever if there is a protocol error.
+  **
+  ** Circumstances that cause a RETRY should only last for the briefest
+  ** instances of time.  No I/O or other system calls are done while the
+  ** locks are held, so the locks should not be held for very long. But 
+  ** if we are unlucky, another process that is holding a lock might get
+  ** paged out or take a page-fault that is time-consuming to resolve, 
+  ** during the few nanoseconds that it is holding the lock.  In that case,
+  ** it might take longer than normal for the lock to free.
+  **
+  ** After 5 RETRYs, we begin calling sqlite3OsSleep().  The first few
+  ** calls to sqlite3OsSleep() have a delay of 1 microsecond.  Really this
+  ** is more of a scheduler yield than an actual delay.  But on the 10th
+  ** an subsequent retries, the delays start becoming longer and longer, 
+  ** so that on the 100th (and last) RETRY we delay for 21 milliseconds.
+  ** The total delay time before giving up is less than 1 second.
+  */
  if( cnt>5 ){
+    int nDelay = 1;                      /* Pause time in microseconds */
+    walTrace("cnt=%d",cnt);
    if( cnt>100 ) return SQLITE_PROTOCOL;
-    sqlite3OsSleep(pWal->pVfs, 1);
+    if( cnt>=10 ) nDelay = (cnt-9)*238;  /* Max delay 21ms. Total delay 996ms */
+    sqlite3OsSleep(pWal->pVfs, nDelay);
  }

  if( !useWal ){
@@ -2011,12 +2051,14 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){
        ** have started to backfill the appended frames but crashed before
        ** it finished. Leaving a corrupt image in the database file.
        */
+        walTrace("wal read/write race - writer won"); 
        walUnlockShared(pWal, WAL_READ_LOCK(0));
        return WAL_RETRY;
      }
      pWal->readLock = 0;
      return SQLITE_OK;
    }else if( rc!=SQLITE_BUSY ){
+      walTrace("walLockShared(0):%d in walTryBeginRead", rc);
      return rc;
    }
  }
@@ -2036,22 +2078,9 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){
      mxI = i;
    }
  }
-  if( mxI==0 ){
-    /* If we get here, it means that all of the aReadMark[] entries between
-    ** 1 and WAL_NREADER-1 are zero.  Try to initialize aReadMark[1] to
-    ** be mxFrame, then retry.
-    */
-    rc = walLockExclusive(pWal, WAL_READ_LOCK(1), 1);
-    if( rc==SQLITE_OK ){
-      pInfo->aReadMark[1] = pWal->hdr.mxFrame;
-      walUnlockExclusive(pWal, WAL_READ_LOCK(1), 1);
-      rc = WAL_RETRY;
-    }else if( rc==SQLITE_BUSY ){
-      rc = WAL_RETRY;
-    }
-    return rc;
-  }else{
-    if( mxReadMark < pWal->hdr.mxFrame ){
+  /* There was once an "if" here. The extra "{" is to preserve indentation. */
+  {
+    if( mxReadMark < pWal->hdr.mxFrame || mxI==0 ){
      for(i=1; i<WAL_NREADER; i++){
        rc = walLockExclusive(pWal, WAL_READ_LOCK(i), 1);
        if( rc==SQLITE_OK ){
@@ -2060,13 +2089,20 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){
          walUnlockExclusive(pWal, WAL_READ_LOCK(i), 1);
          break;
        }else if( rc!=SQLITE_BUSY ){
+          walTrace("walLockExclusive(%d):%d", i, rc);
          return rc;
        }
      }
    }
+    if( mxI==0 ){
+      assert( rc==SQLITE_BUSY );
+      walTrace("all readlocks busy: cannot set read mark");
+      return WAL_RETRY;
+    }

    rc = walLockShared(pWal, WAL_READ_LOCK(mxI));
    if( rc ){
+      walTrace("walLockShared(mxI=%d):%d", mxI, rc);
      return rc==SQLITE_BUSY ? WAL_RETRY : rc;
    }
    /* Now that the read-lock has been obtained, check that neither the
@@ -2441,6 +2477,8 @@ static int walRestartLog(Wal *pWal){
    volatile WalCkptInfo *pInfo = walCkptInfo(pWal);
    assert( pInfo->nBackfill==pWal->hdr.mxFrame );
    if( pInfo->nBackfill>0 ){
+      u32 salt1;
+      sqlite3_randomness(4, &salt1);
      rc = walLockExclusive(pWal, WAL_READ_LOCK(1), WAL_NREADER-1);
      if( rc==SQLITE_OK ){
        /* If all readers are using WAL_READ_LOCK(0) (in other words if no
@@ -2458,7 +2496,7 @@ static int walRestartLog(Wal *pWal){
        pWal->nCkpt++;
        pWal->hdr.mxFrame = 0;
        sqlite3Put4byte((u8*)&aSalt[0], 1 + sqlite3Get4byte((u8*)&aSalt[0]));
-        sqlite3_randomness(4, &aSalt[1]);
+        aSalt[1] = salt1;
        walIndexWriteHdr(pWal);
        pInfo->nBackfill = 0;
        for(i=1; i<WAL_NREADER; i++) pInfo->aReadMark[i] = READMARK_NOT_USED;
Author	SHA1	Message	Date
drh	def84d0b5c	Changes which attempt to address an obscure SQLITE_PROTOCOL error. FossilOrigin-Name: 1725aa7501fa97283a397d4c7cf206f35c6e6bb5	2011-02-19 14:19:17 +00:00
drh	e905eeb7c5	Pull over all the latest trunk changes. FossilOrigin-Name: ca86d04be158df89f474e5b82ce3418d282074d7	2011-01-18 17:34:39 +00:00
drh	d7cb68caa2	Add detailed error logging to WAL in an effort to track down an obscure SQLITE_PROTOCOL problem. This code is intended for debugging and not for release. FossilOrigin-Name: 2c2afdd0adad7d364915ac200c71603deddf148e	2011-01-05 12:50:18 +00:00