Add some extra timestamps to the experimental log output.

FossilOrigin-Name: b09e3ea7b86ff65d749ff0b6c27e05fd3a5fadb1

manifest

@@ -1,5 +1,5 @@
-C Fix\scompiler\swarnings\sand\sremove\sunreachable\scode.
-D 2015-08-08T23:30:56.001
+C Add\ssome\sextra\stimestamps\sto\sthe\sexperimental\slog\soutput.
+D 2015-08-11T13:41:44.948
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in 2fc9ca6bf5949d415801c007ed3004a4bdb7c380
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -276,9 +276,9 @@ F src/auth.c b56c78ebe40a2110fd361379f7e8162d23f92240
 F src/backup.c 4d9134dc988a87838c06056c89c0e8c4700a0452
 F src/bitvec.c d1f21d7d91690747881f03940584f4cc548c9d3d
 F src/btmutex.c 45a968cc85afed9b5e6cf55bf1f42f8d18107f79
-F src/btree.c f48b3ef91676c06a90a8832987ecef6b94c931ee
-F src/btree.h 969adc948e89e449220ff0ff724c94bb2a52e9f1
-F src/btreeInt.h 8177c9ab90d772d6d2c6c517e05bed774b7c92c0
+F src/btree.c 37d3bece89a45a2e938d16f249c09519758153f6
+F src/btree.h 4c2590d2b5649b283b653053621965c3bb8020d1
+F src/btreeInt.h d28997e3b752f2b0bbe4508229a423fd3f1cbc43
 F src/build.c 4acc35c4e0a2d94c906abd164568cd6fc989cfbb
 F src/callback.c 7b44ce59674338ad48b0e84e7b72f935ea4f68b0
 F src/complete.c addcd8160b081131005d5bc2d34adf20c1c5c92f
@@ -299,7 +299,7 @@ F src/journal.c b4124532212b6952f42eb2c12fa3c25701d8ba8d
 F src/legacy.c ba1863ea58c4c840335a84ec276fc2b25e22bc4e
 F src/lempar.c 92bafa308607dd985ca389a788cd9e0a2b608712
 F src/loadext.c dfcee8c7c032cd0fd55af3e0fc1fcfb01e426df2
-F src/main.c 0a60b7ca8252c3a6f95438fa4ce8fe5b275c69f2
+F src/main.c acfb7cf332d41a36cc6efeefb3fa571dcd30ed87
 F src/malloc.c 19461e159bccf0e2cf06a50e867963d0a7b124a8
 F src/mem0.c 6a55ebe57c46ca1a7d98da93aaa07f99f1059645
 F src/mem1.c abe6ee469b6c5a35c7f22bfeb9c9bac664a1c987
@@ -321,8 +321,8 @@ F src/os_setup.h c9d4553b5aaa6f73391448b265b89bed0b890faa
 F src/os_unix.c 388c023582b17890f10c980b30ec1922b471753b
 F src/os_win.c 40b3af7a47eb1107d0d69e592bec345a3b7b798a
 F src/os_win.h eb7a47aa17b26b77eb97e4823f20a00b8bda12ca
-F src/pager.c aa916ca28606ccf4b6877dfc2b643ccbca86589f
-F src/pager.h 6d435f563b3f7fcae4b84433b76a6ac2730036e2
+F src/pager.c f2318f0577257cd38705b4f2fed61896072e99ae
+F src/pager.h ad181d413ffc47069ec2f3b0dbf5c24fec957ea7
 F src/parse.y 6d60dda8f8d418b6dc034f1fbccd816c459983a8
 F src/pcache.c cde06aa50962595e412d497e22fd2e07878ba1f0
 F src/pcache.h 9968603796240cdf83da7e7bef76edf90619cea9
@@ -335,15 +335,15 @@ F src/random.c ba2679f80ec82c4190062d756f22d0c358180696
 F src/resolve.c 2d47554370de8de6dd5be060cef9559eec315005
 F src/rowset.c eccf6af6d620aaa4579bd3b72c1b6395d9e9fa1e
 F src/select.c 57ef3d98c4400b93eea318813be41b2af2da2217
-F src/shell.c b1f91e60918df3a68efad1e3a11696b9a7e23d23
-F src/sqlite.h.in 447ead0a6b3293206f04a0896553955d07cfb4b9
+F src/shell.c 5e8e1115a543de8003ce9d23173e01948d831ff5
+F src/sqlite.h.in fdf8a6a1fa43e3c3f75d5a61dcd14d617f8a8c44
 F src/sqlite3.rc 992c9f5fb8285ae285d6be28240a7e8d3a7f2bad
 F src/sqlite3ext.h a0b948ebc89bac13941254641326a6aa248c2cc4
-F src/sqliteInt.h 9401d7d9124210dfd5d283af45e0addbc1455c2e
+F src/sqliteInt.h e1a5cfe6c44606429838fa9bbd1824e119e05533
 F src/sqliteLimit.h 216557999cb45f2e3578ed53ebefe228d779cb46
 F src/status.c f266ad8a2892d659b74f0f50cb6a88b6e7c12179
 F src/table.c 51b46b2a62d1b3a959633d593b89bab5e2c9155e
-F src/tclsqlite.c d9439b6a910985b7fff43ba6756bcef00de22649
+F src/tclsqlite.c 1a7b57f3ae892d1a1395b5f1399b6da017b6ad07
 F src/test1.c d339ae9b9baf9221c657c9628c9061d88bd831f6
 F src/test2.c 577961fe48961b2f2e5c8b56ee50c3f459d3359d
 F src/test3.c 64d2afdd68feac1bb5e2ffb8226c8c639f798622
@@ -397,7 +397,7 @@ F src/update.c 487747b328b7216bb7f6af0695d6937d5c9e605f
 F src/utf.c fc6b889ba0779b7722634cdeaa25f1930d93820c
 F src/util.c bc9dd64b5db544218b871b66243871c202b2781f
 F src/vacuum.c 2ddd5cad2a7b9cef7f9e431b8c7771634c6b1701
-F src/vdbe.c 2ab1decd98925f8cd846993dde9dccaa69cdf0ef
+F src/vdbe.c 6281c0f806318f51e43fec4a74aad8a1e240e6ca
 F src/vdbe.h 7a75045d879118b9d3af7e8b3c108f2f27c51473
 F src/vdbeInt.h 8b54e01ad0463590e7cffabce0bc36da9ee4f816
 F src/vdbeapi.c adabbd66eb2e3a10f3998485ee0be7e326d06ee4
@@ -1372,8 +1372,7 @@ F tool/vdbe_profile.tcl 67746953071a9f8f2f668b73fe899074e2c6d8c1
 F tool/warnings-clang.sh f6aa929dc20ef1f856af04a730772f59283631d4
 F tool/warnings.sh 48bd54594752d5be3337f12c72f28d2080cb630b
 F tool/win/sqlite.vsix deb315d026cc8400325c5863eef847784a219a2f
-P 1d75a41bb2f7fcd32f9f08768517b814e452e456 962b6cd6bbc1ef82ae98cb2ddf41e7a1116e70f5
-R 9515e6f89ec29f4ddd4e24f2f6aa441a
-T +closed 962b6cd6bbc1ef82ae98cb2ddf41e7a1116e70f5
-U drh
-Z 835c78eb4169c17715bf2b1e3d1fbe33
+P e844304de7c7d50c4c22c2633bbfef146dfc0be1
+R 478ca33d6f9c24a062db3dabfe78c8fc
+U dan
+Z 41fbe673838f8c22a020d24e68c725f9

manifest.uuid

@@ -1 +1 @@
-fd5608fb20831f1f1946c8941445b7acc463a143
+b09e3ea7b86ff65d749ff0b6c27e05fd3a5fadb1

src/btree.c

@@ -3194,6 +3194,8 @@ int sqlite3BtreeBeginTrans(Btree *p, int wrflag){
       }
     }
   }
+  sqlite3ExperimentalLog(p->pLog, "%s TM",
+    wrflag==0 ? "begin-read" : (wrflag>2 ? "begin-exclusive" : "begin-write"));
 
 
 trans_begun:
@@ -3682,6 +3684,7 @@ int sqlite3BtreeCommitPhaseOne(Btree *p, const char *zMaster){
       sqlite3PagerTruncateImage(pBt->pPager, pBt->nPage);
     }
 #endif
+    sqlite3ExperimentalLog(p->pLog, "commit-start TM");
     rc = sqlite3PagerCommitPhaseOne(pBt->pPager, zMaster, 0);
     sqlite3BtreeLeave(p);
   }
@@ -3724,6 +3727,7 @@ static void btreeEndTransaction(Btree *p){
     p->inTrans = TRANS_NONE;
     unlockBtreeIfUnused(pBt);
   }
+  sqlite3ExperimentalLog(p->pLog, "end-transaction TM");
 
   btreeIntegrity(p);
 }
@@ -5543,6 +5547,9 @@ static int allocateBtreePage(
         pTrunk = 0;
         goto end_allocate_page;
       }
+      if( pBt->pLog ){
+        sqlite3ExperimentalLog(pBt->pLog, "freelist-trunk %d", iTrunk);
+      }
       assert( pTrunk!=0 );
       assert( pTrunk->aData!=0 );
       /* EVIDENCE-OF: R-13523-04394 The second integer on a freelist trunk page
@@ -5561,6 +5568,9 @@ static int allocateBtreePage(
         memcpy(&pPage1->aData[32], &pTrunk->aData[0], 4);
         *ppPage = pTrunk;
         pTrunk = 0;
+        if( pBt->pLog ){
+          sqlite3ExperimentalLog(pBt->pLog, "freelist-trunk-alloc %d", iTrunk);
+        }
         TRACE(("ALLOCATE: %d trunk - %d free pages left\n", *pPgno, n-1));
       }else if( k>(u32)(pBt->usableSize/4 - 2) ){
         /* Value of k is out of range.  Database corruption */
@@ -5845,6 +5855,9 @@ static int freePage2(BtShared *pBt, MemPage *pMemPage, Pgno iPage){
       rc = SQLITE_CORRUPT_BKPT;
       goto freepage_out;
     }
+    if( pBt->pLog ){
+      sqlite3ExperimentalLog(pBt->pLog, "freelist-trunk %d", iTrunk);
+    }
     if( nLeaf < (u32)pBt->usableSize/4 - 8 ){
       /* In this case there is room on the trunk page to insert the page
       ** being freed as a new leaf.
@@ -6104,6 +6117,9 @@ static int fillInCell(
       }
 #endif
       rc = allocateBtreePage(pBt, &pOvfl, &pgnoOvfl, pgnoOvfl, 0);
+      if( rc==SQLITE_OK ){
+        sqlite3ExperimentalLog(pBt->pLog, "allocate %d overflow", pgnoOvfl);
+      }
 #ifndef SQLITE_OMIT_AUTOVACUUM
       /* If the database supports auto-vacuum, and the second or subsequent
       ** overflow page is being allocated, add an entry to the pointer-map
@@ -6704,6 +6720,10 @@ static int balance_quick(MemPage *pParent, MemPage *pPage, u8 *pSpace){
   ** may be inserted. If both these operations are successful, proceed.
   */
   rc = allocateBtreePage(pBt, &pNew, &pgnoNew, 0, 0);
+  if( rc==SQLITE_OK ){
+    sqlite3ExperimentalLog(pPage->pBt->pLog,
+                           "allocate %d quickbalance", pgnoNew);
+  }
 
   if( rc==SQLITE_OK ){
 
@@ -7327,6 +7347,7 @@ static int balance_nonroot(
       assert( i>0 );
       rc = allocateBtreePage(pBt, &pNew, &pgno, (bBulk ? 1 : pgno), 0);
       if( rc ) goto balance_cleanup;
+      sqlite3ExperimentalLog(pBt->pLog, "allocate %d balance", pgno);
       zeroPage(pNew, pageFlags);
       apNew[i] = pNew;
       nNew++;
@@ -7697,6 +7718,9 @@ static int balance_deeper(MemPage *pRoot, MemPage **ppChild){
   rc = sqlite3PagerWrite(pRoot->pDbPage);
   if( rc==SQLITE_OK ){
     rc = allocateBtreePage(pBt,&pChild,&pgnoChild,pRoot->pgno,0);
+    if( rc==SQLITE_OK ){
+      sqlite3ExperimentalLog(pBt->pLog, "allocate %d balancedeeper", pgnoChild);
+    }
     copyNodeContent(pRoot, pChild, &rc);
     if( ISAUTOVACUUM ){
       ptrmapPut(pBt, pgnoChild, PTRMAP_BTREE, pRoot->pgno, &rc);
@@ -8166,6 +8190,8 @@ static int btreeCreateTable(Btree *p, int *piTable, int createTabFlags){
   rc = allocateBtreePage(pBt, &pRoot, &pgnoRoot, 1, 0);
   if( rc ){
     return rc;
+  }else{
+    sqlite3ExperimentalLog(p->pLog, "allocate %d createtable", pgnoRoot);
   }
 #else
   if( pBt->autoVacuum ){
@@ -8203,6 +8229,8 @@ static int btreeCreateTable(Btree *p, int *piTable, int createTabFlags){
     rc = allocateBtreePage(pBt, &pPageMove, &pgnoMove, pgnoRoot, BTALLOC_EXACT);
     if( rc!=SQLITE_OK ){
       return rc;
+    }else{
+      sqlite3ExperimentalLog(p->pLog, "allocate %d createtable", pgnoMove);
     }
 
     if( pgnoMove!=pgnoRoot ){
@@ -8280,6 +8308,7 @@ static int btreeCreateTable(Btree *p, int *piTable, int createTabFlags){
   }else{
     rc = allocateBtreePage(pBt, &pRoot, &pgnoRoot, 1, 0);
     if( rc ) return rc;
+    sqlite3ExperimentalLog(p->pLog, "allocate %d createtable", pgnoRoot);
   }
 #endif
   assert( sqlite3PagerIswriteable(pRoot->pDbPage) );
@@ -9578,3 +9607,14 @@ int sqlite3BtreeIsReadonly(Btree *p){
 ** Return the size of the header added to each page by this module.
 */
 int sqlite3HeaderSizeBtree(void){ return ROUND8(sizeof(MemPage)); }
+
+
+/*
+** Set the Btree ExperimentalLog
+*/
+ExperimentalLog *sqlite3BtreeExperimentalLog(Btree *p, ExperimentalLog *pLog){
+  ExperimentalLog *pOld = p->pLog;
+  p->pLog = pLog;
+  p->pBt->pLog = pLog;
+  return pOld;
+}

src/btree.h

@@ -270,5 +270,6 @@ void sqlite3BtreeCursorList(Btree*);
 # define sqlite3SchemaMutexHeld(X,Y,Z) 1
 #endif
 
+ExperimentalLog *sqlite3BtreeExperimentalLog(Btree*,ExperimentalLog*);
 
 #endif /* _BTREE_H_ */

src/btreeInt.h

@@ -363,6 +363,7 @@ struct Btree {
 #ifndef SQLITE_OMIT_SHARED_CACHE
   BtLock lock;       /* Object used to lock page 1 */
 #endif
+  ExperimentalLog *pLog; /* Write various actions to this experimental log */
 };
 
 /*
@@ -414,6 +415,7 @@ struct Btree {
 struct BtShared {
   Pager *pPager;        /* The page cache */
   sqlite3 *db;          /* Database connection currently using this Btree */
+  ExperimentalLog *pLog; /* Log activities here */
   BtCursor *pCursor;    /* A list of all open cursors */
   MemPage *pPage1;      /* First page of the database */
   u8 openFlags;         /* Flags to sqlite3BtreeOpen() */

src/main.c

@@ -978,6 +978,7 @@ static int sqlite3Close(sqlite3 *db, int forceZombie){
     return SQLITE_MISUSE_BKPT;
   }
   sqlite3_mutex_enter(db->mutex);
+  sqlite3_experimental_log_open(db, 0);
 
   /* Force xDisconnect calls on all virtual tables */
   disconnectAllVtab(db);
@@ -3786,3 +3787,66 @@ int sqlite3_db_readonly(sqlite3 *db, const char *zDbName){
   pBt = sqlite3DbNameToBtree(db, zDbName);
   return pBt ? sqlite3BtreeIsReadonly(pBt) : -1;
 }
+
+/*
+** Turn on logging for the main database of database connection db.
+** Disable logging if zFilename is NULL.
+*/
+void sqlite3_experimental_log_open(sqlite3 *db, const char *zFilename){
+  Btree *pBtree;
+  Pager *pPager;
+  ExperimentalLog *pLog;
+
+  sqlite3_mutex_enter(db->mutex);
+  pBtree = db->aDb[0].pBt;
+  if( pBtree ){
+    pPager = sqlite3BtreePager(pBtree);
+    pLog = sqlite3BtreeExperimentalLog(pBtree, 0);
+    if( pLog ){
+      sqlite3ExperimentalLog(pLog, "close TM");
+      fclose(pLog->out);
+      sqlite3_free(pLog);
+      pLog = 0;
+    }
+    if( zFilename ){
+      pLog = sqlite3_malloc( sizeof(*pLog) );
+      if( pLog ){ 
+        pLog->out = fopen(zFilename, "a+");
+        pLog->pVfs = db->pVfs;
+        if( pLog->out==0 ){
+          sqlite3_free(pLog);
+          pLog = 0;
+        }else{
+          sqlite3ExperimentalLog(pLog, "open %s TM", zFilename);
+        }
+      }
+    }
+    db->pLog = pLog;
+    sqlite3BtreeExperimentalLog(pBtree, pLog);
+    sqlite3PagerExperimentalLog(pPager, pLog);
+  }
+  sqlite3_mutex_leave(db->mutex);
+}
+
+/*
+** Write a message on the given ExperimentalLog if it is open
+*/
+void sqlite3ExperimentalLog(ExperimentalLog *pLog, const char *zFormat, ...){
+  if( pLog ){
+    va_list ap;
+    StrAccum acc;
+    sqlite3_int64 iTime = 0;
+    char zMsg[200];
+    va_start(ap, zFormat);
+    sqlite3StrAccumInit(&acc, 0, zMsg, sizeof(zMsg), 0);
+    sqlite3VXPrintf(&acc, 0, zFormat, ap);
+    if( acc.nChar>2 && strncmp(zMsg+acc.nChar-2, "TM", 2)==0 ){
+      acc.nChar -= 2;
+      sqlite3OsCurrentTimeInt64(pLog->pVfs, &iTime);
+      sqlite3XPrintf(&acc, 0, "%lld", iTime);
+    }
+    sqlite3StrAccumAppend(&acc, "\n", 1);
+    sqlite3StrAccumFinish(&acc);
+    fwrite(zMsg, 1, sqlite3Strlen30(zMsg), pLog->out);
+  }
+}

src/pager.c

@@ -703,6 +703,7 @@ struct Pager {
   Wal *pWal;                  /* Write-ahead log used by "journal_mode=wal" */
   char *zWal;                 /* File name for write-ahead log */
 #endif
+  ExperimentalLog *pLog;      /* Output logging */
 };
 
 /*
@@ -4427,6 +4428,9 @@ static int pagerStress(void *p, PgHdr *pPg){
     return SQLITE_OK;
   }
 
+  if( pPager->pLog ){
+    sqlite3ExperimentalLog(pPager->pLog, "spill %d", pPg->pgno);
+  }
   pPg->pDirty = 0;
   if( pagerUseWal(pPager) ){
     /* Write a single frame for this page to the log. */
@@ -5268,6 +5272,9 @@ int sqlite3PagerAcquire(
     return SQLITE_CORRUPT_BKPT;
   }
   pPager->hasBeenUsed = 1;
+  if( pPager->pLog ){
+    sqlite3ExperimentalLog(pPager->pLog, "read %d", pgno);
+  }
 
   /* If the pager is in the error state, return an error immediately. 
   ** Otherwise, request the page from the PCache layer. */
@@ -5703,6 +5710,9 @@ static int pager_write(PgHdr *pPg){
   assert( pPager->errCode==0 );
   assert( pPager->readOnly==0 );
   CHECK_PAGE(pPg);
+  if( pPager->pLog ){
+    sqlite3ExperimentalLog(pPager->pLog, "write %d", pPg->pgno);
+  }
 
   /* The journal file needs to be opened. Higher level routines have already
   ** obtained the necessary locks to begin the write-transaction, but the
@@ -5889,6 +5899,12 @@ int sqlite3PagerWrite(PgHdr *pPg){
   }
 }
 
+/* Set experimental logging for this pager
+*/
+void sqlite3PagerExperimentalLog(Pager *p, ExperimentalLog *pLog){
+  p->pLog = pLog;
+}
+
 /*
 ** Return TRUE if the page given in the argument was previously passed
 ** to sqlite3PagerWrite().  In other words, return TRUE if it is ok
@@ -7082,12 +7098,20 @@ void sqlite3PagerClearCache(Pager *pPager){
 int sqlite3PagerCheckpoint(Pager *pPager, int eMode, int *pnLog, int *pnCkpt){
   int rc = SQLITE_OK;
   if( pPager->pWal ){
+    if( pPager->pLog ){
+      const char *az[] = { "passive", "full", "restart", "truncate" };
+      sqlite3ExperimentalLog(pPager->pLog, "start-checkpoint %s TM", az[eMode]);
+    }
     rc = sqlite3WalCheckpoint(pPager->pWal, eMode,
         (eMode==SQLITE_CHECKPOINT_PASSIVE ? 0 : pPager->xBusyHandler),
         pPager->pBusyHandlerArg,
         pPager->ckptSyncFlags, pPager->pageSize, (u8 *)pPager->pTmpSpace,
         pnLog, pnCkpt
     );
+    if( pPager->pLog ){
+      sqlite3ExperimentalLog(pPager->pLog, "end-checkpoint %d %d TM", 
+          *pnLog, *pnCkpt);
+    }
   }
   return rc;
 }
@@ -7266,5 +7290,4 @@ int sqlite3PagerWalFramesize(Pager *pPager){
 }
 #endif
 
-
 #endif /* SQLITE_OMIT_DISKIO */

src/pager.h

@@ -193,6 +193,8 @@ void sqlite3PagerTruncateImage(Pager*,Pgno);
 
 void sqlite3PagerRekey(DbPage*, Pgno, u16);
 
+void sqlite3PagerExperimentalLog(Pager*, ExperimentalLog*);
+
 #if defined(SQLITE_HAS_CODEC) && !defined(SQLITE_OMIT_WAL)
 void *sqlite3PagerCodec(DbPage *);
 #endif

src/shell.c

@@ -2849,6 +2849,18 @@ static int do_meta_command(char *zLine, ShellState *p){
     rc = 2;
   }else
 
+  if( c=='e' && strncmp(azArg[0], "explog", n)==0 ){
+    open_db(p, 0);
+    if( nArg!=2 ){
+      fprintf(stderr, "Usage: .explog FILENAME|off\n");
+      rc = 1;
+    }else if( strcmp(azArg[1],"off")==0 ){
+      sqlite3_experimental_log_open(p->db, 0);
+    }else{
+      sqlite3_experimental_log_open(p->db, azArg[1]);
+    }
+  }else
+
   if( c=='e' && strncmp(azArg[0], "explain", n)==0 ){
     int val = nArg>=2 ? booleanValue(azArg[1]) : 1;
     if(val == 1) {

src/sqlite.h.in

@@ -7728,6 +7728,8 @@ int sqlite3_stmt_scanstatus(
 */
 void sqlite3_stmt_scanstatus_reset(sqlite3_stmt*);
 
+/* Experimental logging APIs.  Not for release. */
+void sqlite3_experimental_log_open(sqlite3*, const char *zFilename);
 
 /*
 ** Undo the hack that converts floating point types to integer for

src/sqliteInt.h

@@ -923,6 +923,7 @@ typedef struct Schema Schema;
 typedef struct Expr Expr;
 typedef struct ExprList ExprList;
 typedef struct ExprSpan ExprSpan;
+typedef struct ExperimentalLog ExperimentalLog;
 typedef struct FKey FKey;
 typedef struct FuncDestructor FuncDestructor;
 typedef struct FuncDef FuncDef;
@@ -1247,8 +1248,18 @@ struct sqlite3 {
 #ifdef SQLITE_USER_AUTHENTICATION
   sqlite3_userauth auth;        /* User authentication information */
 #endif
+  ExperimentalLog *pLog;        /* Write experimental log messages here */
 };
 
+/*
+** Information needed by the experimental log
+*/
+struct ExperimentalLog {
+  FILE *out;                    /* Write on this file descriptor */
+  sqlite3_vfs *pVfs;            /* Used to get current time of day */
+};
+void sqlite3ExperimentalLog(ExperimentalLog*, const char *zFormat, ...);
+
 /*
 ** A macro to discover the encoding of a database.
 */

src/tclsqlite.c

@@ -1636,6 +1636,7 @@ static int DbObjCmd(void *cd, Tcl_Interp *interp, int objc,Tcl_Obj *const*objv){
     "collate",            "collation_needed",  "commit_hook",
     "complete",           "copy",              "enable_load_extension",
     "errorcode",          "eval",              "exists",
+    "experimental_log_open",
     "function",           "incrblob",          "interrupt",
     "last_insert_rowid",  "nullvalue",         "onecolumn",
     "profile",            "progress",          "rekey",
@@ -1650,6 +1651,7 @@ static int DbObjCmd(void *cd, Tcl_Interp *interp, int objc,Tcl_Obj *const*objv){
     DB_COLLATE,           DB_COLLATION_NEEDED, DB_COMMIT_HOOK,
     DB_COMPLETE,          DB_COPY,             DB_ENABLE_LOAD_EXTENSION,
     DB_ERRORCODE,         DB_EVAL,             DB_EXISTS,
+    DB_EXPERIMENTAL_LOG_OPEN,
     DB_FUNCTION,          DB_INCRBLOB,         DB_INTERRUPT,
     DB_LAST_INSERT_ROWID, DB_NULLVALUE,        DB_ONECOLUMN,
     DB_PROFILE,           DB_PROGRESS,         DB_REKEY,
@@ -2319,6 +2321,25 @@ static int DbObjCmd(void *cd, Tcl_Interp *interp, int objc,Tcl_Obj *const*objv){
     break;
   }
 
+  /*
+  **     $db experimental_log_open ?FILENAME?
+  **
+  ** Invoke the sqlite3_experimental_log_open() API. This code is not for
+  ** release.
+  */
+  case DB_EXPERIMENTAL_LOG_OPEN: {
+    char *zFile = 0;
+    if( objc>3 ){
+      Tcl_WrongNumArgs(interp, 2, objv, "?FILENAME?");
+      return TCL_ERROR;
+    }
+    if( objc==3 ){
+      zFile = Tcl_GetString(objv[2]);
+    }
+    sqlite3_experimental_log_open(pDb->db, zFile);
+    break;
+  }
+
   /*
   **     $db function NAME [-argcount N] [-deterministic] SCRIPT
   **

src/vdbe.c

@@ -6521,6 +6521,15 @@ case OP_Init: {          /* jump */
   char *zTrace;
   char *z;
 
+  if( db->pLog && p->zSql ){
+    char *z = sqlite3DbStrDup(db, p->zSql);
+    int ii;
+    for(ii=0; z[ii]; ii++){
+      if( sqlite3Isspace(z[ii]) ) z[ii] = ' ';
+    }
+    sqlite3ExperimentalLog(db->pLog, "sql {%s} TM", z);
+    sqlite3DbFree(db, z);
+  }
 #ifndef SQLITE_OMIT_TRACE
   if( db->xTrace
    && !p->doingRerun