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