src/test_vfstrace.c

   1 /*
   2 ** 2011 March 16
   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 code implements a VFS shim that writes diagnostic
  14 ** output for each VFS call, similar to "strace".
  15 **
  16 ** USAGE:
  17 **
  18 ** This source file exports a single symbol which is the name of a
  19 ** function:
  20 **
  21 **   int vfstrace_register(
  22 **     const char *zTraceName,         // Name of the newly constructed VFS
  23 **     const char *zOldVfsName,        // Name of the underlying VFS
  24 **     int (*xOut)(const char*,void*), // Output routine.  ex: fputs
  25 **     void *pOutArg,                  // 2nd argument to xOut.  ex: stderr
  26 **     int makeDefault                 // Make the new VFS the default
  27 **   );
  28 **
  29 ** Applications that want to trace their VFS usage must provide a callback
  30 ** function with this prototype:
  31 **
  32 **   int traceOutput(const char *zMessage, void *pAppData);
  33 **
  34 ** This function will "output" the trace messages, where "output" can
  35 ** mean different things to different applications.  The traceOutput function
  36 ** for the command-line shell (see shell.c) is "fputs" from the standard
  37 ** library, which means that all trace output is written on the stream
  38 ** specified by the second argument.  In the case of the command-line shell
  39 ** the second argument is stderr.  Other applications might choose to output
  40 ** trace information to a file, over a socket, or write it into a buffer.
  41 **
  42 ** The vfstrace_register() function creates a new "shim" VFS named by
  43 ** the zTraceName parameter.  A "shim" VFS is an SQLite backend that does
  44 ** not really perform the duties of a true backend, but simply filters or
  45 ** interprets VFS calls before passing them off to another VFS which does
  46 ** the actual work.  In this case the other VFS - the one that does the
  47 ** real work - is identified by the second parameter, zOldVfsName.  If
  48 ** the 2nd parameter is NULL then the default VFS is used.  The common
  49 ** case is for the 2nd parameter to be NULL.
  50 **
  51 ** The third and fourth parameters are the pointer to the output function
  52 ** and the second argument to the output function.  For the SQLite
  53 ** command-line shell, when the -vfstrace option is used, these parameters
  54 ** are fputs and stderr, respectively.
  55 **
  56 ** The fifth argument is true (non-zero) to cause the newly created VFS
  57 ** to become the default VFS.  The common case is for the fifth parameter
  58 ** to be true.
  59 **
  60 ** The call to vfstrace_register() simply creates the shim VFS that does
  61 ** tracing.  The application must also arrange to use the new VFS for
  62 ** all database connections that are created and for which tracing is
  63 ** desired.  This can be done by specifying the trace VFS using URI filename
  64 ** notation, or by specifying the trace VFS as the 4th parameter to
  65 ** sqlite3_open_v2() or by making the trace VFS be the default (by setting
  66 ** the 5th parameter of vfstrace_register() to 1).
  67 **
  68 **
  69 ** ENABLING VFSTRACE IN A COMMAND-LINE SHELL
  70 **
  71 ** The SQLite command line shell implemented by the shell.c source file
  72 ** can be used with this module.  To compile in -vfstrace support, first
  73 ** gather this file (test_vfstrace.c), the shell source file (shell.c),
  74 ** and the SQLite amalgamation source files (sqlite3.c, sqlite3.h) into
  75 ** the working directory.  Then compile using a command like the following:
  76 **
  77 **    gcc -o sqlite3 -Os -I. -DSQLITE_ENABLE_VFSTRACE \
  78 **        -DSQLITE_THREADSAFE=0 -DSQLITE_ENABLE_FTS3 -DSQLITE_ENABLE_RTREE \
  79 **        -DHAVE_READLINE -DHAVE_USLEEP=1 \
  80 **        shell.c test_vfstrace.c sqlite3.c -ldl -lreadline -lncurses
  81 **
  82 ** The gcc command above works on Linux and provides (in addition to the
  83 ** -vfstrace option) support for FTS3 and FTS4, RTREE, and command-line
  84 ** editing using the readline library.  The command-line shell does not
  85 ** use threads so we added -DSQLITE_THREADSAFE=0 just to make the code
  86 ** run a little faster.   For compiling on a Mac, you'll probably need
  87 ** to omit the -DHAVE_READLINE, the -lreadline, and the -lncurses options.
  88 ** The compilation could be simplified to just this:
  89 **
  90 **    gcc -DSQLITE_ENABLE_VFSTRACE \
  91 **         shell.c test_vfstrace.c sqlite3.c -ldl -lpthread
  92 **
  93 ** In this second example, all unnecessary options have been removed
  94 ** Note that since the code is now threadsafe, we had to add the -lpthread
  95 ** option to pull in the pthreads library.
  96 **
  97 ** To cross-compile for windows using MinGW, a command like this might
  98 ** work:
  99 **
 100 **    /opt/mingw/bin/i386-mingw32msvc-gcc -o sqlite3.exe -Os -I \
 101 **         -DSQLITE_THREADSAFE=0 -DSQLITE_ENABLE_VFSTRACE \
 102 **         shell.c test_vfstrace.c sqlite3.c
 103 **
 104 ** Similar compiler commands will work on different systems.  The key
 105 ** invariants are (1) you must have -DSQLITE_ENABLE_VFSTRACE so that
 106 ** the shell.c source file will know to include the -vfstrace command-line
 107 ** option and (2) you must compile and link the three source files
 108 ** shell,c, test_vfstrace.c, and sqlite3.c.
 109 */
 110 #include <stdlib.h>
 111 #include <string.h>
 112 #include "sqlite3.h"
 113
 114 /*
 115 ** An instance of this structure is attached to the each trace VFS to
 116 ** provide auxiliary information.
 117 */
 118 typedef struct vfstrace_info vfstrace_info;
 119 struct vfstrace_info {
 120   sqlite3_vfs *pRootVfs;              /* The underlying real VFS */
 121   int (*xOut)(const char*, void*);    /* Send output here */
 122   void *pOutArg;                      /* First argument to xOut */
 123   const char *zVfsName;               /* Name of this trace-VFS */
 124   sqlite3_vfs *pTraceVfs;             /* Pointer back to the trace VFS */
 125 };
 126
 127 /*
 128 ** The sqlite3_file object for the trace VFS
 129 */
 130 typedef struct vfstrace_file vfstrace_file;
 131 struct vfstrace_file {
 132   sqlite3_file base;        /* Base class.  Must be first */
 133   vfstrace_info *pInfo;     /* The trace-VFS to which this file belongs */
 134   const char *zFName;       /* Base name of the file */
 135   sqlite3_file *pReal;      /* The real underlying file */
 136 };
 137
 138 /*
 139 ** Method declarations for vfstrace_file.
 140 */
 141 static int vfstraceClose(sqlite3_file*);
 142 static int vfstraceRead(sqlite3_file*, void*, int iAmt, sqlite3_int64 iOfst);
 143 static int vfstraceWrite(sqlite3_file*,const void*,int iAmt, sqlite3_int64);
 144 static int vfstraceTruncate(sqlite3_file*, sqlite3_int64 size);
 145 static int vfstraceSync(sqlite3_file*, int flags);
 146 static int vfstraceFileSize(sqlite3_file*, sqlite3_int64 *pSize);
 147 static int vfstraceLock(sqlite3_file*, int);
 148 static int vfstraceUnlock(sqlite3_file*, int);
 149 static int vfstraceCheckReservedLock(sqlite3_file*, int *);
 150 static int vfstraceFileControl(sqlite3_file*, int op, void *pArg);
 151 static int vfstraceSectorSize(sqlite3_file*);
 152 static int vfstraceDeviceCharacteristics(sqlite3_file*);
 153 static int vfstraceShmLock(sqlite3_file*,int,int,int);
 154 static int vfstraceShmMap(sqlite3_file*,int,int,int, void volatile **);
 155 static void vfstraceShmBarrier(sqlite3_file*);
 156 static int vfstraceShmUnmap(sqlite3_file*,int);
 157
 158 /*
 159 ** Method declarations for vfstrace_vfs.
 160 */
 161 static int vfstraceOpen(sqlite3_vfs*, const char *, sqlite3_file*, int , int *);
 162 static int vfstraceDelete(sqlite3_vfs*, const char *zName, int syncDir);
 163 static int vfstraceAccess(sqlite3_vfs*, const char *zName, int flags, int *);
 164 static int vfstraceFullPathname(sqlite3_vfs*, const char *zName, int, char *);
 165 static void *vfstraceDlOpen(sqlite3_vfs*, const char *zFilename);
 166 static void vfstraceDlError(sqlite3_vfs*, int nByte, char *zErrMsg);
 167 static void (*vfstraceDlSym(sqlite3_vfs*,void*, const char *zSymbol))(void);
 168 static void vfstraceDlClose(sqlite3_vfs*, void*);
 169 static int vfstraceRandomness(sqlite3_vfs*, int nByte, char *zOut);
 170 static int vfstraceSleep(sqlite3_vfs*, int microseconds);
 171 static int vfstraceCurrentTime(sqlite3_vfs*, double*);
 172 static int vfstraceGetLastError(sqlite3_vfs*, int, char*);
 173 static int vfstraceCurrentTimeInt64(sqlite3_vfs*, sqlite3_int64*);
 174 static int vfstraceSetSystemCall(sqlite3_vfs*,const char*, sqlite3_syscall_ptr);
 175 static sqlite3_syscall_ptr vfstraceGetSystemCall(sqlite3_vfs*, const char *);
 176 static const char *vfstraceNextSystemCall(sqlite3_vfs*, const char *zName);
 177
 178 /*
 179 ** Return a pointer to the tail of the pathname.  Examples:
 180 **
 181 **     /home/drh/xyzzy.txt -> xyzzy.txt
 182 **     xyzzy.txt           -> xyzzy.txt
 183 */
 184 static const char *fileTail(const char *z){
 185   int i;
 186   if( z==0 ) return 0;
 187   i = strlen(z)-1;
 188   while( i>0 && z[i-1]!='/' ){ i--; }
 189   return &z[i];
 190 }
 191
 192 /*
 193 ** Send trace output defined by zFormat and subsequent arguments.
 194 */
 195 static void vfstrace_printf(
 196   vfstrace_info *pInfo,
 197   const char *zFormat,
 198   ...
 199 ){
 200   va_list ap;
 201   char *zMsg;
 202   va_start(ap, zFormat);
 203   zMsg = sqlite3_vmprintf(zFormat, ap);
 204   va_end(ap);
 205   pInfo->xOut(zMsg, pInfo->pOutArg);
 206   sqlite3_free(zMsg);
 207 }
 208
 209 /*
 210 ** Convert value rc into a string and print it using zFormat.  zFormat
 211 ** should have exactly one %s
 212 */
 213 static void vfstrace_print_errcode(
 214   vfstrace_info *pInfo,
 215   const char *zFormat,
 216   int rc
 217 ){
 218   char zBuf[50];
 219   char *zVal;
 220   switch( rc ){
 221     case SQLITE_OK:         zVal = "SQLITE_OK";          break;
 222     case SQLITE_ERROR:      zVal = "SQLITE_ERROR";       break;
 223     case SQLITE_PERM:       zVal = "SQLITE_PERM";        break;
 224     case SQLITE_ABORT:      zVal = "SQLITE_ABORT";       break;
 225     case SQLITE_BUSY:       zVal = "SQLITE_BUSY";        break;
 226     case SQLITE_NOMEM:      zVal = "SQLITE_NOMEM";       break;
 227     case SQLITE_READONLY:   zVal = "SQLITE_READONLY";    break;
 228     case SQLITE_INTERRUPT:  zVal = "SQLITE_INTERRUPT";   break;
 229     case SQLITE_IOERR:      zVal = "SQLITE_IOERR";       break;
 230     case SQLITE_CORRUPT:    zVal = "SQLITE_CORRUPT";     break;
 231     case SQLITE_FULL:       zVal = "SQLITE_FULL";        break;
 232     case SQLITE_CANTOPEN:   zVal = "SQLITE_CANTOPEN";    break;
 233     case SQLITE_PROTOCOL:   zVal = "SQLITE_PROTOCOL";    break;
 234     case SQLITE_EMPTY:      zVal = "SQLITE_EMPTY";       break;
 235     case SQLITE_SCHEMA:     zVal = "SQLITE_SCHEMA";      break;
 236     case SQLITE_CONSTRAINT: zVal = "SQLITE_CONSTRAINT";  break;
 237     case SQLITE_MISMATCH:   zVal = "SQLITE_MISMATCH";    break;
 238     case SQLITE_MISUSE:     zVal = "SQLITE_MISUSE";      break;
 239     case SQLITE_NOLFS:      zVal = "SQLITE_NOLFS";       break;
 240     case SQLITE_IOERR_READ:         zVal = "SQLITE_IOERR_READ";         break;
 241     case SQLITE_IOERR_SHORT_READ:   zVal = "SQLITE_IOERR_SHORT_READ";   break;
 242     case SQLITE_IOERR_WRITE:        zVal = "SQLITE_IOERR_WRITE";        break;
 243     case SQLITE_IOERR_FSYNC:        zVal = "SQLITE_IOERR_FSYNC";        break;
 244     case SQLITE_IOERR_DIR_FSYNC:    zVal = "SQLITE_IOERR_DIR_FSYNC";    break;
 245     case SQLITE_IOERR_TRUNCATE:     zVal = "SQLITE_IOERR_TRUNCATE";     break;
 246     case SQLITE_IOERR_FSTAT:        zVal = "SQLITE_IOERR_FSTAT";        break;
 247     case SQLITE_IOERR_UNLOCK:       zVal = "SQLITE_IOERR_UNLOCK";       break;
 248     case SQLITE_IOERR_RDLOCK:       zVal = "SQLITE_IOERR_RDLOCK";       break;
 249     case SQLITE_IOERR_DELETE:       zVal = "SQLITE_IOERR_DELETE";       break;
 250     case SQLITE_IOERR_BLOCKED:      zVal = "SQLITE_IOERR_BLOCKED";      break;
 251     case SQLITE_IOERR_NOMEM:        zVal = "SQLITE_IOERR_NOMEM";        break;
 252     case SQLITE_IOERR_ACCESS:       zVal = "SQLITE_IOERR_ACCESS";       break;
 253     case SQLITE_IOERR_CHECKRESERVEDLOCK:
 254                                zVal = "SQLITE_IOERR_CHECKRESERVEDLOCK"; break;
 255     case SQLITE_IOERR_LOCK:         zVal = "SQLITE_IOERR_LOCK";         break;
 256     case SQLITE_IOERR_CLOSE:        zVal = "SQLITE_IOERR_CLOSE";        break;
 257     case SQLITE_IOERR_DIR_CLOSE:    zVal = "SQLITE_IOERR_DIR_CLOSE";    break;
 258     case SQLITE_IOERR_SHMOPEN:      zVal = "SQLITE_IOERR_SHMOPEN";      break;
 259     case SQLITE_IOERR_SHMSIZE:      zVal = "SQLITE_IOERR_SHMSIZE";      break;
 260     case SQLITE_IOERR_SHMLOCK:      zVal = "SQLITE_IOERR_SHMLOCK";      break;
 261     case SQLITE_IOERR_SHMMAP:       zVal = "SQLITE_IOERR_SHMMAP";       break;
 262     case SQLITE_IOERR_SEEK:         zVal = "SQLITE_IOERR_SEEK";         break;
 263     case SQLITE_IOERR_GETTEMPPATH:  zVal = "SQLITE_IOERR_GETTEMPPATH";  break;
 264     case SQLITE_IOERR_CONVPATH:     zVal = "SQLITE_IOERR_CONVPATH";     break;
 265     case SQLITE_READONLY_DBMOVED:   zVal = "SQLITE_READONLY_DBMOVED";   break;
 266     case SQLITE_LOCKED_SHAREDCACHE: zVal = "SQLITE_LOCKED_SHAREDCACHE"; break;
 267     case SQLITE_BUSY_RECOVERY:      zVal = "SQLITE_BUSY_RECOVERY";      break;
 268     case SQLITE_CANTOPEN_NOTEMPDIR: zVal = "SQLITE_CANTOPEN_NOTEMPDIR"; break;
 269     default: {
 270        sqlite3_snprintf(sizeof(zBuf), zBuf, "%d", rc);
 271        zVal = zBuf;
 272        break;
 273     }
 274   }
 275   vfstrace_printf(pInfo, zFormat, zVal);
 276 }
 277
 278 /*
 279 ** Append to a buffer.
 280 */
 281 static void strappend(char *z, int *pI, const char *zAppend){
 282   int i = *pI;
 283   while( zAppend[0] ){ z[i++] = *(zAppend++); }
 284   z[i] = 0;
 285   *pI = i;
 286 }
 287
 288 /*
 289 ** Close an vfstrace-file.
 290 */
 291 static int vfstraceClose(sqlite3_file *pFile){
 292   vfstrace_file *p = (vfstrace_file *)pFile;
 293   vfstrace_info *pInfo = p->pInfo;
 294   int rc;
 295   vfstrace_printf(pInfo, "%s.xClose(%s)", pInfo->zVfsName, p->zFName);
 296   rc = p->pReal->pMethods->xClose(p->pReal);
 297   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 298   if( rc==SQLITE_OK ){
 299     sqlite3_free((void*)p->base.pMethods);
 300     p->base.pMethods = 0;
 301   }
 302   return rc;
 303 }
 304
 305 /*
 306 ** Read data from an vfstrace-file.
 307 */
 308 static int vfstraceRead(
 309   sqlite3_file *pFile,
 310   void *zBuf,
 311   int iAmt,
 312   sqlite_int64 iOfst
 313 ){
 314   vfstrace_file *p = (vfstrace_file *)pFile;
 315   vfstrace_info *pInfo = p->pInfo;
 316   int rc;
 317   vfstrace_printf(pInfo, "%s.xRead(%s,n=%d,ofst=%lld)",
 318                   pInfo->zVfsName, p->zFName, iAmt, iOfst);
 319   rc = p->pReal->pMethods->xRead(p->pReal, zBuf, iAmt, iOfst);
 320   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 321   return rc;
 322 }
 323
 324 /*
 325 ** Write data to an vfstrace-file.
 326 */
 327 static int vfstraceWrite(
 328   sqlite3_file *pFile,
 329   const void *zBuf,
 330   int iAmt,
 331   sqlite_int64 iOfst
 332 ){
 333   vfstrace_file *p = (vfstrace_file *)pFile;
 334   vfstrace_info *pInfo = p->pInfo;
 335   int rc;
 336   vfstrace_printf(pInfo, "%s.xWrite(%s,n=%d,ofst=%lld)",
 337                   pInfo->zVfsName, p->zFName, iAmt, iOfst);
 338   rc = p->pReal->pMethods->xWrite(p->pReal, zBuf, iAmt, iOfst);
 339   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 340   return rc;
 341 }
 342
 343 /*
 344 ** Truncate an vfstrace-file.
 345 */
 346 static int vfstraceTruncate(sqlite3_file *pFile, sqlite_int64 size){
 347   vfstrace_file *p = (vfstrace_file *)pFile;
 348   vfstrace_info *pInfo = p->pInfo;
 349   int rc;
 350   vfstrace_printf(pInfo, "%s.xTruncate(%s,%lld)", pInfo->zVfsName, p->zFName,
 351                   size);
 352   rc = p->pReal->pMethods->xTruncate(p->pReal, size);
 353   vfstrace_printf(pInfo, " -> %d\n", rc);
 354   return rc;
 355 }
 356
 357 /*
 358 ** Sync an vfstrace-file.
 359 */
 360 static int vfstraceSync(sqlite3_file *pFile, int flags){
 361   vfstrace_file *p = (vfstrace_file *)pFile;
 362   vfstrace_info *pInfo = p->pInfo;
 363   int rc;
 364   int i;
 365   char zBuf[100];
 366   memcpy(zBuf, "|0", 3);
 367   i = 0;
 368   if( flags & SQLITE_SYNC_FULL )        strappend(zBuf, &i, "|FULL");
 369   else if( flags & SQLITE_SYNC_NORMAL ) strappend(zBuf, &i, "|NORMAL");
 370   if( flags & SQLITE_SYNC_DATAONLY )    strappend(zBuf, &i, "|DATAONLY");
 371   if( flags & ~(SQLITE_SYNC_FULL|SQLITE_SYNC_DATAONLY) ){
 372     sqlite3_snprintf(sizeof(zBuf)-i, &zBuf[i], "|0x%x", flags);
 373   }
 374   vfstrace_printf(pInfo, "%s.xSync(%s,%s)", pInfo->zVfsName, p->zFName,
 375                   &zBuf[1]);
 376   rc = p->pReal->pMethods->xSync(p->pReal, flags);
 377   vfstrace_printf(pInfo, " -> %d\n", rc);
 378   return rc;
 379 }
 380
 381 /*
 382 ** Return the current file-size of an vfstrace-file.
 383 */
 384 static int vfstraceFileSize(sqlite3_file *pFile, sqlite_int64 *pSize){
 385   vfstrace_file *p = (vfstrace_file *)pFile;
 386   vfstrace_info *pInfo = p->pInfo;
 387   int rc;
 388   vfstrace_printf(pInfo, "%s.xFileSize(%s)", pInfo->zVfsName, p->zFName);
 389   rc = p->pReal->pMethods->xFileSize(p->pReal, pSize);
 390   vfstrace_print_errcode(pInfo, " -> %s,", rc);
 391   vfstrace_printf(pInfo, " size=%lld\n", *pSize);
 392   return rc;
 393 }
 394
 395 /*
 396 ** Return the name of a lock.
 397 */
 398 static const char *lockName(int eLock){
 399   const char *azLockNames[] = {
 400      "NONE", "SHARED", "RESERVED", "PENDING", "EXCLUSIVE"
 401   };
 402   if( eLock<0 || eLock>=sizeof(azLockNames)/sizeof(azLockNames[0]) ){
 403     return "???";
 404   }else{
 405     return azLockNames[eLock];
 406   }
 407 }
 408
 409 /*
 410 ** Lock an vfstrace-file.
 411 */
 412 static int vfstraceLock(sqlite3_file *pFile, int eLock){
 413   vfstrace_file *p = (vfstrace_file *)pFile;
 414   vfstrace_info *pInfo = p->pInfo;
 415   int rc;
 416   vfstrace_printf(pInfo, "%s.xLock(%s,%s)", pInfo->zVfsName, p->zFName,
 417                   lockName(eLock));
 418   rc = p->pReal->pMethods->xLock(p->pReal, eLock);
 419   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 420   return rc;
 421 }
 422
 423 /*
 424 ** Unlock an vfstrace-file.
 425 */
 426 static int vfstraceUnlock(sqlite3_file *pFile, int eLock){
 427   vfstrace_file *p = (vfstrace_file *)pFile;
 428   vfstrace_info *pInfo = p->pInfo;
 429   int rc;
 430   vfstrace_printf(pInfo, "%s.xUnlock(%s,%s)", pInfo->zVfsName, p->zFName,
 431                   lockName(eLock));
 432   rc = p->pReal->pMethods->xUnlock(p->pReal, eLock);
 433   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 434   return rc;
 435 }
 436
 437 /*
 438 ** Check if another file-handle holds a RESERVED lock on an vfstrace-file.
 439 */
 440 static int vfstraceCheckReservedLock(sqlite3_file *pFile, int *pResOut){
 441   vfstrace_file *p = (vfstrace_file *)pFile;
 442   vfstrace_info *pInfo = p->pInfo;
 443   int rc;
 444   vfstrace_printf(pInfo, "%s.xCheckReservedLock(%s,%d)",
 445                   pInfo->zVfsName, p->zFName);
 446   rc = p->pReal->pMethods->xCheckReservedLock(p->pReal, pResOut);
 447   vfstrace_print_errcode(pInfo, " -> %s", rc);
 448   vfstrace_printf(pInfo, ", out=%d\n", *pResOut);
 449   return rc;
 450 }
 451
 452 /*
 453 ** File control method. For custom operations on an vfstrace-file.
 454 */
 455 static int vfstraceFileControl(sqlite3_file *pFile, int op, void *pArg){
 456   vfstrace_file *p = (vfstrace_file *)pFile;
 457   vfstrace_info *pInfo = p->pInfo;
 458   int rc;
 459   char zBuf[100];
 460   char *zOp;
 461   switch( op ){
 462     case SQLITE_FCNTL_LOCKSTATE:    zOp = "LOCKSTATE";          break;
 463     case SQLITE_GET_LOCKPROXYFILE:  zOp = "GET_LOCKPROXYFILE";  break;
 464     case SQLITE_SET_LOCKPROXYFILE:  zOp = "SET_LOCKPROXYFILE";  break;
 465     case SQLITE_LAST_ERRNO:         zOp = "LAST_ERRNO";         break;
 466     case SQLITE_FCNTL_SIZE_HINT: {
 467       sqlite3_snprintf(sizeof(zBuf), zBuf, "SIZE_HINT,%lld",
 468                        *(sqlite3_int64*)pArg);
 469       zOp = zBuf;
 470       break;
 471     }
 472     case SQLITE_FCNTL_CHUNK_SIZE: {
 473       sqlite3_snprintf(sizeof(zBuf), zBuf, "CHUNK_SIZE,%d", *(int*)pArg);
 474       zOp = zBuf;
 475       break;
 476     }
 477     case SQLITE_FCNTL_FILE_POINTER: zOp = "FILE_POINTER";       break;
 478     case SQLITE_FCNTL_SYNC_OMITTED: zOp = "SYNC_OMITTED";       break;
 479     case SQLITE_FCNTL_WIN32_AV_RETRY: zOp = "WIN32_AV_RETRY";   break;
 480     case SQLITE_FCNTL_PERSIST_WAL:  zOp = "PERSIST_WAL";        break;
 481     case SQLITE_FCNTL_OVERWRITE:    zOp = "OVERWRITE";          break;
 482     case SQLITE_FCNTL_VFSNAME:      zOp = "VFSNAME";            break;
 483     case SQLITE_FCNTL_TEMPFILENAME: zOp = "TEMPFILENAME";       break;
 484     case 0xca093fa0:                zOp = "DB_UNCHANGED";       break;
 485     case SQLITE_FCNTL_PRAGMA: {
 486       const char *const* a = (const char*const*)pArg;
 487       sqlite3_snprintf(sizeof(zBuf), zBuf, "PRAGMA,[%s,%s]",a[1],a[2]);
 488       zOp = zBuf;
 489       break;
 490     }
 491     default: {
 492       sqlite3_snprintf(sizeof zBuf, zBuf, "%d", op);
 493       zOp = zBuf;
 494       break;
 495     }
 496   }
 497   vfstrace_printf(pInfo, "%s.xFileControl(%s,%s)",
 498                   pInfo->zVfsName, p->zFName, zOp);
 499   rc = p->pReal->pMethods->xFileControl(p->pReal, op, pArg);
 500   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 501   if( op==SQLITE_FCNTL_VFSNAME && rc==SQLITE_OK ){
 502     *(char**)pArg = sqlite3_mprintf("vfstrace.%s/%z",
 503                                     pInfo->zVfsName, *(char**)pArg);
 504   }
 505   if( (op==SQLITE_FCNTL_PRAGMA || op==SQLITE_FCNTL_TEMPFILENAME)
 506    && rc==SQLITE_OK && *(char**)pArg ){
 507     vfstrace_printf(pInfo, "%s.xFileControl(%s,%s) returns %s",
 508                     pInfo->zVfsName, p->zFName, zOp, *(char**)pArg);
 509   }
 510   return rc;
 511 }
 512
 513 /*
 514 ** Return the sector-size in bytes for an vfstrace-file.
 515 */
 516 static int vfstraceSectorSize(sqlite3_file *pFile){
 517   vfstrace_file *p = (vfstrace_file *)pFile;
 518   vfstrace_info *pInfo = p->pInfo;
 519   int rc;
 520   vfstrace_printf(pInfo, "%s.xSectorSize(%s)", pInfo->zVfsName, p->zFName);
 521   rc = p->pReal->pMethods->xSectorSize(p->pReal);
 522   vfstrace_printf(pInfo, " -> %d\n", rc);
 523   return rc;
 524 }
 525
 526 /*
 527 ** Return the device characteristic flags supported by an vfstrace-file.
 528 */
 529 static int vfstraceDeviceCharacteristics(sqlite3_file *pFile){
 530   vfstrace_file *p = (vfstrace_file *)pFile;
 531   vfstrace_info *pInfo = p->pInfo;
 532   int rc;
 533   vfstrace_printf(pInfo, "%s.xDeviceCharacteristics(%s)",
 534                   pInfo->zVfsName, p->zFName);
 535   rc = p->pReal->pMethods->xDeviceCharacteristics(p->pReal);
 536   vfstrace_printf(pInfo, " -> 0x%08x\n", rc);
 537   return rc;
 538 }
 539
 540 /*
 541 ** Shared-memory operations.
 542 */
 543 static int vfstraceShmLock(sqlite3_file *pFile, int ofst, int n, int flags){
 544   vfstrace_file *p = (vfstrace_file *)pFile;
 545   vfstrace_info *pInfo = p->pInfo;
 546   int rc;
 547   char zLck[100];
 548   int i = 0;
 549   memcpy(zLck, "|0", 3);
 550   if( flags & SQLITE_SHM_UNLOCK )    strappend(zLck, &i, "|UNLOCK");
 551   if( flags & SQLITE_SHM_LOCK )      strappend(zLck, &i, "|LOCK");
 552   if( flags & SQLITE_SHM_SHARED )    strappend(zLck, &i, "|SHARED");
 553   if( flags & SQLITE_SHM_EXCLUSIVE ) strappend(zLck, &i, "|EXCLUSIVE");
 554   if( flags & ~(0xf) ){
 555      sqlite3_snprintf(sizeof(zLck)-i, &zLck[i], "|0x%x", flags);
 556   }
 557   vfstrace_printf(pInfo, "%s.xShmLock(%s,ofst=%d,n=%d,%s)",
 558                   pInfo->zVfsName, p->zFName, ofst, n, &zLck[1]);
 559   rc = p->pReal->pMethods->xShmLock(p->pReal, ofst, n, flags);
 560   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 561   return rc;
 562 }
 563 static int vfstraceShmMap(
 564   sqlite3_file *pFile,
 565   int iRegion,
 566   int szRegion,
 567   int isWrite,
 568   void volatile **pp
 569 ){
 570   vfstrace_file *p = (vfstrace_file *)pFile;
 571   vfstrace_info *pInfo = p->pInfo;
 572   int rc;
 573   vfstrace_printf(pInfo, "%s.xShmMap(%s,iRegion=%d,szRegion=%d,isWrite=%d,*)",
 574                   pInfo->zVfsName, p->zFName, iRegion, szRegion, isWrite);
 575   rc = p->pReal->pMethods->xShmMap(p->pReal, iRegion, szRegion, isWrite, pp);
 576   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 577   return rc;
 578 }
 579 static void vfstraceShmBarrier(sqlite3_file *pFile){
 580   vfstrace_file *p = (vfstrace_file *)pFile;
 581   vfstrace_info *pInfo = p->pInfo;
 582   vfstrace_printf(pInfo, "%s.xShmBarrier(%s)\n", pInfo->zVfsName, p->zFName);
 583   p->pReal->pMethods->xShmBarrier(p->pReal);
 584 }
 585 static int vfstraceShmUnmap(sqlite3_file *pFile, int delFlag){
 586   vfstrace_file *p = (vfstrace_file *)pFile;
 587   vfstrace_info *pInfo = p->pInfo;
 588   int rc;
 589   vfstrace_printf(pInfo, "%s.xShmUnmap(%s,delFlag=%d)",
 590                   pInfo->zVfsName, p->zFName, delFlag);
 591   rc = p->pReal->pMethods->xShmUnmap(p->pReal, delFlag);
 592   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 593   return rc;
 594 }
 595
 596
 597
 598 /*
 599 ** Open an vfstrace file handle.
 600 */
 601 static int vfstraceOpen(
 602   sqlite3_vfs *pVfs,
 603   const char *zName,
 604   sqlite3_file *pFile,
 605   int flags,
 606   int *pOutFlags
 607 ){
 608   int rc;
 609   vfstrace_file *p = (vfstrace_file *)pFile;
 610   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 611   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 612   p->pInfo = pInfo;
 613   p->zFName = zName ? fileTail(zName) : "<temp>";
 614   p->pReal = (sqlite3_file *)&p[1];
 615   rc = pRoot->xOpen(pRoot, zName, p->pReal, flags, pOutFlags);
 616   vfstrace_printf(pInfo, "%s.xOpen(%s,flags=0x%x)",
 617                   pInfo->zVfsName, p->zFName, flags);
 618   if( p->pReal->pMethods ){
 619     sqlite3_io_methods *pNew = sqlite3_malloc( sizeof(*pNew) );
 620     const sqlite3_io_methods *pSub = p->pReal->pMethods;
 621     memset(pNew, 0, sizeof(*pNew));
 622     pNew->iVersion = pSub->iVersion;
 623     pNew->xClose = vfstraceClose;
 624     pNew->xRead = vfstraceRead;
 625     pNew->xWrite = vfstraceWrite;
 626     pNew->xTruncate = vfstraceTruncate;
 627     pNew->xSync = vfstraceSync;
 628     pNew->xFileSize = vfstraceFileSize;
 629     pNew->xLock = vfstraceLock;
 630     pNew->xUnlock = vfstraceUnlock;
 631     pNew->xCheckReservedLock = vfstraceCheckReservedLock;
 632     pNew->xFileControl = vfstraceFileControl;
 633     pNew->xSectorSize = vfstraceSectorSize;
 634     pNew->xDeviceCharacteristics = vfstraceDeviceCharacteristics;
 635     if( pNew->iVersion>=2 ){
 636       pNew->xShmMap = pSub->xShmMap ? vfstraceShmMap : 0;
 637       pNew->xShmLock = pSub->xShmLock ? vfstraceShmLock : 0;
 638       pNew->xShmBarrier = pSub->xShmBarrier ? vfstraceShmBarrier : 0;
 639       pNew->xShmUnmap = pSub->xShmUnmap ? vfstraceShmUnmap : 0;
 640     }
 641     pFile->pMethods = pNew;
 642   }
 643   vfstrace_print_errcode(pInfo, " -> %s", rc);
 644   if( pOutFlags ){
 645     vfstrace_printf(pInfo, ", outFlags=0x%x\n", *pOutFlags);
 646   }else{
 647     vfstrace_printf(pInfo, "\n");
 648   }
 649   return rc;
 650 }
 651
 652 /*
 653 ** Delete the file located at zPath. If the dirSync argument is true,
 654 ** ensure the file-system modifications are synced to disk before
 655 ** returning.
 656 */
 657 static int vfstraceDelete(sqlite3_vfs *pVfs, const char *zPath, int dirSync){
 658   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 659   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 660   int rc;
 661   vfstrace_printf(pInfo, "%s.xDelete(\"%s\",%d)",
 662                   pInfo->zVfsName, zPath, dirSync);
 663   rc = pRoot->xDelete(pRoot, zPath, dirSync);
 664   vfstrace_print_errcode(pInfo, " -> %s\n", rc);
 665   return rc;
 666 }
 667
 668 /*
 669 ** Test for access permissions. Return true if the requested permission
 670 ** is available, or false otherwise.
 671 */
 672 static int vfstraceAccess(
 673   sqlite3_vfs *pVfs,
 674   const char *zPath,
 675   int flags,
 676   int *pResOut
 677 ){
 678   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 679   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 680   int rc;
 681   vfstrace_printf(pInfo, "%s.xAccess(\"%s\",%d)",
 682                   pInfo->zVfsName, zPath, flags);
 683   rc = pRoot->xAccess(pRoot, zPath, flags, pResOut);
 684   vfstrace_print_errcode(pInfo, " -> %s", rc);
 685   vfstrace_printf(pInfo, ", out=%d\n", *pResOut);
 686   return rc;
 687 }
 688
 689 /*
 690 ** Populate buffer zOut with the full canonical pathname corresponding
 691 ** to the pathname in zPath. zOut is guaranteed to point to a buffer
 692 ** of at least (DEVSYM_MAX_PATHNAME+1) bytes.
 693 */
 694 static int vfstraceFullPathname(
 695   sqlite3_vfs *pVfs,
 696   const char *zPath,
 697   int nOut,
 698   char *zOut
 699 ){
 700   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 701   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 702   int rc;
 703   vfstrace_printf(pInfo, "%s.xFullPathname(\"%s\")",
 704                   pInfo->zVfsName, zPath);
 705   rc = pRoot->xFullPathname(pRoot, zPath, nOut, zOut);
 706   vfstrace_print_errcode(pInfo, " -> %s", rc);
 707   vfstrace_printf(pInfo, ", out=\"%.*s\"\n", nOut, zOut);
 708   return rc;
 709 }
 710
 711 /*
 712 ** Open the dynamic library located at zPath and return a handle.
 713 */
 714 static void *vfstraceDlOpen(sqlite3_vfs *pVfs, const char *zPath){
 715   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 716   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 717   vfstrace_printf(pInfo, "%s.xDlOpen(\"%s\")\n", pInfo->zVfsName, zPath);
 718   return pRoot->xDlOpen(pRoot, zPath);
 719 }
 720
 721 /*
 722 ** Populate the buffer zErrMsg (size nByte bytes) with a human readable
 723 ** utf-8 string describing the most recent error encountered associated
 724 ** with dynamic libraries.
 725 */
 726 static void vfstraceDlError(sqlite3_vfs *pVfs, int nByte, char *zErrMsg){
 727   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 728   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 729   vfstrace_printf(pInfo, "%s.xDlError(%d)", pInfo->zVfsName, nByte);
 730   pRoot->xDlError(pRoot, nByte, zErrMsg);
 731   vfstrace_printf(pInfo, " -> \"%s\"", zErrMsg);
 732 }
 733
 734 /*
 735 ** Return a pointer to the symbol zSymbol in the dynamic library pHandle.
 736 */
 737 static void (*vfstraceDlSym(sqlite3_vfs *pVfs,void *p,const char *zSym))(void){
 738   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 739   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 740   vfstrace_printf(pInfo, "%s.xDlSym(\"%s\")\n", pInfo->zVfsName, zSym);
 741   return pRoot->xDlSym(pRoot, p, zSym);
 742 }
 743
 744 /*
 745 ** Close the dynamic library handle pHandle.
 746 */
 747 static void vfstraceDlClose(sqlite3_vfs *pVfs, void *pHandle){
 748   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 749   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 750   vfstrace_printf(pInfo, "%s.xDlOpen()\n", pInfo->zVfsName);
 751   pRoot->xDlClose(pRoot, pHandle);
 752 }
 753
 754 /*
 755 ** Populate the buffer pointed to by zBufOut with nByte bytes of
 756 ** random data.
 757 */
 758 static int vfstraceRandomness(sqlite3_vfs *pVfs, int nByte, char *zBufOut){
 759   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 760   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 761   vfstrace_printf(pInfo, "%s.xRandomness(%d)\n", pInfo->zVfsName, nByte);
 762   return pRoot->xRandomness(pRoot, nByte, zBufOut);
 763 }
 764
 765 /*
 766 ** Sleep for nMicro microseconds. Return the number of microseconds
 767 ** actually slept.
 768 */
 769 static int vfstraceSleep(sqlite3_vfs *pVfs, int nMicro){
 770   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 771   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 772   return pRoot->xSleep(pRoot, nMicro);
 773 }
 774
 775 /*
 776 ** Return the current time as a Julian Day number in *pTimeOut.
 777 */
 778 static int vfstraceCurrentTime(sqlite3_vfs *pVfs, double *pTimeOut){
 779   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 780   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 781   return pRoot->xCurrentTime(pRoot, pTimeOut);
 782 }
 783 static int vfstraceCurrentTimeInt64(sqlite3_vfs *pVfs, sqlite3_int64 *pTimeOut){
 784   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 785   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 786   return pRoot->xCurrentTimeInt64(pRoot, pTimeOut);
 787 }
 788
 789 /*
 790 ** Return th3 emost recent error code and message
 791 */
 792 static int vfstraceGetLastError(sqlite3_vfs *pVfs, int iErr, char *zErr){
 793   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 794   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 795   return pRoot->xGetLastError(pRoot, iErr, zErr);
 796 }
 797
 798 /*
 799 ** Override system calls.
 800 */
 801 static int vfstraceSetSystemCall(
 802   sqlite3_vfs *pVfs,
 803   const char *zName,
 804   sqlite3_syscall_ptr pFunc
 805 ){
 806   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 807   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 808   return pRoot->xSetSystemCall(pRoot, zName, pFunc);
 809 }
 810 static sqlite3_syscall_ptr vfstraceGetSystemCall(
 811   sqlite3_vfs *pVfs,
 812   const char *zName
 813 ){
 814   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 815   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 816   return pRoot->xGetSystemCall(pRoot, zName);
 817 }
 818 static const char *vfstraceNextSystemCall(sqlite3_vfs *pVfs, const char *zName){
 819   vfstrace_info *pInfo = (vfstrace_info*)pVfs->pAppData;
 820   sqlite3_vfs *pRoot = pInfo->pRootVfs;
 821   return pRoot->xNextSystemCall(pRoot, zName);
 822 }
 823
 824
 825 /*
 826 ** Clients invoke this routine to construct a new trace-vfs shim.
 827 **
 828 ** Return SQLITE_OK on success.
 829 **
 830 ** SQLITE_NOMEM is returned in the case of a memory allocation error.
 831 ** SQLITE_NOTFOUND is returned if zOldVfsName does not exist.
 832 */
 833 int vfstrace_register(
 834    const char *zTraceName,           /* Name of the newly constructed VFS */
 835    const char *zOldVfsName,          /* Name of the underlying VFS */
 836    int (*xOut)(const char*,void*),   /* Output routine.  ex: fputs */
 837    void *pOutArg,                    /* 2nd argument to xOut.  ex: stderr */
 838    int makeDefault                   /* True to make the new VFS the default */
 839 ){
 840   sqlite3_vfs *pNew;
 841   sqlite3_vfs *pRoot;
 842   vfstrace_info *pInfo;
 843   int nName;
 844   int nByte;
 845
 846   pRoot = sqlite3_vfs_find(zOldVfsName);
 847   if( pRoot==0 ) return SQLITE_NOTFOUND;
 848   nName = strlen(zTraceName);
 849   nByte = sizeof(*pNew) + sizeof(*pInfo) + nName + 1;
 850   pNew = sqlite3_malloc( nByte );
 851   if( pNew==0 ) return SQLITE_NOMEM;
 852   memset(pNew, 0, nByte);
 853   pInfo = (vfstrace_info*)&pNew[1];
 854   pNew->iVersion = pRoot->iVersion;
 855   pNew->szOsFile = pRoot->szOsFile + sizeof(vfstrace_file);
 856   pNew->mxPathname = pRoot->mxPathname;
 857   pNew->zName = (char*)&pInfo[1];
 858   memcpy((char*)&pInfo[1], zTraceName, nName+1);
 859   pNew->pAppData = pInfo;
 860   pNew->xOpen = vfstraceOpen;
 861   pNew->xDelete = vfstraceDelete;
 862   pNew->xAccess = vfstraceAccess;
 863   pNew->xFullPathname = vfstraceFullPathname;
 864   pNew->xDlOpen = pRoot->xDlOpen==0 ? 0 : vfstraceDlOpen;
 865   pNew->xDlError = pRoot->xDlError==0 ? 0 : vfstraceDlError;
 866   pNew->xDlSym = pRoot->xDlSym==0 ? 0 : vfstraceDlSym;
 867   pNew->xDlClose = pRoot->xDlClose==0 ? 0 : vfstraceDlClose;
 868   pNew->xRandomness = vfstraceRandomness;
 869   pNew->xSleep = vfstraceSleep;
 870   pNew->xCurrentTime = vfstraceCurrentTime;
 871   pNew->xGetLastError = pRoot->xGetLastError==0 ? 0 : vfstraceGetLastError;
 872   if( pNew->iVersion>=2 ){
 873     pNew->xCurrentTimeInt64 = pRoot->xCurrentTimeInt64==0 ? 0 :
 874                                    vfstraceCurrentTimeInt64;
 875     if( pNew->iVersion>=3 ){
 876       pNew->xSetSystemCall = pRoot->xSetSystemCall==0 ? 0 :
 877                                    vfstraceSetSystemCall;
 878       pNew->xGetSystemCall = pRoot->xGetSystemCall==0 ? 0 :
 879                                    vfstraceGetSystemCall;
 880       pNew->xNextSystemCall = pRoot->xNextSystemCall==0 ? 0 :
 881                                    vfstraceNextSystemCall;
 882     }
 883   }
 884   pInfo->pRootVfs = pRoot;
 885   pInfo->xOut = xOut;
 886   pInfo->pOutArg = pOutArg;
 887   pInfo->zVfsName = pNew->zName;
 888   pInfo->pTraceVfs = pNew;
 889   vfstrace_printf(pInfo, "%s.enabled_for(\"%s\")\n",
 890        pInfo->zVfsName, pRoot->zName);
 891   return sqlite3_vfs_register(pNew, makeDefault);
 892 }