/ Check-in [6549e767]
Login
SQLite training in Houston TX on 2019-11-05 (details)
Part of the 2019 Tcl Conference

Many hyperlinks are disabled.
Use anonymous login to enable hyperlinks.

Overview
Comment:Cherrypick the WAL error logging from the pre-3.7.5 line into a branch for version 3.7.2. Include the sqlite3_vsnprintf() interface. This checkin is intended for debugging and not for release.
Downloads: Tarball | ZIP archive | SQL archive
Timelines: family | ancestors | wal-trace-372
Files: files | file ages | folders
SHA1: 6549e7672bcbac0bca6cef96c4d4a42998ba3ba9
User & Date: drh 2011-01-05 13:07:19
Context
2011-01-05
13:07
Cherrypick the WAL error logging from the pre-3.7.5 line into a branch for version 3.7.2. Include the sqlite3_vsnprintf() interface. This checkin is intended for debugging and not for release. Leaf check-in: 6549e767 user: drh tags: wal-trace-372
2010-08-24
00:40
Version 3.7.2 check-in: 42537b60 user: drh tags: trunk, release, version-3.7.2
Changes
Hide Diffs Side-by-Side Diffs Ignore Whitespace Patch

install-sh became a regular file.


Changes to src/printf.c.

   930    930   }
   931    931   
   932    932   /*
   933    933   ** sqlite3_snprintf() works like snprintf() except that it ignores the
   934    934   ** current locale settings.  This is important for SQLite because we
   935    935   ** are not able to use a "," as the decimal point in place of "." as
   936    936   ** specified by some locales.
          937  +**
          938  +** Oops:  The first two arguments of sqlite3_snprintf() are backwards
          939  +** from the snprintf() standard.  Unfortunately, it is too late to change
          940  +** this without breaking compatibility, so we just have to live with the
          941  +** mistake.
          942  +**
          943  +** sqlite3_vsnprintf() is the varargs version.
   937    944   */
          945  +char *sqlite3_vsnprintf(int n, char *zBuf, const char *zFormat, va_list ap){
          946  +  StrAccum acc;
          947  +  if( n<=0 ) return zBuf;
          948  +  sqlite3StrAccumInit(&acc, zBuf, n, 0);
          949  +  acc.useMalloc = 0;
          950  +  sqlite3VXPrintf(&acc, 0, zFormat, ap);
          951  +  return sqlite3StrAccumFinish(&acc);
          952  +}
   938    953   char *sqlite3_snprintf(int n, char *zBuf, const char *zFormat, ...){
   939    954     char *z;
   940    955     va_list ap;
   941         -  StrAccum acc;
   942         -
   943         -  if( n<=0 ){
   944         -    return zBuf;
   945         -  }
   946         -  sqlite3StrAccumInit(&acc, zBuf, n, 0);
   947         -  acc.useMalloc = 0;
   948    956     va_start(ap,zFormat);
   949         -  sqlite3VXPrintf(&acc, 0, zFormat, ap);
          957  +  z = sqlite3_vsnprintf(n, zBuf, zFormat, ap);
   950    958     va_end(ap);
   951         -  z = sqlite3StrAccumFinish(&acc);
   952    959     return z;
   953    960   }
   954    961   
   955    962   /*
   956    963   ** This is the routine that actually formats the sqlite3_log() message.
   957    964   ** We house it in a separate routine from sqlite3_log() to avoid using
   958    965   ** stack space on small-stack systems when logging is disabled.

Changes to src/sqlite.h.in.

  1825   1825   **
  1826   1826   ** ^As long as the buffer size is greater than zero, sqlite3_snprintf()
  1827   1827   ** guarantees that the buffer is always zero-terminated.  ^The first
  1828   1828   ** parameter "n" is the total size of the buffer, including space for
  1829   1829   ** the zero terminator.  So the longest string that can be completely
  1830   1830   ** written will be n-1 characters.
  1831   1831   **
         1832  +** ^The sqlite3_vsnprintf() routine is a varargs version of sqlite3_snprintf().
         1833  +**
  1832   1834   ** These routines all implement some additional formatting
  1833   1835   ** options that are useful for constructing SQL statements.
  1834   1836   ** All of the usual printf() formatting options apply.  In addition, there
  1835   1837   ** is are "%q", "%Q", and "%z" options.
  1836   1838   **
  1837   1839   ** ^(The %q option works like %s in that it substitutes a null-terminated
  1838   1840   ** string from the argument list.  But %q also doubles every '\'' character.
................................................................................
  1888   1890   ** ^(The "%z" formatting option works like "%s" but with the
  1889   1891   ** addition that after the string has been read and copied into
  1890   1892   ** the result, [sqlite3_free()] is called on the input string.)^
  1891   1893   */
  1892   1894   char *sqlite3_mprintf(const char*,...);
  1893   1895   char *sqlite3_vmprintf(const char*, va_list);
  1894   1896   char *sqlite3_snprintf(int,char*,const char*, ...);
         1897  +char *sqlite3_vsnprintf(int,char*,const char*, va_list);
  1895   1898   
  1896   1899   /*
  1897   1900   ** CAPI3REF: Memory Allocation Subsystem
  1898   1901   **
  1899   1902   ** The SQLite core uses these three routines for all of its own
  1900   1903   ** internal memory allocation needs. "Core" in the previous sentence
  1901   1904   ** does not include operating-system specific VFS implementation.  The

Changes to src/wal.c.

   248    248   */
   249    249   #if defined(SQLITE_TEST) && defined(SQLITE_DEBUG)
   250    250   int sqlite3WalTrace = 0;
   251    251   # define WALTRACE(X)  if(sqlite3WalTrace) sqlite3DebugPrintf X
   252    252   #else
   253    253   # define WALTRACE(X)
   254    254   #endif
          255  +
          256  +/*
          257  +** WAL tracing logic added to search for an SQLITE_PROTOCOL error.
          258  +*/
          259  +static void walTrace(const char *zFormat, ...){
          260  +  va_list ap;
          261  +  char zMsg[100];
          262  +  va_start(ap, zFormat);
          263  +  sqlite3_vsnprintf(sizeof(zMsg), zMsg, zFormat, ap);
          264  +  va_end(ap);
          265  +#ifdef SQLITE_WAL_TRACE
          266  +  fprintf(stdout, "WALTRACE: [%s]\n", zMsg); fflush(stdout);
          267  +#endif
          268  +  sqlite3_log(99, "%s", zMsg);
          269  +}
   255    270   
   256    271   /*
   257    272   ** The maximum (and only) versions of the wal and wal-index formats
   258    273   ** that may be interpreted by this version of SQLite.
   259    274   **
   260    275   ** If a client begins recovering a WAL file and finds that (a) the checksum
   261    276   ** values in the wal-header are correct and (b) the version field is not
................................................................................
   500    515     /* Enlarge the pWal->apWiData[] array if required */
   501    516     if( pWal->nWiData<=iPage ){
   502    517       int nByte = sizeof(u32*)*(iPage+1);
   503    518       volatile u32 **apNew;
   504    519       apNew = (volatile u32 **)sqlite3_realloc((void *)pWal->apWiData, nByte);
   505    520       if( !apNew ){
   506    521         *ppPage = 0;
          522  +      walTrace("realloc(%d) in walIndexPage()", nByte);
   507    523         return SQLITE_NOMEM;
   508    524       }
   509    525       memset((void*)&apNew[pWal->nWiData], 0,
   510    526              sizeof(u32*)*(iPage+1-pWal->nWiData));
   511    527       pWal->apWiData = apNew;
   512    528       pWal->nWiData = iPage+1;
   513    529     }
   514    530   
   515    531     /* Request a pointer to the required page from the VFS */
   516    532     if( pWal->apWiData[iPage]==0 ){
   517    533       rc = sqlite3OsShmMap(pWal->pDbFd, iPage, WALINDEX_PGSZ, 
   518    534           pWal->writeLock, (void volatile **)&pWal->apWiData[iPage]
   519    535       );
          536  +    if( rc ) walTrace("xShmMap():%d in walIndexPage(iPage=%d)",rc,iPage);
   520    537     }
   521    538   
   522    539     *ppPage = pWal->apWiData[iPage];
   523    540     assert( iPage==0 || *ppPage || rc!=SQLITE_OK );
   524    541     return rc;
   525    542   }
   526    543   
................................................................................
  1791   1808   
  1792   1809     /* If the first attempt failed, it might have been due to a race
  1793   1810     ** with a writer.  So get a WRITE lock and try again.
  1794   1811     */
  1795   1812     assert( badHdr==0 || pWal->writeLock==0 );
  1796   1813     if( badHdr && SQLITE_OK==(rc = walLockExclusive(pWal, WAL_WRITE_LOCK, 1)) ){
  1797   1814       pWal->writeLock = 1;
         1815  +    walTrace("trying walIndexTryHdr w/lock");
  1798   1816       if( SQLITE_OK==(rc = walIndexPage(pWal, 0, &page0)) ){
  1799   1817         badHdr = walIndexTryHdr(pWal, pChanged);
  1800   1818         if( badHdr ){
  1801   1819           /* If the wal-index header is still malformed even while holding
  1802   1820           ** a WRITE lock, it can only mean that the header is corrupted and
  1803   1821           ** needs to be reconstructed.  So run recovery to do exactly that.
  1804   1822           */
         1823  +        walTrace("walIndexTryHdr() failed w/lock");
  1805   1824           rc = walIndexRecover(pWal);
         1825  +        if( rc ) walTrace("walIndexRecover():%d", rc);
  1806   1826           *pChanged = 1;
  1807   1827         }
  1808   1828       }
  1809   1829       pWal->writeLock = 0;
  1810   1830       walUnlockExclusive(pWal, WAL_WRITE_LOCK, 1);
  1811   1831     }
         1832  +  else if(badHdr) walTrace("walLockExcl():%d in walIndexReadHdr()", rc);
  1812   1833   
  1813   1834     /* If the header is read successfully, check the version number to make
  1814   1835     ** sure the wal-index was not constructed with some future format that
  1815   1836     ** this version of SQLite cannot understand.
  1816   1837     */
  1817   1838     if( badHdr==0 && pWal->hdr.iVersion!=WALINDEX_MAX_VERSION ){
  1818   1839       rc = SQLITE_CANTOPEN_BKPT;
................................................................................
  1884   1905     int i;                          /* Loop counter */
  1885   1906     int rc = SQLITE_OK;             /* Return code  */
  1886   1907   
  1887   1908     assert( pWal->readLock<0 );     /* Not currently locked */
  1888   1909   
  1889   1910     /* Take steps to avoid spinning forever if there is a protocol error. */
  1890   1911     if( cnt>5 ){
         1912  +    walTrace("cnt=%d",cnt);
  1891   1913       if( cnt>100 ) return SQLITE_PROTOCOL;
  1892   1914       sqlite3OsSleep(pWal->pVfs, 1);
  1893   1915     }
  1894   1916   
  1895   1917     if( !useWal ){
  1896   1918       rc = walIndexReadHdr(pWal, pChanged);
  1897   1919       if( rc==SQLITE_BUSY ){
................................................................................
  1942   1964           **
  1943   1965           ** However, if frames have been appended to the log (or if the log 
  1944   1966           ** is wrapped and written for that matter) before the READ_LOCK(0)
  1945   1967           ** is obtained, that is not necessarily true. A checkpointer may
  1946   1968           ** have started to backfill the appended frames but crashed before
  1947   1969           ** it finished. Leaving a corrupt image in the database file.
  1948   1970           */
         1971  +        walTrace("wal read/write race - writer won"); 
  1949   1972           walUnlockShared(pWal, WAL_READ_LOCK(0));
  1950   1973           return WAL_RETRY;
  1951   1974         }
  1952   1975         pWal->readLock = 0;
  1953   1976         return SQLITE_OK;
  1954   1977       }else if( rc!=SQLITE_BUSY ){
         1978  +      walTrace("walLockShared(0):%d in walTryBeginRead", rc);
  1955   1979         return rc;
  1956   1980       }
  1957   1981     }
  1958   1982   
  1959   1983     /* If we get this far, it means that the reader will want to use
  1960   1984     ** the WAL to get at content from recent commits.  The job now is
  1961   1985     ** to select one of the aReadMark[] entries that is closest to
................................................................................
  1977   2001       ** be mxFrame, then retry.
  1978   2002       */
  1979   2003       rc = walLockExclusive(pWal, WAL_READ_LOCK(1), 1);
  1980   2004       if( rc==SQLITE_OK ){
  1981   2005         pInfo->aReadMark[1] = pWal->hdr.mxFrame;
  1982   2006         walUnlockExclusive(pWal, WAL_READ_LOCK(1), 1);
  1983   2007         rc = WAL_RETRY;
         2008  +      walTrace("aReadMark[1] <- %d", pWal->hdr.mxFrame);
  1984   2009       }else if( rc==SQLITE_BUSY ){
  1985   2010         rc = WAL_RETRY;
         2011  +      walTrace("aReadMark[1] is busy");
  1986   2012       }
  1987   2013       return rc;
  1988   2014     }else{
  1989   2015       if( mxReadMark < pWal->hdr.mxFrame ){
  1990   2016         for(i=1; i<WAL_NREADER; i++){
  1991   2017           rc = walLockExclusive(pWal, WAL_READ_LOCK(i), 1);
  1992   2018           if( rc==SQLITE_OK ){
  1993   2019             mxReadMark = pInfo->aReadMark[i] = pWal->hdr.mxFrame;
  1994   2020             mxI = i;
  1995   2021             walUnlockExclusive(pWal, WAL_READ_LOCK(i), 1);
  1996   2022             break;
  1997   2023           }else if( rc!=SQLITE_BUSY ){
         2024  +          walTrace("walLockExclusive(%d):%d", i, rc);
  1998   2025             return rc;
  1999   2026           }
  2000   2027         }
  2001   2028       }
  2002   2029   
  2003   2030       rc = walLockShared(pWal, WAL_READ_LOCK(mxI));
  2004   2031       if( rc ){
         2032  +      walTrace("walLockShared(mxI=%d):%d", mxI, rc);
  2005   2033         return rc==SQLITE_BUSY ? WAL_RETRY : rc;
  2006   2034       }
  2007   2035       /* Now that the read-lock has been obtained, check that neither the
  2008   2036       ** value in the aReadMark[] array or the contents of the wal-index
  2009   2037       ** header have changed.
  2010   2038       **
  2011   2039       ** It is necessary to check that the wal-index header did not change

test/progress.test became executable.


tool/mkopts.tcl became executable.