Add the undocumented and experimental I/O tracing interface. This

interface is likely to change and may be completely abandoned in the
near future. (CVS 3665)

FossilOrigin-Name: 007ca283892a66dd8b9e0dfece4f75d0d08a4300

manifest

@@ -1,5 +1,5 @@
-C Improvements\sto\sOS\slayer\stracing\son\sthe\sunix\sbackend.\s(CVS\s3664)
-D 2007-02-27T02:01:14
+C Add\sthe\sundocumented\sand\sexperimental\sI/O\stracing\sinterface.\s\sThis\ninterface\sis\slikely\sto\schange\sand\smay\sbe\scompletely\sabandoned\sin\sthe\nnear\sfuture.\s(CVS\s3665)
+D 2007-02-28T04:47:27
 F Makefile.in 1fe3d0b46e40fd684e1e61f8e8056cefed16de9f
 F Makefile.linux-gcc 2d8574d1ba75f129aba2019f0b959db380a90935
 F README 9c4e2d6706bdcc3efdd773ce752a8cdab4f90028
@@ -72,7 +72,7 @@ F src/hash.h 1b3f7e2609141fd571f62199fc38687d262e9564
 F src/insert.c 72cb64b698796f2005c0158e098124d9490868bb
 F src/legacy.c 2631df6a861f830d6b1c0fe92b9fdd745b2c0cd6
 F src/loadext.c bbfdbf452c71b6f2723375478a365788498ec3cd
-F src/main.c 33c32014da3a1471e8869d2eba32b2c4314c39ce
+F src/main.c af8922e0205cf618392de2836c9efad71786d0d6
 F src/md5.c c5fdfa5c2593eaee2e32a5ce6c6927c986eaf217
 F src/os.c 59f05de8c5777c34876607114a2fbe55ae578235
 F src/os.h 17fc73165cb7436aa79492d2dff754baec74fcb9
@@ -85,7 +85,7 @@ F src/os_unix.c abdb0f7b8e3f078b8b48d4c0b8c801693046774d
 F src/os_unix.h 5768d56d28240d3fe4537fac08cc85e4fb52279e
 F src/os_win.c 8736cf3a49fd651a6538857480f302807d57814c
 F src/os_win.h 41a946bea10f61c158ce8645e7646b29d44f122b
-F src/pager.c d6ad66eb119602cb2e6a097f8f635372ba677d23
+F src/pager.c e1ef884e2be3f24fb5048be36cd82d328d54102f
 F src/pager.h 2e6d42f4ae004ae748a037b8468112b851c447a7
 F src/parse.y bcfe366c1fd61cfc40e5344eb69a31997a821af0
 F src/pragma.c 5091300911670ddaa552bfa12c45cbca1bb7e7d6
@@ -94,10 +94,10 @@ F src/printf.c aade23a789d7cc88b397ec0d33a0a01a33a7a9c1
 F src/random.c 6119474a6f6917f708c1dee25b9a8e519a620e88
 F src/select.c 6a090150d6866a94f719eda57e58207105f4a26d
 F src/server.c 087b92a39d883e3fa113cae259d64e4c7438bc96
-F src/shell.c d13ca007cd18192c07a668aeddcdd6a9fe639be9
+F src/shell.c a7df003f26fac3b4024d7147d8d56e93329ee96e
 F src/sqlite.h.in 6b7383baf76070214f6381f603328ca9b22a7fae
 F src/sqlite3ext.h 011c75fd6459a61454514af07c7a4f1f5c767f27
-F src/sqliteInt.h cc9f729ca211a11a9d735b66a5f6c968a143e472
+F src/sqliteInt.h dad7a8f74ba26b7293015fd6be2823c18c02a9cb
 F src/table.c 6d0da66dde26ee75614ed8f584a1996467088d06
 F src/tclsqlite.c cd2b3b86ab07c0e0779f6c6e71e72c6c7dc1e704
 F src/test1.c b4ff8f82f84d2ccdf07a2db5acae7b47c12f60d7
@@ -434,7 +434,7 @@ F www/tclsqlite.tcl bb0d1357328a42b1993d78573e587c6dcbc964b9
 F www/vdbe.tcl 87a31ace769f20d3627a64fa1fade7fed47b90d0
 F www/version3.tcl 890248cf7b70e60c383b0e84d77d5132b3ead42b
 F www/whentouse.tcl 97e2b5cd296f7d8057e11f44427dea8a4c2db513
-P fba0a1e50820677081bc7cf01f97bf953065f7c4
-R 53e6e1175e996a66fdc28979d298605a
+P 3ad96dbe09b99bd5f623de0de3072a25e9e2bc17
+R ade257ac6814a758e96651f4bfa01c2d
 U drh
-Z 6212737d1226e74d32458bf3f5faf876
+Z 6ecb44f9119dd3f2c6ea27b1aef2521e

manifest.uuid

@@ -1 +1 @@
-3ad96dbe09b99bd5f623de0de3072a25e9e2bc17
+007ca283892a66dd8b9e0dfece4f75d0d08a4300

src/main.c

@@ -14,7 +14,7 @@
 ** other files are for internal use by SQLite and should not be
 ** accessed by users of the library.
 **
-** $Id: main.c,v 1.360 2006/12/19 18:57:11 drh Exp $
+** $Id: main.c,v 1.361 2007/02/28 04:47:27 drh Exp $
 */
 #include "sqliteInt.h"
 #include "os.h"
@@ -33,6 +33,14 @@ const char sqlite3_version[] = SQLITE_VERSION;
 const char *sqlite3_libversion(void){ return sqlite3_version; }
 int sqlite3_libversion_number(void){ return SQLITE_VERSION_NUMBER; }
 
+/*
+** If the following function pointer is not NULL and if
+** SQLITE_ENABLE_IOTRACE is enabled, then messages describing
+** I/O active are written using this function.  These messages
+** are intended for debugging activity only.
+*/
+void (*sqlite3_io_trace)(const char*, ...) = 0;
+
 /*
 ** This is the default collating function named "BINARY" which is always
 ** available.

src/pager.c

@@ -18,7 +18,7 @@
 ** file simultaneously, or one process from reading the database while
 ** another is writing.
 **
-** @(#) $Id: pager.c,v 1.282 2007/01/05 02:00:47 drh Exp $
+** @(#) $Id: pager.c,v 1.283 2007/02/28 04:47:27 drh Exp $
 */
 #ifndef SQLITE_OMIT_DISKIO
 #include "sqliteInt.h"
@@ -662,12 +662,14 @@ static int writeJournalHdr(Pager *pPager){
   put32bits(&zHeader[sizeof(aJournalMagic)+8], pPager->dbSize);
   /* The assumed sector size for this process */
   put32bits(&zHeader[sizeof(aJournalMagic)+12], pPager->sectorSize);
+  IOTRACE(("JHDR %p %lld %d\n", pPager, pPager->journalHdr, sizeof(zHeader)))
   rc = sqlite3OsWrite(pPager->jfd, zHeader, sizeof(zHeader));
 
   /* The journal header has been written successfully. Seek the journal
   ** file descriptor to the end of the journal header sector.
   */
   if( rc==SQLITE_OK ){
+    IOTRACE(("JTAIL %p %lld\n", pPager, pPager->journalOff-1))
     rc = sqlite3OsSeek(pPager->jfd, pPager->journalOff-1);
     if( rc==SQLITE_OK ){
       rc = sqlite3OsWrite(pPager->jfd, "\000", 1);
@@ -861,6 +863,7 @@ static void pager_unlock(Pager *pPager){
   if( !MEMDB ){
     sqlite3OsUnlock(pPager->fd, NO_LOCK);
     pPager->dbSize = -1;
+    IOTRACE(("UNLOCK %p\n", pPager))
   }
   pPager->state = PAGER_UNLOCK;
   assert( pPager->pAll==0 );
@@ -1688,6 +1691,7 @@ int sqlite3pager_open(
   }
 
   TRACE3("OPEN %d %s\n", FILEHANDLEID(fd), zFullPathname);
+  IOTRACE(("OPEN %p %s\n", pPager, zFullPathname))
   pPager->zFilename = (char*)&pPager[1];
   pPager->zDirectory = &pPager->zFilename[nameLen+1];
   pPager->zJournal = &pPager->zDirectory[nameLen+1];
@@ -1825,6 +1829,7 @@ int sqlite3pager_read_fileheader(Pager *pPager, int N, unsigned char *pDest){
     disable_simulated_io_errors();
     sqlite3OsSeek(pPager->fd, 0);
     enable_simulated_io_errors();
+    IOTRACE(("DBHDR %p 0 %d\n", pPager, N))
     rc = sqlite3OsRead(pPager->fd, pDest, N);
     if( rc==SQLITE_IOERR_SHORT_READ ){
       rc = SQLITE_OK;
@@ -2007,6 +2012,7 @@ static int pager_wait_on_lock(Pager *pPager, int locktype){
     }while( rc==SQLITE_BUSY && sqlite3InvokeBusyHandler(pPager->pBusyHandler) );
     if( rc==SQLITE_OK ){
       pPager->state = locktype;
+      IOTRACE(("LOCK %p %d\n", pPager, locktype))
     }
   }
   return rc;
@@ -2080,6 +2086,7 @@ int sqlite3pager_close(Pager *pPager){
   pager_reset(pPager);
   enable_simulated_io_errors();
   TRACE2("CLOSE %d\n", PAGERID(pPager));
+  IOTRACE(("CLOSE %p\n", pPager))
   assert( pPager->errCode || (pPager->journalOpen==0 && pPager->stmtOpen==0) );
   if( pPager->journalOpen ){
     sqlite3OsClose(&pPager->jfd);
@@ -2226,12 +2233,15 @@ static int syncJournal(Pager *pPager){
         */
         if( pPager->fullSync ){
           TRACE2("SYNC journal of %d\n", PAGERID(pPager));
+          IOTRACE(("JSYNC %p\n", pPager))
           rc = sqlite3OsSync(pPager->jfd, 0);
           if( rc!=0 ) return rc;
         }
         rc = sqlite3OsSeek(pPager->jfd,
                            pPager->journalHdr + sizeof(aJournalMagic));
         if( rc ) return rc;
+        IOTRACE(("JHDR %p %lld %d\n", pPager,
+                  pPager->journalHdr + sizeof(aJournalMagic), 4))
         rc = write32bits(pPager->jfd, pPager->nRec);
         if( rc ) return rc;
 
@@ -2239,6 +2249,7 @@ static int syncJournal(Pager *pPager){
         if( rc ) return rc;
       }
       TRACE2("SYNC journal of %d\n", PAGERID(pPager));
+      IOTRACE(("JSYNC %d\n", pPager))
       rc = sqlite3OsSync(pPager->jfd, pPager->full_fsync);
       if( rc!=0 ) return rc;
       pPager->journalStarted = 1;
@@ -2377,6 +2388,7 @@ static int pager_write_pagelist(PgHdr *pList){
     if( pList->pgno<=pPager->dbSize ){
       char *pData = CODEC2(pPager, PGHDR_TO_DATA(pList), pList->pgno, 6);
       TRACE3("STORE %d page %d\n", PAGERID(pPager), pList->pgno);
+      IOTRACE(("PGOUT %p %d\n", pPager, pList->pgno))
       rc = sqlite3OsWrite(pPager->fd, pData, pPager->pageSize);
       TEST_INCR(pPager->nWrite);
     }
@@ -2780,6 +2792,7 @@ int sqlite3pager_get(Pager *pPager, Pgno pgno, void **ppPage){
         rc = sqlite3OsRead(pPager->fd, PGHDR_TO_DATA(pPg),
                               pPager->pageSize);
       }
+      IOTRACE(("PGIN %p %d\n", pPager, pgno))
       TRACE3("FETCH %d page %d\n", PAGERID(pPager), pPg->pgno);
       CODEC1(pPager, PGHDR_TO_DATA(pPg), pPg->pgno, 3);
       if( rc!=SQLITE_OK && rc!=SQLITE_IOERR_SHORT_READ ){
@@ -3151,6 +3164,8 @@ int sqlite3pager_write(void *pData){
           szPg = pPager->pageSize+8;
           put32bits(pData2, pPg->pgno);
           rc = sqlite3OsWrite(pPager->jfd, pData2, szPg);
+          IOTRACE(("JOUT %p %d %lld %d\n", pPager, pPg->pgno,
+                   pPager->journalOff, szPg))
           pPager->journalOff += szPg;
           TRACE4("JOURNAL %d page %d needSync=%d\n",
                   PAGERID(pPager), pPg->pgno, pPg->needSync);
@@ -3304,6 +3319,7 @@ void sqlite3pager_dont_write(Pager *pPager, Pgno pgno){
       */
     }else{
       TRACE3("DONT_WRITE page %d of %d\n", pgno, PAGERID(pPager));
+      IOTRACE(("CLEAN %p %d\n", pPager, pgno))
       makeClean(pPg);
 #ifdef SQLITE_CHECK_PAGES
       pPg->pageHash = pager_pagehash(pPg);
@@ -3334,6 +3350,7 @@ void sqlite3pager_dont_rollback(void *pData){
       page_add_to_stmt_list(pPg);
     }
     TRACE3("DONT_ROLLBACK page %d of %d\n", pPg->pgno, PAGERID(pPager));
+    IOTRACE(("GARBAGE %p %d\n", pPager, pPg->pgno))
   }
   if( pPager->stmtInUse && !pPg->inStmt && (int)pPg->pgno<=pPager->stmtSize ){
     assert( pPg->inJournal || (int)pPg->pgno>pPager->origDbSize );
@@ -3787,6 +3804,7 @@ int sqlite3pager_sync(Pager *pPager, const char *zMaster, Pgno nTrunc){
     if( !pPager->noSync ){
       rc = sqlite3OsSync(pPager->fd, 0);
     }
+    IOTRACE(("DBSYNC %p\n", pPager))
 
     pPager->state = PAGER_SYNCED;
   }else if( MEMDB && nTrunc!=0 ){
@@ -3825,6 +3843,7 @@ int sqlite3pager_movepage(Pager *pPager, void *pData, Pgno pgno){
 
   TRACE5("MOVE %d page %d (needSync=%d) moves to %d\n", 
       PAGERID(pPager), pPg->pgno, pPg->needSync, pgno);
+  IOTRACE(("MOVE %p %d %d\n", pPager, pPg->pgno, pgno))
 
   if( pPg->needSync ){
     needSyncPgno = pPg->pgno;

src/shell.c

@@ -12,7 +12,7 @@
 ** This file contains code to implement the "sqlite" command line
 ** utility for accessing SQLite databases.
 **
-** $Id: shell.c,v 1.158 2007/01/08 14:31:36 drh Exp $
+** $Id: shell.c,v 1.159 2007/02/28 04:47:27 drh Exp $
 */
 #include <stdlib.h>
 #include <string.h>
@@ -20,6 +20,7 @@
 #include <assert.h>
 #include "sqlite3.h"
 #include <ctype.h>
+#include <stdarg.h>
 
 #if !defined(_WIN32) && !defined(WIN32) && !defined(__MACOS__) && !defined(__OS2__)
 # include <signal.h>
@@ -97,6 +98,25 @@ static char *Argv0;
 static char mainPrompt[20];     /* First line prompt. default: "sqlite> "*/
 static char continuePrompt[20]; /* Continuation prompt. default: "   ...> " */
 
+/*
+** Write I/O traces to the following stream.
+*/
+static FILE *iotrace = 0;
+
+/*
+** This routine works like printf in that its first argument is a
+** format string and subsequent arguments are values to be substituted
+** in place of % fields.  The result of formatting this string
+** is written to iotrace.
+*/
+static void iotracePrintf(const char *zFormat, ...){
+  va_list ap;
+  if( iotrace==0 ) return;
+  va_start(ap, zFormat);
+  vfprintf(iotrace, zFormat, ap);
+  va_end(ap);
+}
+
 
 /*
 ** Determines if a string is a number of not.
@@ -1219,6 +1239,26 @@ static int do_meta_command(char *zLine, struct callback_data *p){
     }
   }else
 
+  if( c=='i' && strncmp(azArg[0], "iotrace", n)==0 ){
+    extern void (*sqlite3_io_trace)(const char*, ...);
+    if( iotrace && iotrace!=stdout ) fclose(iotrace);
+    iotrace = 0;
+    if( nArg<2 ){
+      sqlite3_io_trace = 0;
+    }else if( strcmp(azArg[1], "-")==0 ){
+      sqlite3_io_trace = iotracePrintf;
+      iotrace = stdout;
+    }else{
+      iotrace = fopen(azArg[1], "w");
+      if( iotrace==0 ){
+        fprintf(stderr, "cannot open \"%s\"\n", azArg[1]);
+        sqlite3_io_trace = 0;
+      }else{
+        sqlite3_io_trace = iotracePrintf;
+      }
+    }
+  }else
+
 #ifndef SQLITE_OMIT_LOAD_EXTENSION
   if( c=='l' && strncmp(azArg[0], "load", n)==0 && nArg>=2 ){
     const char *zFile, *zProc;

src/sqliteInt.h

@@ -11,7 +11,7 @@
 *************************************************************************
 ** Internal interface definitions for SQLite.
 **
-** @(#) $Id: sqliteInt.h,v 1.538 2007/02/24 11:52:55 drh Exp $
+** @(#) $Id: sqliteInt.h,v 1.539 2007/02/28 04:47:27 drh Exp $
 */
 #ifndef _SQLITEINT_H_
 #define _SQLITEINT_H_
@@ -1897,4 +1897,16 @@ int sqlite3Reprepare(Vdbe*);
 #include "sseInt.h"
 #endif
 
+/*
+** If the SQLITE_ENABLE IOTRACE exists then the global variable
+** sqlite3_io_trace is a pointer to a printf-like routine used to
+** print I/O tracing messages. 
+*/
+#ifdef SQLITE_ENABLE_IOTRACE
+# define IOTRACE(A)  if( sqlite3_io_trace ){ sqlite3_io_trace A; }
+#else
+# define IOTRACE(A)
+#endif
+extern void (*sqlite3_io_trace)(const char*,...);
+
 #endif