test_sqllog.c 16 KB

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