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>
getProcessId(void)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 */
sqllog_isspace(char c)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 */
sqllogTokenize(const char * z,const char ** pz,int * pn)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 */
sqllogFindFile(const char * zFile)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
sqllogFindAttached(sqlite3 * db,const char * zSearch,char * zName,char * zFile)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 */
sqllogCopydb(struct SLConn * p,const char * zSearch,int bLog)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, ©);
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 */
sqllogOpenlog(struct SLConn * p)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 */
testSqllogStmt(struct SLConn * p,const char * zSql)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 */
sqllogTraceDb(sqlite3 * db)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 */
testSqllog(void * pCtx,sqlite3 * db,const char * zSql,int eType)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 */
sqlite3_init_sqllog(void)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 }
557