Index: src/btree.c ================================================================== --- src/btree.c +++ src/btree.c @@ -3192,10 +3192,12 @@ put4byte(&pPage1->aData[28], pBt->nPage); } } } } + sqlite3ExperimentalLog(p->pLog, "%s TM", + wrflag==0 ? "begin-read" : (wrflag>2 ? "begin-exclusive" : "begin-write")); trans_begun: if( rc==SQLITE_OK && wrflag ){ /* This call makes sure that the pager has the correct number of @@ -3680,10 +3682,11 @@ } if( pBt->bDoTruncate ){ sqlite3PagerTruncateImage(pBt->pPager, pBt->nPage); } #endif + sqlite3ExperimentalLog(p->pLog, "commit-start TM"); rc = sqlite3PagerCommitPhaseOne(pBt->pPager, zMaster, 0); sqlite3BtreeLeave(p); } return rc; } @@ -3722,10 +3725,11 @@ /* Set the current transaction state to TRANS_NONE and unlock the ** pager if this call closed the only read or write transaction. */ p->inTrans = TRANS_NONE; unlockBtreeIfUnused(pBt); } + sqlite3ExperimentalLog(p->pLog, "end-transaction TM"); btreeIntegrity(p); } /* @@ -5541,10 +5545,13 @@ } if( rc ){ 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 ** is the number of leaf page pointers to follow. */ k = get4byte(&pTrunk->aData[4]); @@ -5559,10 +5566,13 @@ } *pPgno = iTrunk; 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 */ rc = SQLITE_CORRUPT_BKPT; goto end_allocate_page; @@ -5843,10 +5853,13 @@ assert( pBt->usableSize>32 ); if( nLeaf > (u32)pBt->usableSize/4 - 2 ){ 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. ** ** Note that the trunk page is not really full until it contains @@ -6102,10 +6115,13 @@ PTRMAP_ISPAGE(pBt, pgnoOvfl) || pgnoOvfl==PENDING_BYTE_PAGE(pBt) ); } #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 ** for that page now. ** @@ -6702,10 +6718,14 @@ /* Allocate a new page. This page will become the right-sibling of ** pPage. Make the parent page writable, so that the new divider cell ** 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 ){ u8 *pOut = &pSpace[4]; u8 *pCell = pPage->apOvfl[0]; @@ -7325,10 +7345,11 @@ if( rc ) goto balance_cleanup; }else{ 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++; cntOld[i] = b.nCell; @@ -7695,10 +7716,13 @@ ** of the node stored on pRoot into the new child page. */ 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); } } @@ -8164,10 +8188,12 @@ #ifdef SQLITE_OMIT_AUTOVACUUM rc = allocateBtreePage(pBt, &pRoot, &pgnoRoot, 1, 0); if( rc ){ return rc; + }else{ + sqlite3ExperimentalLog(p->pLog, "allocate %d createtable", pgnoRoot); } #else if( pBt->autoVacuum ){ Pgno pgnoMove; /* Move a page here to make room for the root-page */ MemPage *pPageMove; /* The page to move to. */ @@ -8201,10 +8227,12 @@ ** to reside at pgnoRoot). */ 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 ){ /* pgnoRoot is the page that will be used for the root-page of ** the new table (assuming an error did not occur). But we were @@ -8278,10 +8306,11 @@ } }else{ rc = allocateBtreePage(pBt, &pRoot, &pgnoRoot, 1, 0); if( rc ) return rc; + sqlite3ExperimentalLog(p->pLog, "allocate %d createtable", pgnoRoot); } #endif assert( sqlite3PagerIswriteable(pRoot->pDbPage) ); if( createTabFlags & BTREE_INTKEY ){ ptfFlags = PTF_INTKEY | PTF_LEAFDATA | PTF_LEAF; @@ -9576,5 +9605,16 @@ /* ** 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; +} Index: src/btree.h ================================================================== --- src/btree.h +++ src/btree.h @@ -268,7 +268,8 @@ # define sqlite3BtreeHoldsMutex(X) 1 # define sqlite3BtreeHoldsAllMutexes(X) 1 # define sqlite3SchemaMutexHeld(X,Y,Z) 1 #endif +ExperimentalLog *sqlite3BtreeExperimentalLog(Btree*,ExperimentalLog*); #endif /* _BTREE_H_ */ Index: src/btreeInt.h ================================================================== --- src/btreeInt.h +++ src/btreeInt.h @@ -361,10 +361,11 @@ Btree *pNext; /* List of other sharable Btrees from the same db */ Btree *pPrev; /* Back pointer of the same list */ #ifndef SQLITE_OMIT_SHARED_CACHE BtLock lock; /* Object used to lock page 1 */ #endif + ExperimentalLog *pLog; /* Write various actions to this experimental log */ }; /* ** Btree.inTrans may take one of the following values. ** @@ -412,10 +413,11 @@ ** This feature is included to help prevent writer-starvation. */ 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() */ #ifndef SQLITE_OMIT_AUTOVACUUM u8 autoVacuum; /* True if auto-vacuum is enabled */ Index: src/main.c ================================================================== --- src/main.c +++ src/main.c @@ -976,10 +976,11 @@ } if( !sqlite3SafetyCheckSickOrOk(db) ){ return SQLITE_MISUSE_BKPT; } sqlite3_mutex_enter(db->mutex); + sqlite3_experimental_log_open(db, 0); /* Force xDisconnect calls on all virtual tables */ disconnectAllVtab(db); /* If a transaction is open, the disconnectAllVtab() call above @@ -3784,5 +3785,68 @@ } #endif 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); + } +} Index: src/pager.c ================================================================== --- src/pager.c +++ src/pager.c @@ -701,10 +701,11 @@ PCache *pPCache; /* Pointer to page cache object */ #ifndef SQLITE_OMIT_WAL Wal *pWal; /* Write-ahead log used by "journal_mode=wal" */ char *zWal; /* File name for write-ahead log */ #endif + ExperimentalLog *pLog; /* Output logging */ }; /* ** Indexes for use with Pager.aStat[]. The Pager.aStat[] array contains ** the values accessed by passing SQLITE_DBSTATUS_CACHE_HIT, CACHE_MISS @@ -4425,10 +4426,13 @@ || (pPg->flags & PGHDR_NEED_SYNC)!=0) ){ 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. */ rc = subjournalPageIfRequired(pPg); if( rc==SQLITE_OK ){ @@ -5266,10 +5270,13 @@ if( pgno==0 ){ 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. */ if( pPager->errCode!=SQLITE_OK ){ rc = pPager->errCode; @@ -5701,10 +5708,13 @@ ); assert( assert_pager_state(pPager) ); 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 ** rollback journal might not yet be open. Open it now if this is the case. ** @@ -5886,10 +5896,16 @@ return pagerWriteLargeSector(pPg); }else{ return pager_write(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 ** to change the content of the page. @@ -7080,16 +7096,24 @@ ** Parameter eMode is one of SQLITE_CHECKPOINT_PASSIVE, FULL or RESTART. */ 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; } int sqlite3PagerWalCallback(Pager *pPager){ @@ -7263,8 +7287,7 @@ int sqlite3PagerWalFramesize(Pager *pPager){ assert( pPager->eState>=PAGER_READER ); return sqlite3WalFramesize(pPager->pWal); } #endif - #endif /* SQLITE_OMIT_DISKIO */ Index: src/pager.h ================================================================== --- src/pager.h +++ src/pager.h @@ -190,10 +190,12 @@ /* Functions used to truncate the database file. */ 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 Index: src/shell.c ================================================================== --- src/shell.c +++ src/shell.c @@ -2846,10 +2846,22 @@ if( c=='e' && strncmp(azArg[0], "exit", n)==0 ){ if( nArg>1 && (rc = (int)integerValue(azArg[1]))!=0 ) exit(rc); 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) { if(!p->normalMode.valid) { Index: src/sqlite.h.in ================================================================== --- src/sqlite.h.in +++ src/sqlite.h.in @@ -7726,10 +7726,12 @@ ** This API is only available if the library is built with pre-processor ** symbol [SQLITE_ENABLE_STMT_SCANSTATUS] defined. */ 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 ** builds on processors without floating point support. */ Index: src/sqliteInt.h ================================================================== --- src/sqliteInt.h +++ src/sqliteInt.h @@ -921,10 +921,11 @@ typedef struct Db Db; 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; typedef struct FuncDefHash FuncDefHash; typedef struct IdList IdList; @@ -1245,11 +1246,21 @@ sqlite3 *pNextBlocked; /* Next in list of all blocked connections */ #endif #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. */ #define SCHEMA_ENC(db) ((db)->aDb[0].pSchema->enc) Index: src/tclsqlite.c ================================================================== --- src/tclsqlite.c +++ src/tclsqlite.c @@ -1634,10 +1634,11 @@ "authorizer", "backup", "busy", "cache", "changes", "close", "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", "restore", "rollback_hook", "status", "timeout", "total_changes", "trace", @@ -1648,10 +1649,11 @@ DB_AUTHORIZER, DB_BACKUP, DB_BUSY, DB_CACHE, DB_CHANGES, DB_CLOSE, 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, DB_RESTORE, DB_ROLLBACK_HOOK, DB_STATUS, DB_TIMEOUT, DB_TOTAL_CHANGES, DB_TRACE, @@ -2316,10 +2318,29 @@ cd2[1] = (void *)pScript; rc = DbEvalNextCmd(cd2, interp, TCL_OK); } 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 ** ** Create a new SQL function called NAME. Whenever that function is Index: src/vdbe.c ================================================================== --- src/vdbe.c +++ src/vdbe.c @@ -6519,10 +6519,19 @@ */ 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 && (zTrace = (pOp->p4.z ? pOp->p4.z : p->zSql))!=0 ){