ext/misc/vfslog.c

   1 /*
   2 ** 2013-10-09
   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 ** This file contains the implementation of an SQLite vfs wrapper for
  14 ** unix that generates per-database log files of all disk activity.
  15 */
  16
  17 /*
  18 ** This module contains code for a wrapper VFS that causes a log of
  19 ** most VFS calls to be written into a file on disk.
  20 **
  21 ** Each database connection creates a separate log file in the same
  22 ** directory as the original database and named after the original
  23 ** database.  A unique suffix is added to avoid name collisions.
  24 ** Separate log files are used so that concurrent processes do not
  25 ** try to write log operations to the same file at the same instant,
  26 ** resulting in overwritten or comingled log text.
  27 **
  28 ** Each individual log file records operations by a single database
  29 ** connection on both the original database and its associated rollback
  30 ** journal.
  31 **
  32 ** The log files are in the comma-separated-value (CSV) format.  The
  33 ** log files can be imported into an SQLite database using the ".import"
  34 ** command of the SQLite command-line shell for analysis.
  35 **
  36 ** One technique for using this module is to append the text of this
  37 ** module to the end of a standard "sqlite3.c" amalgamation file then
  38 ** add the following compile-time options:
  39 **
  40 **     -DSQLITE_EXTRA_INIT=sqlite3_register_vfslog
  41 **     -DSQLITE_USE_FCNTL_TRACE
  42 **
  43 ** The first compile-time option causes the sqlite3_register_vfslog()
  44 ** function, defined below, to be invoked when SQLite is initialized.
  45 ** That causes this custom VFS to become the default VFS for all
  46 ** subsequent connections.  The SQLITE_USE_FCNTL_TRACE option causes
  47 ** the SQLite core to issue extra sqlite3_file_control() operations
  48 ** with SQLITE_FCNTL_TRACE to give some indication of what is going
  49 ** on in the core.
  50 */
  51
  52 #include "sqlite3.h"
  53 #include <string.h>
  54 #include <assert.h>
  55 #include <stdio.h>
  56 #if SQLITE_OS_UNIX
  57 # include <unistd.h>
  58 #endif
  59
  60 /*
  61 ** Forward declaration of objects used by this utility
  62 */
  63 typedef struct VLogLog VLogLog;
  64 typedef struct VLogVfs VLogVfs;
  65 typedef struct VLogFile VLogFile;
  66
  67 /* There is a pair (an array of size 2) of the following objects for
  68 ** each database file being logged.  The first contains the filename
  69 ** and is used to log I/O with the main database.  The second has
  70 ** a NULL filename and is used to log I/O for the journal.  Both
  71 ** out pointers are the same.
  72 */
  73 struct VLogLog {
  74   VLogLog *pNext;                 /* Next in a list of all active logs */
  75   VLogLog **ppPrev;               /* Pointer to this in the list */
  76   int nRef;                       /* Number of references to this object */
  77   int nFilename;                  /* Length of zFilename in bytes */
  78   char *zFilename;                /* Name of database file.  NULL for journal */
  79   FILE *out;                      /* Write information here */
  80 };
  81
  82 struct VLogVfs {
  83   sqlite3_vfs base;               /* VFS methods */
  84   sqlite3_vfs *pVfs;              /* Parent VFS */
  85 };
  86
  87 struct VLogFile {
  88   sqlite3_file base;              /* IO methods */
  89   sqlite3_file *pReal;            /* Underlying file handle */
  90   VLogLog *pLog;                  /* The log file for this file */
  91 };
  92
  93 #define REALVFS(p) (((VLogVfs*)(p))->pVfs)
  94
  95 /*
  96 ** Methods for VLogFile
  97 */
  98 static int vlogClose(sqlite3_file*);
  99 static int vlogRead(sqlite3_file*, void*, int iAmt, sqlite3_int64 iOfst);
 100 static int vlogWrite(sqlite3_file*,const void*,int iAmt, sqlite3_int64 iOfst);
 101 static int vlogTruncate(sqlite3_file*, sqlite3_int64 size);
 102 static int vlogSync(sqlite3_file*, int flags);
 103 static int vlogFileSize(sqlite3_file*, sqlite3_int64 *pSize);
 104 static int vlogLock(sqlite3_file*, int);
 105 static int vlogUnlock(sqlite3_file*, int);
 106 static int vlogCheckReservedLock(sqlite3_file*, int *pResOut);
 107 static int vlogFileControl(sqlite3_file*, int op, void *pArg);
 108 static int vlogSectorSize(sqlite3_file*);
 109 static int vlogDeviceCharacteristics(sqlite3_file*);
 110
 111 /*
 112 ** Methods for VLogVfs
 113 */
 114 static int vlogOpen(sqlite3_vfs*, const char *, sqlite3_file*, int , int *);
 115 static int vlogDelete(sqlite3_vfs*, const char *zName, int syncDir);
 116 static int vlogAccess(sqlite3_vfs*, const char *zName, int flags, int *);
 117 static int vlogFullPathname(sqlite3_vfs*, const char *zName, int, char *zOut);
 118 static void *vlogDlOpen(sqlite3_vfs*, const char *zFilename);
 119 static void vlogDlError(sqlite3_vfs*, int nByte, char *zErrMsg);
 120 static void (*vlogDlSym(sqlite3_vfs *pVfs, void *p, const char*zSym))(void);
 121 static void vlogDlClose(sqlite3_vfs*, void*);
 122 static int vlogRandomness(sqlite3_vfs*, int nByte, char *zOut);
 123 static int vlogSleep(sqlite3_vfs*, int microseconds);
 124 static int vlogCurrentTime(sqlite3_vfs*, double*);
 125 static int vlogGetLastError(sqlite3_vfs*, int, char *);
 126 static int vlogCurrentTimeInt64(sqlite3_vfs*, sqlite3_int64*);
 127
 128 static VLogVfs vlog_vfs = {
 129   {
 130     1,                            /* iVersion */
 131     0,                            /* szOsFile (set by register_vlog()) */
 132     1024,                         /* mxPathname */
 133     0,                            /* pNext */
 134     "vfslog",                     /* zName */
 135     0,                            /* pAppData */
 136     vlogOpen,                     /* xOpen */
 137     vlogDelete,                   /* xDelete */
 138     vlogAccess,                   /* xAccess */
 139     vlogFullPathname,             /* xFullPathname */
 140     vlogDlOpen,                   /* xDlOpen */
 141     vlogDlError,                  /* xDlError */
 142     vlogDlSym,                    /* xDlSym */
 143     vlogDlClose,                  /* xDlClose */
 144     vlogRandomness,               /* xRandomness */
 145     vlogSleep,                    /* xSleep */
 146     vlogCurrentTime,              /* xCurrentTime */
 147     vlogGetLastError,             /* xGetLastError */
 148     vlogCurrentTimeInt64          /* xCurrentTimeInt64 */
 149   },
 150   0
 151 };
 152
 153 static sqlite3_io_methods vlog_io_methods = {
 154   1,                              /* iVersion */
 155   vlogClose,                      /* xClose */
 156   vlogRead,                       /* xRead */
 157   vlogWrite,                      /* xWrite */
 158   vlogTruncate,                   /* xTruncate */
 159   vlogSync,                       /* xSync */
 160   vlogFileSize,                   /* xFileSize */
 161   vlogLock,                       /* xLock */
 162   vlogUnlock,                     /* xUnlock */
 163   vlogCheckReservedLock,          /* xCheckReservedLock */
 164   vlogFileControl,                /* xFileControl */
 165   vlogSectorSize,                 /* xSectorSize */
 166   vlogDeviceCharacteristics,      /* xDeviceCharacteristics */
 167   0,                              /* xShmMap */
 168   0,                              /* xShmLock */
 169   0,                              /* xShmBarrier */
 170   0                               /* xShmUnmap */
 171 };
 172
 173 #if SQLITE_OS_UNIX && !defined(NO_GETTOD)
 174 #include <sys/time.h>
 175 static sqlite3_uint64 vlog_time(){
 176   struct timeval sTime;
 177   gettimeofday(&sTime, 0);
 178   return sTime.tv_usec + (sqlite3_uint64)sTime.tv_sec * 1000000;
 179 }
 180 #elif SQLITE_OS_WIN
 181 #include <windows.h>
 182 #include <time.h>
 183 static sqlite3_uint64 vlog_time(){
 184   FILETIME ft;
 185   sqlite3_uint64 u64time = 0;
 186
 187   GetSystemTimeAsFileTime(&ft);
 188
 189   u64time |= ft.dwHighDateTime;
 190   u64time <<= 32;
 191   u64time |= ft.dwLowDateTime;
 192
 193   /* ft is 100-nanosecond intervals, we want microseconds */
 194   return u64time /(sqlite3_uint64)10;
 195 }
 196 #else
 197 static sqlite3_uint64 vlog_time(){
 198   return 0;
 199 }
 200 #endif
 201
 202
 203 /*
 204 ** Write a message to the log file
 205 */
 206 static void vlogLogPrint(
 207   VLogLog *pLog,                 /* The log file to write into */
 208   sqlite3_int64 tStart,            /* Start time of system call */
 209   sqlite3_int64 tElapse,           /* Elapse time of system call */
 210   const char *zOp,                 /* Type of system call */
 211   sqlite3_int64 iArg1,             /* First argument */
 212   sqlite3_int64 iArg2,             /* Second argument */
 213   const char *zArg3,               /* Third argument */
 214   int iRes                         /* Result */
 215 ){
 216   char z1[40], z2[40], z3[2000];
 217   if( pLog==0 ) return;
 218   if( iArg1>=0 ){
 219     sqlite3_snprintf(sizeof(z1), z1, "%lld", iArg1);
 220   }else{
 221     z1[0] = 0;
 222   }
 223   if( iArg2>=0 ){
 224     sqlite3_snprintf(sizeof(z2), z2, "%lld", iArg2);
 225   }else{
 226     z2[0] = 0;
 227   }
 228   if( zArg3 ){
 229     sqlite3_snprintf(sizeof(z3), z3, "\"%.*w\"", sizeof(z3)-4, zArg3);
 230   }else{
 231     z3[0] = 0;
 232   }
 233   fprintf(pLog->out,"%lld,%lld,%s,%d,%s,%s,%s,%d\n",
 234       tStart, tElapse, zOp, pLog->zFilename==0, z1, z2, z3, iRes);
 235 }
 236
 237 /*
 238 ** List of all active log connections.  Protected by the master mutex.
 239 */
 240 static VLogLog *allLogs = 0;
 241
 242 /*
 243 ** Close a VLogLog object
 244 */
 245 static void vlogLogClose(VLogLog *p){
 246   if( p ){
 247     sqlite3_mutex *pMutex;
 248     p->nRef--;
 249     if( p->nRef>0 || p->zFilename==0 ) return;
 250     pMutex = sqlite3_mutex_alloc(SQLITE_MUTEX_STATIC_MASTER);
 251     sqlite3_mutex_enter(pMutex);
 252     *p->ppPrev = p->pNext;
 253     if( p->pNext ) p->pNext->ppPrev = p->ppPrev;
 254     sqlite3_mutex_leave(pMutex);
 255     fclose(p->out);
 256     sqlite3_free(p);
 257   }
 258 }
 259
 260 /*
 261 ** Open a VLogLog object on the given file
 262 */
 263 static VLogLog *vlogLogOpen(const char *zFilename){
 264   int nName = (int)strlen(zFilename);
 265   int isJournal = 0;
 266   sqlite3_mutex *pMutex;
 267   VLogLog *pLog, *pTemp;
 268   sqlite3_int64 tNow = 0;
 269   if( nName>4 && strcmp(zFilename+nName-4,"-wal")==0 ){
 270     return 0;  /* Do not log wal files */
 271   }else
 272   if( nName>8 && strcmp(zFilename+nName-8,"-journal")==0 ){
 273     nName -= 8;
 274     isJournal = 1;
 275   }else if( nName>12
 276          && sqlite3_strglob("-mj??????9??", zFilename+nName-12)==0 ){
 277     return 0;  /* Do not log master journal files */
 278   }
 279   pTemp = sqlite3_malloc64( sizeof(*pLog)*2 + nName + 60 );
 280   if( pTemp==0 ) return 0;
 281   pMutex = sqlite3_mutex_alloc(SQLITE_MUTEX_STATIC_MASTER);
 282   sqlite3_mutex_enter(pMutex);
 283   for(pLog=allLogs; pLog; pLog=pLog->pNext){
 284     if( pLog->nFilename==nName && !memcmp(pLog->zFilename, zFilename, nName) ){
 285       break;
 286     }
 287   }
 288   if( pLog==0 ){
 289     pLog = pTemp;
 290     pTemp = 0;
 291     memset(pLog, 0, sizeof(*pLog)*2);
 292     pLog->zFilename = (char*)&pLog[2];
 293     tNow = vlog_time();
 294     sqlite3_snprintf(nName+60, pLog->zFilename, "%.*s-debuglog-%lld",
 295                      nName, zFilename, tNow);
 296     pLog->out = fopen(pLog->zFilename, "a");
 297     if( pLog->out==0 ){
 298       sqlite3_mutex_leave(pMutex);
 299       sqlite3_free(pLog);
 300       return 0;
 301     }
 302     pLog->nFilename = nName;
 303     pLog[1].out = pLog[0].out;
 304     pLog->ppPrev = &allLogs;
 305     if( allLogs ) allLogs->ppPrev = &pLog->pNext;
 306     pLog->pNext = allLogs;
 307     allLogs = pLog;
 308   }
 309   sqlite3_mutex_leave(pMutex);
 310   if( pTemp ){
 311     sqlite3_free(pTemp);
 312   }else{
 313 #if SQLITE_OS_UNIX
 314     char zHost[200];
 315     zHost[0] = 0;
 316     gethostname(zHost, sizeof(zHost)-1);
 317     zHost[sizeof(zHost)-1] = 0;
 318     vlogLogPrint(pLog, tNow, 0, "IDENT", getpid(), -1, zHost, 0);
 319 #endif
 320   }
 321   if( pLog && isJournal ) pLog++;
 322   pLog->nRef++;
 323   return pLog;
 324 }
 325
 326
 327 /*
 328 ** Close an vlog-file.
 329 */
 330 static int vlogClose(sqlite3_file *pFile){
 331   sqlite3_uint64 tStart, tElapse;
 332   int rc = SQLITE_OK;
 333   VLogFile *p = (VLogFile *)pFile;
 334
 335   tStart = vlog_time();
 336   if( p->pReal->pMethods ){
 337     rc = p->pReal->pMethods->xClose(p->pReal);
 338   }
 339   tElapse = vlog_time() - tStart;
 340   vlogLogPrint(p->pLog, tStart, tElapse, "CLOSE", -1, -1, 0, rc);
 341   vlogLogClose(p->pLog);
 342   return rc;
 343 }
 344
 345 /*
 346 ** Compute signature for a block of content.
 347 **
 348 ** For blocks of 16 or fewer bytes, the signature is just a hex dump of
 349 ** the entire block.
 350 **
 351 ** For blocks of more than 16 bytes, the signature is a hex dump of the
 352 ** first 8 bytes followed by a 64-bit has of the entire block.
 353 */
 354 static void vlogSignature(unsigned char *p, int n, char *zCksum){
 355   unsigned int s0 = 0, s1 = 0;
 356   unsigned int *pI;
 357   int i;
 358   if( n<=16 ){
 359     for(i=0; i<n; i++) sqlite3_snprintf(3, zCksum+i*2, "%02x", p[i]);
 360   }else{
 361     pI = (unsigned int*)p;
 362     for(i=0; i<n-7; i+=8){
 363       s0 += pI[0] + s1;
 364       s1 += pI[1] + s0;
 365       pI += 2;
 366     }
 367     for(i=0; i<8; i++) sqlite3_snprintf(3, zCksum+i*2, "%02x", p[i]);
 368     sqlite3_snprintf(18, zCksum+i*2, "-%08x%08x", s0, s1);
 369   }
 370 }
 371
 372 /*
 373 ** Convert a big-endian 32-bit integer into a native integer
 374 */
 375 static int bigToNative(const unsigned char *x){
 376   return (x[0]<<24) + (x[1]<<16) + (x[2]<<8) + x[3];
 377 }
 378
 379 /*
 380 ** Read data from an vlog-file.
 381 */
 382 static int vlogRead(
 383   sqlite3_file *pFile,
 384   void *zBuf,
 385   int iAmt,
 386   sqlite_int64 iOfst
 387 ){
 388   int rc;
 389   sqlite3_uint64 tStart, tElapse;
 390   VLogFile *p = (VLogFile *)pFile;
 391   char zSig[40];
 392
 393   tStart = vlog_time();
 394   rc = p->pReal->pMethods->xRead(p->pReal, zBuf, iAmt, iOfst);
 395   tElapse = vlog_time() - tStart;
 396   if( rc==SQLITE_OK ){
 397     vlogSignature(zBuf, iAmt, zSig);
 398   }else{
 399     zSig[0] = 0;
 400   }
 401   vlogLogPrint(p->pLog, tStart, tElapse, "READ", iAmt, iOfst, zSig, rc);
 402   if( rc==SQLITE_OK
 403    && p->pLog
 404    && p->pLog->zFilename
 405    && iOfst<=24
 406    && iOfst+iAmt>=28
 407   ){
 408     unsigned char *x = ((unsigned char*)zBuf)+(24-iOfst);
 409     unsigned iCtr, nFree = -1;
 410     char *zFree = 0;
 411     char zStr[12];
 412     iCtr = bigToNative(x);
 413     if( iOfst+iAmt>=40 ){
 414       zFree = zStr;
 415       sqlite3_snprintf(sizeof(zStr), zStr, "%d", bigToNative(x+8));
 416       nFree = bigToNative(x+12);
 417     }
 418     vlogLogPrint(p->pLog, tStart, 0, "CHNGCTR-READ", iCtr, nFree, zFree, 0);
 419   }
 420   return rc;
 421 }
 422
 423 /*
 424 ** Write data to an vlog-file.
 425 */
 426 static int vlogWrite(
 427   sqlite3_file *pFile,
 428   const void *z,
 429   int iAmt,
 430   sqlite_int64 iOfst
 431 ){
 432   int rc;
 433   sqlite3_uint64 tStart, tElapse;
 434   VLogFile *p = (VLogFile *)pFile;
 435   char zSig[40];
 436
 437   tStart = vlog_time();
 438   vlogSignature((unsigned char*)z, iAmt, zSig);
 439   rc = p->pReal->pMethods->xWrite(p->pReal, z, iAmt, iOfst);
 440   tElapse = vlog_time() - tStart;
 441   vlogLogPrint(p->pLog, tStart, tElapse, "WRITE", iAmt, iOfst, zSig, rc);
 442   if( rc==SQLITE_OK
 443    && p->pLog
 444    && p->pLog->zFilename
 445    && iOfst<=24
 446    && iOfst+iAmt>=28
 447   ){
 448     unsigned char *x = ((unsigned char*)z)+(24-iOfst);
 449     unsigned iCtr, nFree = -1;
 450     char *zFree = 0;
 451     char zStr[12];
 452     iCtr = bigToNative(x);
 453     if( iOfst+iAmt>=40 ){
 454       zFree = zStr;
 455       sqlite3_snprintf(sizeof(zStr), zStr, "%d", bigToNative(x+8));
 456       nFree = bigToNative(x+12);
 457     }
 458     vlogLogPrint(p->pLog, tStart, 0, "CHNGCTR-WRITE", iCtr, nFree, zFree, 0);
 459   }
 460   return rc;
 461 }
 462
 463 /*
 464 ** Truncate an vlog-file.
 465 */
 466 static int vlogTruncate(sqlite3_file *pFile, sqlite_int64 size){
 467   int rc;
 468   sqlite3_uint64 tStart, tElapse;
 469   VLogFile *p = (VLogFile *)pFile;
 470   tStart = vlog_time();
 471   rc = p->pReal->pMethods->xTruncate(p->pReal, size);
 472   tElapse = vlog_time() - tStart;
 473   vlogLogPrint(p->pLog, tStart, tElapse, "TRUNCATE", size, -1, 0, rc);
 474   return rc;
 475 }
 476
 477 /*
 478 ** Sync an vlog-file.
 479 */
 480 static int vlogSync(sqlite3_file *pFile, int flags){
 481   int rc;
 482   sqlite3_uint64 tStart, tElapse;
 483   VLogFile *p = (VLogFile *)pFile;
 484   tStart = vlog_time();
 485   rc = p->pReal->pMethods->xSync(p->pReal, flags);
 486   tElapse = vlog_time() - tStart;
 487   vlogLogPrint(p->pLog, tStart, tElapse, "SYNC", flags, -1, 0, rc);
 488   return rc;
 489 }
 490
 491 /*
 492 ** Return the current file-size of an vlog-file.
 493 */
 494 static int vlogFileSize(sqlite3_file *pFile, sqlite_int64 *pSize){
 495   int rc;
 496   sqlite3_uint64 tStart, tElapse;
 497   VLogFile *p = (VLogFile *)pFile;
 498   tStart = vlog_time();
 499   rc = p->pReal->pMethods->xFileSize(p->pReal, pSize);
 500   tElapse = vlog_time() - tStart;
 501   vlogLogPrint(p->pLog, tStart, tElapse, "FILESIZE", *pSize, -1, 0, rc);
 502   return rc;
 503 }
 504
 505 /*
 506 ** Lock an vlog-file.
 507 */
 508 static int vlogLock(sqlite3_file *pFile, int eLock){
 509   int rc;
 510   sqlite3_uint64 tStart, tElapse;
 511   VLogFile *p = (VLogFile *)pFile;
 512   tStart = vlog_time();
 513   rc = p->pReal->pMethods->xLock(p->pReal, eLock);
 514   tElapse = vlog_time() - tStart;
 515   vlogLogPrint(p->pLog, tStart, tElapse, "LOCK", eLock, -1, 0, rc);
 516   return rc;
 517 }
 518
 519 /*
 520 ** Unlock an vlog-file.
 521 */
 522 static int vlogUnlock(sqlite3_file *pFile, int eLock){
 523   int rc;
 524   sqlite3_uint64 tStart;
 525   VLogFile *p = (VLogFile *)pFile;
 526   tStart = vlog_time();
 527   vlogLogPrint(p->pLog, tStart, 0, "UNLOCK", eLock, -1, 0, 0);
 528   rc = p->pReal->pMethods->xUnlock(p->pReal, eLock);
 529   return rc;
 530 }
 531
 532 /*
 533 ** Check if another file-handle holds a RESERVED lock on an vlog-file.
 534 */
 535 static int vlogCheckReservedLock(sqlite3_file *pFile, int *pResOut){
 536   int rc;
 537   sqlite3_uint64 tStart, tElapse;
 538   VLogFile *p = (VLogFile *)pFile;
 539   tStart = vlog_time();
 540   rc = p->pReal->pMethods->xCheckReservedLock(p->pReal, pResOut);
 541   tElapse = vlog_time() - tStart;
 542   vlogLogPrint(p->pLog, tStart, tElapse, "CHECKRESERVEDLOCK",
 543                  *pResOut, -1, "", rc);
 544   return rc;
 545 }
 546
 547 /*
 548 ** File control method. For custom operations on an vlog-file.
 549 */
 550 static int vlogFileControl(sqlite3_file *pFile, int op, void *pArg){
 551   VLogFile *p = (VLogFile *)pFile;
 552   sqlite3_uint64 tStart, tElapse;
 553   int rc;
 554   tStart = vlog_time();
 555   rc = p->pReal->pMethods->xFileControl(p->pReal, op, pArg);
 556   if( op==SQLITE_FCNTL_VFSNAME && rc==SQLITE_OK ){
 557     *(char**)pArg = sqlite3_mprintf("vlog/%z", *(char**)pArg);
 558   }
 559   tElapse = vlog_time() - tStart;
 560   if( op==SQLITE_FCNTL_TRACE ){
 561     vlogLogPrint(p->pLog, tStart, tElapse, "TRACE", op, -1, pArg, rc);
 562   }else if( op==SQLITE_FCNTL_PRAGMA ){
 563     const char **azArg = (const char **)pArg;
 564     vlogLogPrint(p->pLog, tStart, tElapse, "FILECONTROL", op, -1, azArg[1], rc);
 565   }else if( op==SQLITE_FCNTL_SIZE_HINT ){
 566     sqlite3_int64 sz = *(sqlite3_int64*)pArg;
 567     vlogLogPrint(p->pLog, tStart, tElapse, "FILECONTROL", op, sz, 0, rc);
 568   }else{
 569     vlogLogPrint(p->pLog, tStart, tElapse, "FILECONTROL", op, -1, 0, rc);
 570   }
 571   return rc;
 572 }
 573
 574 /*
 575 ** Return the sector-size in bytes for an vlog-file.
 576 */
 577 static int vlogSectorSize(sqlite3_file *pFile){
 578   int rc;
 579   sqlite3_uint64 tStart, tElapse;
 580   VLogFile *p = (VLogFile *)pFile;
 581   tStart = vlog_time();
 582   rc = p->pReal->pMethods->xSectorSize(p->pReal);
 583   tElapse = vlog_time() - tStart;
 584   vlogLogPrint(p->pLog, tStart, tElapse, "SECTORSIZE", -1, -1, 0, rc);
 585   return rc;
 586 }
 587
 588 /*
 589 ** Return the device characteristic flags supported by an vlog-file.
 590 */
 591 static int vlogDeviceCharacteristics(sqlite3_file *pFile){
 592   int rc;
 593   sqlite3_uint64 tStart, tElapse;
 594   VLogFile *p = (VLogFile *)pFile;
 595   tStart = vlog_time();
 596   rc = p->pReal->pMethods->xDeviceCharacteristics(p->pReal);
 597   tElapse = vlog_time() - tStart;
 598   vlogLogPrint(p->pLog, tStart, tElapse, "DEVCHAR", -1, -1, 0, rc);
 599   return rc;
 600 }
 601
 602
 603 /*
 604 ** Open an vlog file handle.
 605 */
 606 static int vlogOpen(
 607   sqlite3_vfs *pVfs,
 608   const char *zName,
 609   sqlite3_file *pFile,
 610   int flags,
 611   int *pOutFlags
 612 ){
 613   int rc;
 614   sqlite3_uint64 tStart, tElapse;
 615   sqlite3_int64 iArg2;
 616   VLogFile *p = (VLogFile*)pFile;
 617
 618   p->pReal = (sqlite3_file*)&p[1];
 619   if( (flags & (SQLITE_OPEN_MAIN_DB|SQLITE_OPEN_MAIN_JOURNAL))!=0 ){
 620     p->pLog = vlogLogOpen(zName);
 621   }else{
 622     p->pLog = 0;
 623   }
 624   tStart = vlog_time();
 625   rc = REALVFS(pVfs)->xOpen(REALVFS(pVfs), zName, p->pReal, flags, pOutFlags);
 626   tElapse = vlog_time() - tStart;
 627   iArg2 = pOutFlags ? *pOutFlags : -1;
 628   vlogLogPrint(p->pLog, tStart, tElapse, "OPEN", flags, iArg2, 0, rc);
 629   if( rc==SQLITE_OK ){
 630     pFile->pMethods = &vlog_io_methods;
 631   }else{
 632     if( p->pLog ) vlogLogClose(p->pLog);
 633     p->pLog = 0;
 634   }
 635   return rc;
 636 }
 637
 638 /*
 639 ** Delete the file located at zPath. If the dirSync argument is true,
 640 ** ensure the file-system modifications are synced to disk before
 641 ** returning.
 642 */
 643 static int vlogDelete(sqlite3_vfs *pVfs, const char *zPath, int dirSync){
 644   int rc;
 645   sqlite3_uint64 tStart, tElapse;
 646   VLogLog *pLog;
 647   tStart = vlog_time();
 648   rc = REALVFS(pVfs)->xDelete(REALVFS(pVfs), zPath, dirSync);
 649   tElapse = vlog_time() - tStart;
 650   pLog = vlogLogOpen(zPath);
 651   vlogLogPrint(pLog, tStart, tElapse, "DELETE", dirSync, -1, 0, rc);
 652   vlogLogClose(pLog);
 653   return rc;
 654 }
 655
 656 /*
 657 ** Test for access permissions. Return true if the requested permission
 658 ** is available, or false otherwise.
 659 */
 660 static int vlogAccess(
 661   sqlite3_vfs *pVfs,
 662   const char *zPath,
 663   int flags,
 664   int *pResOut
 665 ){
 666   int rc;
 667   sqlite3_uint64 tStart, tElapse;
 668   VLogLog *pLog;
 669   tStart = vlog_time();
 670   rc = REALVFS(pVfs)->xAccess(REALVFS(pVfs), zPath, flags, pResOut);
 671   tElapse = vlog_time() - tStart;
 672   pLog = vlogLogOpen(zPath);
 673   vlogLogPrint(pLog, tStart, tElapse, "ACCESS", flags, *pResOut, 0, rc);
 674   vlogLogClose(pLog);
 675   return rc;
 676 }
 677
 678 /*
 679 ** Populate buffer zOut with the full canonical pathname corresponding
 680 ** to the pathname in zPath. zOut is guaranteed to point to a buffer
 681 ** of at least (INST_MAX_PATHNAME+1) bytes.
 682 */
 683 static int vlogFullPathname(
 684   sqlite3_vfs *pVfs,
 685   const char *zPath,
 686   int nOut,
 687   char *zOut
 688 ){
 689   return REALVFS(pVfs)->xFullPathname(REALVFS(pVfs), zPath, nOut, zOut);
 690 }
 691
 692 /*
 693 ** Open the dynamic library located at zPath and return a handle.
 694 */
 695 static void *vlogDlOpen(sqlite3_vfs *pVfs, const char *zPath){
 696   return REALVFS(pVfs)->xDlOpen(REALVFS(pVfs), zPath);
 697 }
 698
 699 /*
 700 ** Populate the buffer zErrMsg (size nByte bytes) with a human readable
 701 ** utf-8 string describing the most recent error encountered associated
 702 ** with dynamic libraries.
 703 */
 704 static void vlogDlError(sqlite3_vfs *pVfs, int nByte, char *zErrMsg){
 705   REALVFS(pVfs)->xDlError(REALVFS(pVfs), nByte, zErrMsg);
 706 }
 707
 708 /*
 709 ** Return a pointer to the symbol zSymbol in the dynamic library pHandle.
 710 */
 711 static void (*vlogDlSym(sqlite3_vfs *pVfs, void *p, const char *zSym))(void){
 712   return REALVFS(pVfs)->xDlSym(REALVFS(pVfs), p, zSym);
 713 }
 714
 715 /*
 716 ** Close the dynamic library handle pHandle.
 717 */
 718 static void vlogDlClose(sqlite3_vfs *pVfs, void *pHandle){
 719   REALVFS(pVfs)->xDlClose(REALVFS(pVfs), pHandle);
 720 }
 721
 722 /*
 723 ** Populate the buffer pointed to by zBufOut with nByte bytes of
 724 ** random data.
 725 */
 726 static int vlogRandomness(sqlite3_vfs *pVfs, int nByte, char *zBufOut){
 727   return REALVFS(pVfs)->xRandomness(REALVFS(pVfs), nByte, zBufOut);
 728 }
 729
 730 /*
 731 ** Sleep for nMicro microseconds. Return the number of microseconds
 732 ** actually slept.
 733 */
 734 static int vlogSleep(sqlite3_vfs *pVfs, int nMicro){
 735   return REALVFS(pVfs)->xSleep(REALVFS(pVfs), nMicro);
 736 }
 737
 738 /*
 739 ** Return the current time as a Julian Day number in *pTimeOut.
 740 */
 741 static int vlogCurrentTime(sqlite3_vfs *pVfs, double *pTimeOut){
 742   return REALVFS(pVfs)->xCurrentTime(REALVFS(pVfs), pTimeOut);
 743 }
 744
 745 static int vlogGetLastError(sqlite3_vfs *pVfs, int a, char *b){
 746   return REALVFS(pVfs)->xGetLastError(REALVFS(pVfs), a, b);
 747 }
 748 static int vlogCurrentTimeInt64(sqlite3_vfs *pVfs, sqlite3_int64 *p){
 749   return REALVFS(pVfs)->xCurrentTimeInt64(REALVFS(pVfs), p);
 750 }
 751
 752 /*
 753 ** Register debugvfs as the default VFS for this process.
 754 */
 755 int sqlite3_register_vfslog(const char *zArg){
 756   vlog_vfs.pVfs = sqlite3_vfs_find(0);
 757   if( vlog_vfs.pVfs==0 ) return SQLITE_ERROR;
 758   vlog_vfs.base.szOsFile = sizeof(VLogFile) + vlog_vfs.pVfs->szOsFile;
 759   return sqlite3_vfs_register(&vlog_vfs.base, 1);
 760 }