From: drh Date: Wed, 5 Jan 2011 12:50:18 +0000 (+0000) Subject: Add detailed error logging to WAL in an effort to track down an obscure X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=d7cb68caa275c389777c0bee39fbead42817f7ac;p=thirdparty%2Fsqlite.git 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 --- diff --git a/manifest b/manifest index c7260b994d..207aa11dad 100644 --- a/manifest +++ b/manifest @@ -1,8 +1,8 @@ -----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 -C Add\sthe\ssqlite3_vsnprintf()\sinterface. -D 2011-01-05T12:20:09 +C Add\sdetailed\serror\slogging\sto\sWAL\sin\san\seffort\sto\strack\sdown\san\sobscure\nSQLITE_PROTOCOL\sproblem.\s\sThis\scode\sis\sintended\sfor\sdebugging\sand\snot\nfor\srelease. +D 2011-01-05T12:50:18 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 2db71704aad93c8af510b9d03db7ff83cb72d262 F src/wal.h c1aac6593a0b02b15dc625987e619edeab39292e F src/walker.c 3112bb3afe1d85dc52317cb1d752055e9a781f8f F src/where.c af069e6b53234118014dabfece96a9515b69d76b @@ -898,14 +898,18 @@ F tool/speedtest2.tcl ee2149167303ba8e95af97873c575c3e0fab58ff F tool/speedtest8.c 2902c46588c40b55661e471d7a86e4dd71a18224 F tool/speedtest8inst1.c 293327bc76823f473684d589a8160bde1f52c14e F tool/vdbe-compress.tcl d70ea6d8a19e3571d7ab8c9b75cba86d1173ff0f -P 73128d4ef5d7703bf7af0553c307b55dc1b783f6 -R 22f3c024ddce8fb34edcc7b2ba2f47cc +P fc67adea414320e0c0b24054f76070cfaeebb401 +R 9a70d0db3cd018c7ffadd937acab66a6 +T *bgcolor * #8eb2a1 +T *branch * wal-trace-375 +T *sym-wal-trace-375 * +T -sym-trunk * U drh -Z 7a7101ec3b07503edbe1e87dcccedd8b +Z deca480426022b743682a4741edf3ac7 -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.6 (GNU/Linux) -iD8DBQFNJGH9oxKgR168RlERApc5AJ0YgtPklZ+P441lEcNlotS284XXhwCdF7KS -vpLjG17hnHrqRDNqDYunPRg= -=hyLY +iD8DBQFNJGkNoxKgR168RlERAlszAJ4xSpT0v27OigWR5jRHbwMOdSMMawCgh9Ef +iJiFD8SkEPDoPW+dVg/AXgU= +=RGug -----END PGP SIGNATURE----- diff --git a/manifest.uuid b/manifest.uuid index adfaf67b0f..fbb877e17d 100644 --- a/manifest.uuid +++ b/manifest.uuid @@ -1 +1 @@ -fc67adea414320e0c0b24054f76070cfaeebb401 \ No newline at end of file +2c2afdd0adad7d364915ac200c71603deddf148e \ No newline at end of file diff --git a/src/wal.c b/src/wal.c index ff327bf6bb..a2e2a39ba4 100644 --- a/src/wal.c +++ b/src/wal.c @@ -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 @@ -1953,6 +1974,7 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){ /* Take steps to avoid spinning forever if there is a protocol error. */ if( cnt>5 ){ + walTrace("cnt=%d",cnt); if( cnt>100 ) return SQLITE_PROTOCOL; sqlite3OsSleep(pWal->pVfs, 1); } @@ -2011,12 +2033,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; } } @@ -2046,8 +2070,10 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){ pInfo->aReadMark[1] = pWal->hdr.mxFrame; walUnlockExclusive(pWal, WAL_READ_LOCK(1), 1); rc = WAL_RETRY; + walTrace("aReadMark[1] <- %d", pWal->hdr.mxFrame); }else if( rc==SQLITE_BUSY ){ rc = WAL_RETRY; + walTrace("aReadMark[1] is busy"); } return rc; }else{ @@ -2060,6 +2086,7 @@ 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; } } @@ -2067,6 +2094,7 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){ 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