OLD | NEW |
(Empty) | |
| 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, ©); |
| 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 } |
OLD | NEW |