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 |