blob: 0ec6de5aab52314472ad6b8d888bdb89e80f338e [file] [log] [blame]
/*
** 2012 November 26
**
** The author disclaims copyright to this source code. In place of
** a legal notice, here is a blessing:
**
** May you do good and not evil.
** May you find forgiveness for yourself and forgive others.
** May you share freely, never taking more than you give.
**
*************************************************************************
**
** OVERVIEW
**
** This file contains experimental code used to record data from live
** SQLite applications that may be useful for offline analysis.
** Specifically, this module can be used to capture the following
** information:
**
** 1) The initial contents of all database files opened by the
** application, and
**
** 2) All SQL statements executed by the application.
**
** The captured information can then be used to run (for example)
** performance analysis looking for slow queries or to look for
** optimization opportunities in either the application or in SQLite
** itself.
**
** USAGE
**
** To use this module, SQLite must be compiled with the SQLITE_ENABLE_SQLLOG
** pre-processor symbol defined and this file linked into the application.
** One way to link this file into the application is to append the content
** of this file onto the end of the "sqlite3.c" amalgamation and then
** recompile the application as normal except with the addition of the
** -DSQLITE_ENABLE_SQLLOG option.
**
** At runtime, logging is enabled by setting environment variable
** SQLITE_SQLLOG_DIR to the name of a directory in which to store logged
** data. The logging directory must already exist.
**
** Usually, if the application opens the same database file more than once
** (either by attaching it or by using more than one database handle), only
** a single copy is made. This behavior may be overridden (so that a
** separate copy is taken each time the database file is opened or attached)
** by setting the environment variable SQLITE_SQLLOG_REUSE_FILES to 0.
**
** If the environment variable SQLITE_SQLLOG_CONDITIONAL is defined, then
** logging is only done for database connections if a file named
** "<database>-sqllog" exists in the same directly as the main database
** file when it is first opened ("<database>" is replaced by the actual
** name of the main database file).
**
** OUTPUT:
**
** The SQLITE_SQLLOG_DIR is populated with three types of files:
**
** sqllog_N.db - Copies of database files. N may be any integer.
**
** sqllog_N.sql - A list of SQL statements executed by a single
** connection. N may be any integer.
**
** sqllog.idx - An index mapping from integer N to a database
** file name - indicating the full path of the
** database from which sqllog_N.db was copied.
**
** ERROR HANDLING:
**
** This module attempts to make a best effort to continue logging if an
** IO or other error is encountered. For example, if a log file cannot
** be opened logs are not collected for that connection, but other
** logging proceeds as expected. Errors are logged by calling sqlite3_log().
*/
#ifndef _SQLITE3_H_
#include "sqlite3.h"
#endif
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <assert.h>
#include <sys/types.h>
#include <unistd.h>
static int getProcessId(void){
#if SQLITE_OS_WIN
return (int)_getpid();
#else
return (int)getpid();
#endif
}
/* Names of environment variables to be used */
#define ENVIRONMENT_VARIABLE1_NAME "SQLITE_SQLLOG_DIR"
#define ENVIRONMENT_VARIABLE2_NAME "SQLITE_SQLLOG_REUSE_FILES"
#define ENVIRONMENT_VARIABLE3_NAME "SQLITE_SQLLOG_CONDITIONAL"
/* Assume that all database and database file names are shorted than this. */
#define SQLLOG_NAMESZ 512
/* Maximum number of simultaneous database connections the process may
** open (if any more are opened an error is logged using sqlite3_log()
** and processing is halted).
*/
#define MAX_CONNECTIONS 256
/* There is one instance of this object for each SQLite database connection
** that is being logged.
*/
struct SLConn {
int isErr; /* True if an error has occurred */
sqlite3 *db; /* Connection handle */
int iLog; /* First integer value used in file names */
FILE *fd; /* File descriptor for log file */
};
/* This object is a singleton that keeps track of all data loggers.
*/
static struct SLGlobal {
/* Protected by MUTEX_STATIC_MASTER */
sqlite3_mutex *mutex; /* Recursive mutex */
int nConn; /* Size of aConn[] array */
/* Protected by SLGlobal.mutex */
int bConditional; /* Only trace if *-sqllog file is present */
int bReuse; /* True to avoid extra copies of db files */
char zPrefix[SQLLOG_NAMESZ]; /* Prefix for all created files */
char zIdx[SQLLOG_NAMESZ]; /* Full path to *.idx file */
int iNextLog; /* Used to allocate file names */
int iNextDb; /* Used to allocate database file names */
int bRec; /* True if testSqllog() is called rec. */
int iClock; /* Clock value */
struct SLConn aConn[MAX_CONNECTIONS];
} sqllogglobal;
/*
** Return true if c is an ASCII whitespace character.
*/
static int sqllog_isspace(char c){
return (c==' ' || c=='\t' || c=='\n' || c=='\v' || c=='\f' || c=='\r');
}
/*
** The first argument points to a nul-terminated string containing an SQL
** command. Before returning, this function sets *pz to point to the start
** of the first token in this command, and *pn to the number of bytes in
** the token. This is used to check if the SQL command is an "ATTACH" or
** not.
*/
static void sqllogTokenize(const char *z, const char **pz, int *pn){
const char *p = z;
int n;
/* Skip past any whitespace */
while( sqllog_isspace(*p) ){
p++;
}
/* Figure out how long the first token is */
*pz = p;
n = 0;
while( (p[n]>='a' && p[n]<='z') || (p[n]>='A' && p[n]<='Z') ) n++;
*pn = n;
}
/*
** Check if the logs directory already contains a copy of database file
** zFile. If so, return a pointer to the full path of the copy. Otherwise,
** return NULL.
**
** If a non-NULL value is returned, then the caller must arrange to
** eventually free it using sqlite3_free().
*/
static char *sqllogFindFile(const char *zFile){
char *zRet = 0;
FILE *fd = 0;
/* Open the index file for reading */
fd = fopen(sqllogglobal.zIdx, "r");
if( fd==0 ){
sqlite3_log(SQLITE_IOERR, "sqllogFindFile(): error in fopen()");
return 0;
}
/* Loop through each entry in the index file. If zFile is not NULL and the
** entry is a match, then set zRet to point to the filename of the existing
** copy and break out of the loop. */
while( feof(fd)==0 ){
char zLine[SQLLOG_NAMESZ*2+5];
if( fgets(zLine, sizeof(zLine), fd) ){
int n;
char *z;
zLine[sizeof(zLine)-1] = '\0';
z = zLine;
while( *z>='0' && *z<='9' ) z++;
while( *z==' ' ) z++;
n = strlen(z);
while( n>0 && sqllog_isspace(z[n-1]) ) n--;
if( n==strlen(zFile) && 0==memcmp(zFile, z, n) ){
char zBuf[16];
memset(zBuf, 0, sizeof(zBuf));
z = zLine;
while( *z>='0' && *z<='9' ){
zBuf[z-zLine] = *z;
z++;
}
zRet = sqlite3_mprintf("%s_%s.db", sqllogglobal.zPrefix, zBuf);
break;
}
}
}
if( ferror(fd) ){
sqlite3_log(SQLITE_IOERR, "sqllogFindFile(): error reading index file");
}
fclose(fd);
return zRet;
}
static int sqllogFindAttached(
sqlite3 *db, /* Database connection */
const char *zSearch, /* Name to search for (or NULL) */
char *zName, /* OUT: Name of attached database */
char *zFile /* OUT: Name of attached file */
){
sqlite3_stmt *pStmt;
int rc;
/* The "PRAGMA database_list" command returns a list of databases in the
** order that they were attached. So a newly attached database is
** described by the last row returned. */
assert( sqllogglobal.bRec==0 );
sqllogglobal.bRec = 1;
rc = sqlite3_prepare_v2(db, "PRAGMA database_list", -1, &pStmt, 0);
if( rc==SQLITE_OK ){
while( SQLITE_ROW==sqlite3_step(pStmt) ){
const char *zVal1; int nVal1;
const char *zVal2; int nVal2;
zVal1 = (const char*)sqlite3_column_text(pStmt, 1);
nVal1 = sqlite3_column_bytes(pStmt, 1);
if( zName ){
memcpy(zName, zVal1, nVal1+1);
}
zVal2 = (const char*)sqlite3_column_text(pStmt, 2);
nVal2 = sqlite3_column_bytes(pStmt, 2);
memcpy(zFile, zVal2, nVal2+1);
if( zSearch && strlen(zSearch)==nVal1
&& 0==sqlite3_strnicmp(zSearch, zVal1, nVal1)
){
break;
}
}
rc = sqlite3_finalize(pStmt);
}
sqllogglobal.bRec = 0;
if( rc!=SQLITE_OK ){
sqlite3_log(rc, "sqllogFindAttached(): error in \"PRAGMA database_list\"");
}
return rc;
}
/*
** Parameter zSearch is the name of a database attached to the database
** connection associated with the first argument. This function creates
** a backup of this database in the logs directory.
**
** The name used for the backup file is automatically generated. Call
** it zFile.
**
** If the bLog parameter is true, then a statement of the following form
** is written to the log file associated with *p:
**
** ATTACH 'zFile' AS 'zName';
**
** Otherwise, if bLog is false, a comment is added to the log file:
**
** -- Main database file is 'zFile'
**
** The SLGlobal.mutex mutex is always held when this function is called.
*/
static void sqllogCopydb(struct SLConn *p, const char *zSearch, int bLog){
char zName[SQLLOG_NAMESZ]; /* Attached database name */
char zFile[SQLLOG_NAMESZ]; /* Database file name */
char *zFree;
char *zInit = 0;
int rc;
rc = sqllogFindAttached(p->db, zSearch, zName, zFile);
if( rc!=SQLITE_OK ) return;
if( zFile[0]=='\0' ){
zInit = sqlite3_mprintf("");
}else{
if( sqllogglobal.bReuse ){
zInit = sqllogFindFile(zFile);
}else{
zInit = 0;
}
if( zInit==0 ){
int rc;
sqlite3 *copy = 0;
int iDb;
/* Generate a file-name to use for the copy of this database */
iDb = sqllogglobal.iNextDb++;
zInit = sqlite3_mprintf("%s_%02d.db", sqllogglobal.zPrefix, iDb);
/* Create the backup */
assert( sqllogglobal.bRec==0 );
sqllogglobal.bRec = 1;
rc = sqlite3_open(zInit, &copy);
if( rc==SQLITE_OK ){
sqlite3_backup *pBak;
sqlite3_exec(copy, "PRAGMA synchronous = 0", 0, 0, 0);
pBak = sqlite3_backup_init(copy, "main", p->db, zName);
if( pBak ){
sqlite3_backup_step(pBak, -1);
rc = sqlite3_backup_finish(pBak);
}else{
rc = sqlite3_errcode(copy);
}
sqlite3_close(copy);
}
sqllogglobal.bRec = 0;
if( rc==SQLITE_OK ){
/* Write an entry into the database index file */
FILE *fd = fopen(sqllogglobal.zIdx, "a");
if( fd ){
fprintf(fd, "%d %s\n", iDb, zFile);
fclose(fd);
}
}else{
sqlite3_log(rc, "sqllogCopydb(): error backing up database");
}
}
}
if( bLog ){
zFree = sqlite3_mprintf("ATTACH '%q' AS '%q'; -- clock=%d\n",
zInit, zName, sqllogglobal.iClock++
);
}else{
zFree = sqlite3_mprintf("-- Main database is '%q'\n", zInit);
}
fprintf(p->fd, "%s", zFree);
sqlite3_free(zFree);
sqlite3_free(zInit);
}
/*
** If it is not already open, open the log file for connection *p.
**
** The SLGlobal.mutex mutex is always held when this function is called.
*/
static void sqllogOpenlog(struct SLConn *p){
/* If the log file has not yet been opened, open it now. */
if( p->fd==0 ){
char *zLog;
/* If it is still NULL, have global.zPrefix point to a copy of
** environment variable $ENVIRONMENT_VARIABLE1_NAME. */
if( sqllogglobal.zPrefix[0]==0 ){
FILE *fd;
char *zVar = getenv(ENVIRONMENT_VARIABLE1_NAME);
if( zVar==0 || strlen(zVar)+10>=(sizeof(sqllogglobal.zPrefix)) ) return;
sqlite3_snprintf(sizeof(sqllogglobal.zPrefix), sqllogglobal.zPrefix,
"%s/sqllog_%05d", zVar, getProcessId());
sqlite3_snprintf(sizeof(sqllogglobal.zIdx), sqllogglobal.zIdx,
"%s.idx", sqllogglobal.zPrefix);
if( getenv(ENVIRONMENT_VARIABLE2_NAME) ){
sqllogglobal.bReuse = atoi(getenv(ENVIRONMENT_VARIABLE2_NAME));
}
fd = fopen(sqllogglobal.zIdx, "w");
if( fd ) fclose(fd);
}
/* Open the log file */
zLog = sqlite3_mprintf("%s_%05d.sql", sqllogglobal.zPrefix, p->iLog);
p->fd = fopen(zLog, "w");
sqlite3_free(zLog);
if( p->fd==0 ){
sqlite3_log(SQLITE_IOERR, "sqllogOpenlog(): Failed to open log file");
}
}
}
/*
** This function is called if the SQLLOG callback is invoked to report
** execution of an SQL statement. Parameter p is the connection the statement
** was executed by and parameter zSql is the text of the statement itself.
*/
static void testSqllogStmt(struct SLConn *p, const char *zSql){
const char *zFirst; /* Pointer to first token in zSql */
int nFirst; /* Size of token zFirst in bytes */
sqllogTokenize(zSql, &zFirst, &nFirst);
if( nFirst!=6 || 0!=sqlite3_strnicmp("ATTACH", zFirst, 6) ){
/* Not an ATTACH statement. Write this directly to the log. */
fprintf(p->fd, "%s; -- clock=%d\n", zSql, sqllogglobal.iClock++);
}else{
/* This is an ATTACH statement. Copy the database. */
sqllogCopydb(p, 0, 1);
}
}
/*
** The database handle passed as the only argument has just been opened.
** Return true if this module should log initial databases and SQL
** statements for this connection, or false otherwise.
**
** If an error occurs, sqlite3_log() is invoked to report it to the user
** and zero returned.
*/
static int sqllogTraceDb(sqlite3 *db){
int bRet = 1;
if( sqllogglobal.bConditional ){
char zFile[SQLLOG_NAMESZ]; /* Attached database name */
int rc = sqllogFindAttached(db, "main", 0, zFile);
if( rc==SQLITE_OK ){
int nFile = strlen(zFile);
if( (SQLLOG_NAMESZ-nFile)<8 ){
sqlite3_log(SQLITE_IOERR,
"sqllogTraceDb(): database name too long (%d bytes)", nFile
);
bRet = 0;
}else{
memcpy(&zFile[nFile], "-sqllog", 8);
bRet = !access(zFile, F_OK);
}
}
}
return bRet;
}
/*
** The SQLITE_CONFIG_SQLLOG callback registered by sqlite3_init_sqllog().
**
** The eType parameter has the following values:
**
** 0: Opening a new database connection. zSql is the name of the
** file being opened. db is a pointer to the newly created database
** connection.
**
** 1: An SQL statement has run to completion. zSql is the text of the
** SQL statement with all parameters expanded to their actual values.
**
** 2: Closing a database connection. zSql is NULL. The db pointer to
** the database connection being closed has already been shut down
** and cannot be used for any further SQL.
**
** The pCtx parameter is a copy of the pointer that was originally passed
** into the sqlite3_config(SQLITE_CONFIG_SQLLOG) statement. In this
** particular implementation, pCtx is always a pointer to the
** sqllogglobal global variable define above.
*/
static void testSqllog(void *pCtx, sqlite3 *db, const char *zSql, int eType){
struct SLConn *p = 0;
sqlite3_mutex *master = sqlite3_mutex_alloc(SQLITE_MUTEX_STATIC_MASTER);
assert( eType==0 || eType==1 || eType==2 );
assert( (eType==2)==(zSql==0) );
/* This is a database open command. */
if( eType==0 ){
sqlite3_mutex_enter(master);
if( sqllogglobal.mutex==0 ){
sqllogglobal.mutex = sqlite3_mutex_alloc(SQLITE_MUTEX_RECURSIVE);
}
sqlite3_mutex_leave(master);
sqlite3_mutex_enter(sqllogglobal.mutex);
if( sqllogglobal.bRec==0 && sqllogTraceDb(db) ){
sqlite3_mutex_enter(master);
p = &sqllogglobal.aConn[sqllogglobal.nConn++];
p->fd = 0;
p->db = db;
p->iLog = sqllogglobal.iNextLog++;
sqlite3_mutex_leave(master);
/* Open the log and take a copy of the main database file */
sqllogOpenlog(p);
if( p->fd ) sqllogCopydb(p, "main", 0);
}
sqlite3_mutex_leave(sqllogglobal.mutex);
}
else{
int i;
for(i=0; i<sqllogglobal.nConn; i++){
p = &sqllogglobal.aConn[i];
if( p->db==db ) break;
}
/* A database handle close command */
if( eType==2 ){
sqlite3_mutex_enter(master);
if( i<sqllogglobal.nConn ){
if( p->fd ) fclose(p->fd);
p->db = 0;
p->fd = 0;
sqllogglobal.nConn--;
}
if( sqllogglobal.nConn==0 ){
sqlite3_mutex_free(sqllogglobal.mutex);
sqllogglobal.mutex = 0;
}else if( i<sqllogglobal.nConn ){
int nShift = &sqllogglobal.aConn[sqllogglobal.nConn] - p;
if( nShift>0 ){
memmove(p, &p[1], nShift*sizeof(struct SLConn));
}
}
sqlite3_mutex_leave(master);
/* An ordinary SQL command. */
}else if( i<sqllogglobal.nConn && p->fd ){
sqlite3_mutex_enter(sqllogglobal.mutex);
if( sqllogglobal.bRec==0 ){
testSqllogStmt(p, zSql);
}
sqlite3_mutex_leave(sqllogglobal.mutex);
}
}
}
/*
** This function is called either before sqlite3_initialized() or by it.
** It checks if the SQLITE_SQLLOG_DIR variable is defined, and if so
** registers an SQLITE_CONFIG_SQLLOG callback to record the applications
** database activity.
*/
void sqlite3_init_sqllog(void){
if( getenv(ENVIRONMENT_VARIABLE1_NAME) ){
if( SQLITE_OK==sqlite3_config(SQLITE_CONFIG_SQLLOG, testSqllog, 0) ){
memset(&sqllogglobal, 0, sizeof(sqllogglobal));
sqllogglobal.bReuse = 1;
if( getenv(ENVIRONMENT_VARIABLE3_NAME) ){
sqllogglobal.bConditional = 1;
}
}
}
}