src/test_sqllog.c

   1 /*
   2 ** 2012 November 26
   3 **
   4 ** The author disclaims copyright to this source code.  In place of
   5 ** a legal notice, here is a blessing:
   6 **
   7 **    May you do good and not evil.
   8 **    May you find forgiveness for yourself and forgive others.
   9 **    May you share freely, never taking more than you give.
  10 **
  11 *************************************************************************
  12 **
  13 ** OVERVIEW
  14 **
  15 **   This file contains experimental code used to record data from live
  16 **   SQLite applications that may be useful for offline analysis.
  17 **   Specifically, this module can be used to capture the following
  18 **   information:
  19 **
  20 **     1) The initial contents of all database files opened by the
  21 **        application, and
  22 **
  23 **     2) All SQL statements executed by the application.
  24 **
  25 **   The captured information can then be used to run (for example)
  26 **   performance analysis looking for slow queries or to look for
  27 **   optimization opportunities in either the application or in SQLite
  28 **   itself.
  29 **
  30 ** USAGE
  31 **
  32 **   To use this module, SQLite must be compiled with the SQLITE_ENABLE_SQLLOG
  33 **   pre-processor symbol defined and this file linked into the application.
  34 **   One way to link this file into the application is to append the content
  35 **   of this file onto the end of the "sqlite3.c" amalgamation and then
  36 **   recompile the application as normal except with the addition  of the
  37 **   -DSQLITE_ENABLE_SQLLOG option.
  38 **
  39 **   At runtime, logging is enabled by setting environment variable
  40 **   SQLITE_SQLLOG_DIR to the name of a directory in which to store logged
  41 **   data. The logging directory must already exist.
  42 **
  43 **   Usually, if the application opens the same database file more than once
  44 **   (either by attaching it or by using more than one database handle), only
  45 **   a single copy is made. This behavior may be overridden (so that a
  46 **   separate copy is taken each time the database file is opened or attached)
  47 **   by setting the environment variable SQLITE_SQLLOG_REUSE_FILES to 0.
  48 **
  49 **   If the environment variable SQLITE_SQLLOG_CONDITIONAL is defined, then
  50 **   logging is only done for database connections if a file named
  51 **   "<database>-sqllog" exists in the same directly as the main database
  52 **   file when it is first opened ("<database>" is replaced by the actual
  53 **   name of the main database file).
  54 **
  55 ** OUTPUT:
  56 **
  57 **   The SQLITE_SQLLOG_DIR is populated with three types of files:
  58 **
  59 **      sqllog_N.db   - Copies of database files. N may be any integer.
  60 **
  61 **      sqllog_N.sql  - A list of SQL statements executed by a single
  62 **                      connection. N may be any integer.
  63 **
  64 **      sqllog.idx    - An index mapping from integer N to a database
  65 **                      file name - indicating the full path of the
  66 **                      database from which sqllog_N.db was copied.
  67 **
  68 ** ERROR HANDLING:
  69 **
  70 **   This module attempts to make a best effort to continue logging if an
  71 **   IO or other error is encountered. For example, if a log file cannot
  72 **   be opened logs are not collected for that connection, but other
  73 **   logging proceeds as expected. Errors are logged by calling sqlite3_log().
  74 */
  75
  76 #ifndef _SQLITE3_H_
  77 #include "sqlite3.h"
  78 #endif
  79 #include <stdio.h>
  80 #include <stdlib.h>
  81 #include <string.h>
  82 #include <assert.h>
  83
  84 #include <sys/types.h>
  85 #include <unistd.h>
  86 static int getProcessId(void){
  87 #if SQLITE_OS_WIN
  88   return (int)_getpid();
  89 #else
  90   return (int)getpid();
  91 #endif
  92 }
  93
  94 /* Names of environment variables to be used */
  95 #define ENVIRONMENT_VARIABLE1_NAME "SQLITE_SQLLOG_DIR"
  96 #define ENVIRONMENT_VARIABLE2_NAME "SQLITE_SQLLOG_REUSE_FILES"
  97 #define ENVIRONMENT_VARIABLE3_NAME "SQLITE_SQLLOG_CONDITIONAL"
  98
  99 /* Assume that all database and database file names are shorted than this. */
 100 #define SQLLOG_NAMESZ 512
 101
 102 /* Maximum number of simultaneous database connections the process may
 103 ** open (if any more are opened an error is logged using sqlite3_log()
 104 ** and processing is halted).
 105 */
 106 #define MAX_CONNECTIONS 256
 107
 108 /* There is one instance of this object for each SQLite database connection
 109 ** that is being logged.
 110 */
 111 struct SLConn {
 112   int isErr;                      /* True if an error has occurred */
 113   sqlite3 *db;                    /* Connection handle */
 114   int iLog;                       /* First integer value used in file names */
 115   FILE *fd;                       /* File descriptor for log file */
 116 };
 117
 118 /* This object is a singleton that keeps track of all data loggers.
 119 */
 120 static struct SLGlobal {
 121   /* Protected by MUTEX_STATIC_MASTER */
 122   sqlite3_mutex *mutex;           /* Recursive mutex */
 123   int nConn;                      /* Size of aConn[] array */
 124
 125   /* Protected by SLGlobal.mutex */
 126   int bConditional;               /* Only trace if *-sqllog file is present */
 127   int bReuse;                     /* True to avoid extra copies of db files */
 128   char zPrefix[SQLLOG_NAMESZ];    /* Prefix for all created files */
 129   char zIdx[SQLLOG_NAMESZ];       /* Full path to *.idx file */
 130   int iNextLog;                   /* Used to allocate file names */
 131   int iNextDb;                    /* Used to allocate database file names */
 132   int bRec;                       /* True if testSqllog() is called rec. */
 133   int iClock;                     /* Clock value */
 134   struct SLConn aConn[MAX_CONNECTIONS];
 135 } sqllogglobal;
 136
 137 /*
 138 ** Return true if c is an ASCII whitespace character.
 139 */
 140 static int sqllog_isspace(char c){
 141   return (c==' ' || c=='\t' || c=='\n' || c=='\v' || c=='\f' || c=='\r');
 142 }
 143
 144 /*
 145 ** The first argument points to a nul-terminated string containing an SQL
 146 ** command. Before returning, this function sets *pz to point to the start
 147 ** of the first token in this command, and *pn to the number of bytes in
 148 ** the token. This is used to check if the SQL command is an "ATTACH" or
 149 ** not.
 150 */
 151 static void sqllogTokenize(const char *z, const char **pz, int *pn){
 152   const char *p = z;
 153   int n;
 154
 155   /* Skip past any whitespace */
 156   while( sqllog_isspace(*p) ){
 157     p++;
 158   }
 159
 160   /* Figure out how long the first token is */
 161   *pz = p;
 162   n = 0;
 163   while( (p[n]>='a' && p[n]<='z') || (p[n]>='A' && p[n]<='Z') ) n++;
 164   *pn = n;
 165 }
 166
 167 /*
 168 ** Check if the logs directory already contains a copy of database file
 169 ** zFile. If so, return a pointer to the full path of the copy. Otherwise,
 170 ** return NULL.
 171 **
 172 ** If a non-NULL value is returned, then the caller must arrange to
 173 ** eventually free it using sqlite3_free().
 174 */
 175 static char *sqllogFindFile(const char *zFile){
 176   char *zRet = 0;
 177   FILE *fd = 0;
 178
 179   /* Open the index file for reading */
 180   fd = fopen(sqllogglobal.zIdx, "r");
 181   if( fd==0 ){
 182     sqlite3_log(SQLITE_IOERR, "sqllogFindFile(): error in fopen()");
 183     return 0;
 184   }
 185
 186   /* Loop through each entry in the index file. If zFile is not NULL and the
 187   ** entry is a match, then set zRet to point to the filename of the existing
 188   ** copy and break out of the loop.  */
 189   while( feof(fd)==0 ){
 190     char zLine[SQLLOG_NAMESZ*2+5];
 191     if( fgets(zLine, sizeof(zLine), fd) ){
 192       int n;
 193       char *z;
 194
 195       zLine[sizeof(zLine)-1] = '\0';
 196       z = zLine;
 197       while( *z>='0' && *z<='9' ) z++;
 198       while( *z==' ' ) z++;
 199
 200       n = strlen(z);
 201       while( n>0 && sqllog_isspace(z[n-1]) ) n--;
 202
 203       if( n==strlen(zFile) && 0==memcmp(zFile, z, n) ){
 204         char zBuf[16];
 205         memset(zBuf, 0, sizeof(zBuf));
 206         z = zLine;
 207         while( *z>='0' && *z<='9' ){
 208           zBuf[z-zLine] = *z;
 209           z++;
 210         }
 211         zRet = sqlite3_mprintf("%s_%s.db", sqllogglobal.zPrefix, zBuf);
 212         break;
 213       }
 214     }
 215   }
 216
 217   if( ferror(fd) ){
 218     sqlite3_log(SQLITE_IOERR, "sqllogFindFile(): error reading index file");
 219   }
 220
 221   fclose(fd);
 222   return zRet;
 223 }
 224
 225 static int sqllogFindAttached(
 226   sqlite3 *db,                    /* Database connection */
 227   const char *zSearch,            /* Name to search for (or NULL) */
 228   char *zName,                    /* OUT: Name of attached database */
 229   char *zFile                     /* OUT: Name of attached file */
 230 ){
 231   sqlite3_stmt *pStmt;
 232   int rc;
 233
 234   /* The "PRAGMA database_list" command returns a list of databases in the
 235   ** order that they were attached. So a newly attached database is
 236   ** described by the last row returned.  */
 237   assert( sqllogglobal.bRec==0 );
 238   sqllogglobal.bRec = 1;
 239   rc = sqlite3_prepare_v2(db, "PRAGMA database_list", -1, &pStmt, 0);
 240   if( rc==SQLITE_OK ){
 241     while( SQLITE_ROW==sqlite3_step(pStmt) ){
 242       const char *zVal1; int nVal1;
 243       const char *zVal2; int nVal2;
 244
 245       zVal1 = (const char*)sqlite3_column_text(pStmt, 1);
 246       nVal1 = sqlite3_column_bytes(pStmt, 1);
 247       if( zName ){
 248         memcpy(zName, zVal1, nVal1+1);
 249       }
 250
 251       zVal2 = (const char*)sqlite3_column_text(pStmt, 2);
 252       nVal2 = sqlite3_column_bytes(pStmt, 2);
 253       memcpy(zFile, zVal2, nVal2+1);
 254
 255       if( zSearch && strlen(zSearch)==nVal1
 256        && 0==sqlite3_strnicmp(zSearch, zVal1, nVal1)
 257       ){
 258         break;
 259       }
 260     }
 261     rc = sqlite3_finalize(pStmt);
 262   }
 263   sqllogglobal.bRec = 0;
 264
 265   if( rc!=SQLITE_OK ){
 266     sqlite3_log(rc, "sqllogFindAttached(): error in \"PRAGMA database_list\"");
 267   }
 268   return rc;
 269 }
 270
 271
 272 /*
 273 ** Parameter zSearch is the name of a database attached to the database
 274 ** connection associated with the first argument. This function creates
 275 ** a backup of this database in the logs directory.
 276 **
 277 ** The name used for the backup file is automatically generated. Call
 278 ** it zFile.
 279 **
 280 ** If the bLog parameter is true, then a statement of the following form
 281 ** is written to the log file associated with *p:
 282 **
 283 **    ATTACH 'zFile' AS 'zName';
 284 **
 285 ** Otherwise, if bLog is false, a comment is added to the log file:
 286 **
 287 **    -- Main database file is 'zFile'
 288 **
 289 ** The SLGlobal.mutex mutex is always held when this function is called.
 290 */
 291 static void sqllogCopydb(struct SLConn *p, const char *zSearch, int bLog){
 292   char zName[SQLLOG_NAMESZ];      /* Attached database name */
 293   char zFile[SQLLOG_NAMESZ];      /* Database file name */
 294   char *zFree;
 295   char *zInit = 0;
 296   int rc;
 297
 298   rc = sqllogFindAttached(p->db, zSearch, zName, zFile);
 299   if( rc!=SQLITE_OK ) return;
 300
 301   if( zFile[0]=='\0' ){
 302     zInit = sqlite3_mprintf("");
 303   }else{
 304     if( sqllogglobal.bReuse ){
 305       zInit = sqllogFindFile(zFile);
 306     }else{
 307       zInit = 0;
 308     }
 309     if( zInit==0 ){
 310       int rc;
 311       sqlite3 *copy = 0;
 312       int iDb;
 313
 314       /* Generate a file-name to use for the copy of this database */
 315       iDb = sqllogglobal.iNextDb++;
 316       zInit = sqlite3_mprintf("%s_%02d.db", sqllogglobal.zPrefix, iDb);
 317
 318       /* Create the backup */
 319       assert( sqllogglobal.bRec==0 );
 320       sqllogglobal.bRec = 1;
 321       rc = sqlite3_open(zInit, &copy);
 322       if( rc==SQLITE_OK ){
 323         sqlite3_backup *pBak;
 324         sqlite3_exec(copy, "PRAGMA synchronous = 0", 0, 0, 0);
 325         pBak = sqlite3_backup_init(copy, "main", p->db, zName);
 326         if( pBak ){
 327           sqlite3_backup_step(pBak, -1);
 328           rc = sqlite3_backup_finish(pBak);
 329         }else{
 330           rc = sqlite3_errcode(copy);
 331         }
 332         sqlite3_close(copy);
 333       }
 334       sqllogglobal.bRec = 0;
 335
 336       if( rc==SQLITE_OK ){
 337         /* Write an entry into the database index file */
 338         FILE *fd = fopen(sqllogglobal.zIdx, "a");
 339         if( fd ){
 340           fprintf(fd, "%d %s\n", iDb, zFile);
 341           fclose(fd);
 342         }
 343       }else{
 344         sqlite3_log(rc, "sqllogCopydb(): error backing up database");
 345       }
 346     }
 347   }
 348
 349   if( bLog ){
 350     zFree = sqlite3_mprintf("ATTACH '%q' AS '%q'; -- clock=%d\n",
 351         zInit, zName, sqllogglobal.iClock++
 352     );
 353   }else{
 354     zFree = sqlite3_mprintf("-- Main database is '%q'\n", zInit);
 355   }
 356   fprintf(p->fd, "%s", zFree);
 357   sqlite3_free(zFree);
 358
 359   sqlite3_free(zInit);
 360 }
 361
 362 /*
 363 ** If it is not already open, open the log file for connection *p.
 364 **
 365 ** The SLGlobal.mutex mutex is always held when this function is called.
 366 */
 367 static void sqllogOpenlog(struct SLConn *p){
 368   /* If the log file has not yet been opened, open it now. */
 369   if( p->fd==0 ){
 370     char *zLog;
 371
 372     /* If it is still NULL, have global.zPrefix point to a copy of
 373     ** environment variable $ENVIRONMENT_VARIABLE1_NAME.  */
 374     if( sqllogglobal.zPrefix[0]==0 ){
 375       FILE *fd;
 376       char *zVar = getenv(ENVIRONMENT_VARIABLE1_NAME);
 377       if( zVar==0 || strlen(zVar)+10>=(sizeof(sqllogglobal.zPrefix)) ) return;
 378       sqlite3_snprintf(sizeof(sqllogglobal.zPrefix), sqllogglobal.zPrefix,
 379                         "%s/sqllog_%05d", zVar, getProcessId());
 380       sqlite3_snprintf(sizeof(sqllogglobal.zIdx), sqllogglobal.zIdx,
 381                         "%s.idx", sqllogglobal.zPrefix);
 382       if( getenv(ENVIRONMENT_VARIABLE2_NAME) ){
 383         sqllogglobal.bReuse = atoi(getenv(ENVIRONMENT_VARIABLE2_NAME));
 384       }
 385       fd = fopen(sqllogglobal.zIdx, "w");
 386       if( fd ) fclose(fd);
 387     }
 388
 389     /* Open the log file */
 390     zLog = sqlite3_mprintf("%s_%05d.sql", sqllogglobal.zPrefix, p->iLog);
 391     p->fd = fopen(zLog, "w");
 392     sqlite3_free(zLog);
 393     if( p->fd==0 ){
 394       sqlite3_log(SQLITE_IOERR, "sqllogOpenlog(): Failed to open log file");
 395     }
 396   }
 397 }
 398
 399 /*
 400 ** This function is called if the SQLLOG callback is invoked to report
 401 ** execution of an SQL statement. Parameter p is the connection the statement
 402 ** was executed by and parameter zSql is the text of the statement itself.
 403 */
 404 static void testSqllogStmt(struct SLConn *p, const char *zSql){
 405   const char *zFirst;             /* Pointer to first token in zSql */
 406   int nFirst;                     /* Size of token zFirst in bytes */
 407
 408   sqllogTokenize(zSql, &zFirst, &nFirst);
 409   if( nFirst!=6 || 0!=sqlite3_strnicmp("ATTACH", zFirst, 6) ){
 410     /* Not an ATTACH statement. Write this directly to the log. */
 411     fprintf(p->fd, "%s; -- clock=%d\n", zSql, sqllogglobal.iClock++);
 412   }else{
 413     /* This is an ATTACH statement. Copy the database. */
 414     sqllogCopydb(p, 0, 1);
 415   }
 416 }
 417
 418 /*
 419 ** The database handle passed as the only argument has just been opened.
 420 ** Return true if this module should log initial databases and SQL
 421 ** statements for this connection, or false otherwise.
 422 **
 423 ** If an error occurs, sqlite3_log() is invoked to report it to the user
 424 ** and zero returned.
 425 */
 426 static int sqllogTraceDb(sqlite3 *db){
 427   int bRet = 1;
 428   if( sqllogglobal.bConditional ){
 429     char zFile[SQLLOG_NAMESZ];      /* Attached database name */
 430     int rc = sqllogFindAttached(db, "main", 0, zFile);
 431     if( rc==SQLITE_OK ){
 432       int nFile = strlen(zFile);
 433       if( (SQLLOG_NAMESZ-nFile)<8 ){
 434         sqlite3_log(SQLITE_IOERR,
 435             "sqllogTraceDb(): database name too long (%d bytes)", nFile
 436         );
 437         bRet = 0;
 438       }else{
 439         memcpy(&zFile[nFile], "-sqllog", 8);
 440         bRet = !access(zFile, F_OK);
 441       }
 442     }
 443   }
 444   return bRet;
 445 }
 446
 447 /*
 448 ** The SQLITE_CONFIG_SQLLOG callback registered by sqlite3_init_sqllog().
 449 **
 450 ** The eType parameter has the following values:
 451 **
 452 **    0:  Opening a new database connection.  zSql is the name of the
 453 **        file being opened.  db is a pointer to the newly created database
 454 **        connection.
 455 **
 456 **    1:  An SQL statement has run to completion.  zSql is the text of the
 457 **        SQL statement with all parameters expanded to their actual values.
 458 **
 459 **    2:  Closing a database connection.  zSql is NULL.  The db pointer to
 460 **        the database connection being closed has already been shut down
 461 **        and cannot be used for any further SQL.
 462 **
 463 ** The pCtx parameter is a copy of the pointer that was originally passed
 464 ** into the sqlite3_config(SQLITE_CONFIG_SQLLOG) statement.  In this
 465 ** particular implementation, pCtx is always a pointer to the
 466 ** sqllogglobal global variable define above.
 467 */
 468 static void testSqllog(void *pCtx, sqlite3 *db, const char *zSql, int eType){
 469   struct SLConn *p = 0;
 470   sqlite3_mutex *master = sqlite3_mutex_alloc(SQLITE_MUTEX_STATIC_MASTER);
 471
 472   assert( eType==0 || eType==1 || eType==2 );
 473   assert( (eType==2)==(zSql==0) );
 474
 475   /* This is a database open command. */
 476   if( eType==0 ){
 477     sqlite3_mutex_enter(master);
 478     if( sqllogglobal.mutex==0 ){
 479       sqllogglobal.mutex = sqlite3_mutex_alloc(SQLITE_MUTEX_RECURSIVE);
 480     }
 481     sqlite3_mutex_leave(master);
 482
 483     sqlite3_mutex_enter(sqllogglobal.mutex);
 484     if( sqllogglobal.bRec==0 && sqllogTraceDb(db) ){
 485
 486       sqlite3_mutex_enter(master);
 487       p = &sqllogglobal.aConn[sqllogglobal.nConn++];
 488       p->fd = 0;
 489       p->db = db;
 490       p->iLog = sqllogglobal.iNextLog++;
 491       sqlite3_mutex_leave(master);
 492
 493       /* Open the log and take a copy of the main database file */
 494       sqllogOpenlog(p);
 495       if( p->fd ) sqllogCopydb(p, "main", 0);
 496     }
 497     sqlite3_mutex_leave(sqllogglobal.mutex);
 498   }
 499
 500   else{
 501
 502     int i;
 503     for(i=0; i<sqllogglobal.nConn; i++){
 504       p = &sqllogglobal.aConn[i];
 505       if( p->db==db ) break;
 506     }
 507
 508     /* A database handle close command */
 509     if( eType==2 ){
 510       sqlite3_mutex_enter(master);
 511       if( i<sqllogglobal.nConn ){
 512         if( p->fd ) fclose(p->fd);
 513         p->db = 0;
 514         p->fd = 0;
 515         sqllogglobal.nConn--;
 516       }
 517
 518       if( sqllogglobal.nConn==0 ){
 519         sqlite3_mutex_free(sqllogglobal.mutex);
 520         sqllogglobal.mutex = 0;
 521       }else if( i<sqllogglobal.nConn ){
 522         int nShift = &sqllogglobal.aConn[sqllogglobal.nConn] - p;
 523         if( nShift>0 ){
 524           memmove(p, &p[1], nShift*sizeof(struct SLConn));
 525         }
 526       }
 527       sqlite3_mutex_leave(master);
 528
 529     /* An ordinary SQL command. */
 530     }else if( i<sqllogglobal.nConn && p->fd ){
 531       sqlite3_mutex_enter(sqllogglobal.mutex);
 532       if( sqllogglobal.bRec==0 ){
 533         testSqllogStmt(p, zSql);
 534       }
 535       sqlite3_mutex_leave(sqllogglobal.mutex);
 536     }
 537   }
 538 }
 539
 540 /*
 541 ** This function is called either before sqlite3_initialized() or by it.
 542 ** It checks if the SQLITE_SQLLOG_DIR variable is defined, and if so
 543 ** registers an SQLITE_CONFIG_SQLLOG callback to record the applications
 544 ** database activity.
 545 */
 546 void sqlite3_init_sqllog(void){
 547   if( getenv(ENVIRONMENT_VARIABLE1_NAME) ){
 548     if( SQLITE_OK==sqlite3_config(SQLITE_CONFIG_SQLLOG, testSqllog, 0) ){
 549       memset(&sqllogglobal, 0, sizeof(sqllogglobal));
 550       sqllogglobal.bReuse = 1;
 551       if( getenv(ENVIRONMENT_VARIABLE3_NAME) ){
 552         sqllogglobal.bConditional = 1;
 553       }
 554     }
 555   }
 556 }