test_vfstrace.c

/*
** 2011 March 16
**
** The author disclaims copyright to this source code.  In place of
** a legal notice, here is a blessing:
**
**    May you do good and not evil.
**    May you find forgiveness for yourself and forgive others.
**    May you share freely, never taking more than you give.
**
******************************************************************************
**
** This file contains code implements a VFS shim that writes diagnostic
** output for each VFS call, similar to "strace".
**
** USAGE:
**
** This source file exports a single symbol which is the name of a
** function:
**
**   int vfstrace_register(
**     const char *zTraceName,         // Name of the newly constructed VFS
**     const char *zOldVfsName,        // Name of the underlying VFS
**     int (*xOut)(const char*,void*), // Output routine.  ex: fputs
**     void *pOutArg,                  // 2nd argument to xOut.  ex: stderr
**     int makeDefault                 // Make the new VFS the default
**   );
**
** Applications that want to trace their VFS usage must provide a callback
** function with this prototype:
**
**   int traceOutput(const char *zMessage, void *pAppData);
**
** This function will "output" the trace messages, where "output" can
** mean different things to different applications.  The traceOutput function
** for the command-line shell (see shell.c) is "fputs" from the standard
** library, which means that all trace output is written on the stream
** specified by the second argument.  In the case of the command-line shell
** the second argument is stderr.  Other applications might choose to output
** trace information to a file, over a socket, or write it into a buffer.
**
** The vfstrace_register() function creates a new "shim" VFS named by
** the zTraceName parameter.  A "shim" VFS is an SQLite backend that does
** not really perform the duties of a true backend, but simply filters or
** interprets VFS calls before passing them off to another VFS which does
** the actual work.  In this case the other VFS - the one that does the
** real work - is identified by the second parameter, zOldVfsName.  If
** the 2nd parameter is NULL then the default VFS is used.  The common
** case is for the 2nd parameter to be NULL.
**
** The third and fourth parameters are the pointer to the output function
** and the second argument to the output function.  For the SQLite
** command-line shell, when the -vfstrace option is used, these parameters
** are fputs and stderr, respectively.
**
** The fifth argument is true (non-zero) to cause the newly created VFS
** to become the default VFS.  The common case is for the fifth parameter
** to be true.
**
** The call to vfstrace_register() simply creates the shim VFS that does
** tracing.  The application must also arrange to use the new VFS for
** all database connections that are created and for which tracing is
** desired.  This can be done by specifying the trace VFS using URI filename
** notation, or by specifying the trace VFS as the 4th parameter to
** sqlite3_open_v2() or by making the trace VFS be the default (by setting
** the 5th parameter of vfstrace_register() to 1).
**
**
** ENABLING VFSTRACE IN A COMMAND-LINE SHELL
**
** The SQLite command line shell implemented by the shell.c source file
** can be used with this module.  To compile in -vfstrace support, first
** gather this file (test_vfstrace.c), the shell source file (shell.c),
** and the SQLite amalgamation source files (sqlite3.c, sqlite3.h) into
** the working directory.  Then compile using a command like the following:
**
**    gcc -o sqlite3 -Os -I. -DSQLITE_ENABLE_VFSTRACE \
**        -DSQLITE_THREADSAFE=0 -DSQLITE_ENABLE_FTS3 -DSQLITE_ENABLE_RTREE \
**        -DHAVE_READLINE -DHAVE_USLEEP=1 \
**        shell.c test_vfstrace.c sqlite3.c -ldl -lreadline -lncurses
**
** The gcc command above works on Linux and provides (in addition to the
** -vfstrace option) support for FTS3 and FTS4, RTREE, and command-line
** editing using the readline library.  The command-line shell does not
** use threads so we added -DSQLITE_THREADSAFE=0 just to make the code
** run a little faster.   For compiling on a Mac, you'll probably need
** to omit the -DHAVE_READLINE, the -lreadline, and the -lncurses options.
** The compilation could be simplified to just this:
**
**    gcc -DSQLITE_ENABLE_VFSTRACE \
**         shell.c test_vfstrace.c sqlite3.c -ldl -lpthread
**
** In this second example, all unnecessary options have been removed
** Note that since the code is now threadsafe, we had to add the -lpthread
** option to pull in the pthreads library.
**
** To cross-compile for windows using MinGW, a command like this might
** work:
**
**    /opt/mingw/bin/i386-mingw32msvc-gcc -o sqlite3.exe -Os -I \
**         -DSQLITE_THREADSAFE=0 -DSQLITE_ENABLE_VFSTRACE \
**         shell.c test_vfstrace.c sqlite3.c
**
** Similar compiler commands will work on different systems.  The key
** invariants are (1) you must have -DSQLITE_ENABLE_VFSTRACE so that
** the shell.c source file will know to include the -vfstrace command-line
** option and (2) you must compile and link the three source files
** shell,c, test_vfstrace.c, and sqlite3.c.
*/
#include "sqlite3.h"
#include <stdlib.h>
#include <string.h>

/*
** An instance of this structure is attached to the each trace VFS to
** provide auxiliary information.
*/
typedef struct vfstrace_info vfstrace_info;
struct vfstrace_info {
    sqlite3_vfs *pRootVfs;             /* The underlying real VFS */
    int (*xOut)(const char *, void *); /* Send output here */
    void *pOutArg;                     /* First argument to xOut */
    const char *zVfsName;              /* Name of this trace-VFS */
    sqlite3_vfs *pTraceVfs;            /* Pointer back to the trace VFS */
};

/*
** The sqlite3_file object for the trace VFS
*/
typedef struct vfstrace_file vfstrace_file;
struct vfstrace_file {
    sqlite3_file base;    /* Base class.  Must be first */
    vfstrace_info *pInfo; /* The trace-VFS to which this file belongs */
    const char *zFName;   /* Base name of the file */
    sqlite3_file *pReal;  /* The real underlying file */
};

/*
** Method declarations for vfstrace_file.
*/
static int vfstraceClose(sqlite3_file *);
static int vfstraceRead(sqlite3_file *, void *, int iAmt, sqlite3_int64 iOfst);
static int vfstraceWrite(sqlite3_file *, const void *, int iAmt, sqlite3_int64);
static int vfstraceTruncate(sqlite3_file *, sqlite3_int64 size);
static int vfstraceSync(sqlite3_file *, int flags);
static int vfstraceFileSize(sqlite3_file *, sqlite3_int64 *pSize);
static int vfstraceLock(sqlite3_file *, int);
static int vfstraceUnlock(sqlite3_file *, int);
static int vfstraceCheckReservedLock(sqlite3_file *, int *);
static int vfstraceFileControl(sqlite3_file *, int op, void *pArg);
static int vfstraceSectorSize(sqlite3_file *);
static int vfstraceDeviceCharacteristics(sqlite3_file *);
static int vfstraceShmLock(sqlite3_file *, int, int, int);
static int vfstraceShmMap(sqlite3_file *, int, int, int, void volatile **);
static void vfstraceShmBarrier(sqlite3_file *);
static int vfstraceShmUnmap(sqlite3_file *, int);

/*
** Method declarations for vfstrace_vfs.
*/
static int vfstraceOpen(sqlite3_vfs *, const char *, sqlite3_file *, int, int *);
static int vfstraceDelete(sqlite3_vfs *, const char *zName, int syncDir);
static int vfstraceAccess(sqlite3_vfs *, const char *zName, int flags, int *);
static int vfstraceFullPathname(sqlite3_vfs *, const char *zName, int, char *);
static void *vfstraceDlOpen(sqlite3_vfs *, const char *zFilename);
static void vfstraceDlError(sqlite3_vfs *, int nByte, char *zErrMsg);
static void (*vfstraceDlSym(sqlite3_vfs *, void *, const char *zSymbol))(void);
static void vfstraceDlClose(sqlite3_vfs *, void *);
static int vfstraceRandomness(sqlite3_vfs *, int nByte, char *zOut);
static int vfstraceSleep(sqlite3_vfs *, int microseconds);
static int vfstraceCurrentTime(sqlite3_vfs *, double *);
static int vfstraceGetLastError(sqlite3_vfs *, int, char *);
static int vfstraceCurrentTimeInt64(sqlite3_vfs *, sqlite3_int64 *);
static int vfstraceSetSystemCall(sqlite3_vfs *, const char *, sqlite3_syscall_ptr);
static sqlite3_syscall_ptr vfstraceGetSystemCall(sqlite3_vfs *, const char *);
static const char *vfstraceNextSystemCall(sqlite3_vfs *, const char *zName);

/*
** Return a pointer to the tail of the pathname.  Examples:
**
**     /home/drh/xyzzy.txt -> xyzzy.txt
**     xyzzy.txt           -> xyzzy.txt
*/
static const char *fileTail(const char *z) {
    int i;
    if (z == 0)
        return 0;
    i = strlen(z) - 1;
    while (i > 0 && z[i - 1] != '/') {
        i--;
    }
    return &z[i];
}

/*
** Send trace output defined by zFormat and subsequent arguments.
*/
static void vfstrace_printf(vfstrace_info *pInfo, const char *zFormat, ...) {
    va_list ap;
    char *zMsg;
    va_start(ap, zFormat);
    zMsg = sqlite3_vmprintf(zFormat, ap);
    va_end(ap);
    pInfo->xOut(zMsg, pInfo->pOutArg);
    sqlite3_free(zMsg);
}

/*
** Convert value rc into a string and print it using zFormat.  zFormat
** should have exactly one %s
*/
static void vfstrace_print_errcode(vfstrace_info *pInfo, const char *zFormat, int rc) {
    char zBuf[50];
    char *zVal;
    switch (rc) {
    case SQLITE_OK:
        zVal = "SQLITE_OK";
        break;
    case SQLITE_ERROR:
        zVal = "SQLITE_ERROR";
        break;
    case SQLITE_PERM:
        zVal = "SQLITE_PERM";
        break;
    case SQLITE_ABORT:
        zVal = "SQLITE_ABORT";
        break;
    case SQLITE_BUSY:
        zVal = "SQLITE_BUSY";
        break;
    case SQLITE_NOMEM:
        zVal = "SQLITE_NOMEM";
        break;
    case SQLITE_READONLY:
        zVal = "SQLITE_READONLY";
        break;
    case SQLITE_INTERRUPT:
        zVal = "SQLITE_INTERRUPT";
        break;
    case SQLITE_IOERR:
        zVal = "SQLITE_IOERR";
        break;
    case SQLITE_CORRUPT:
        zVal = "SQLITE_CORRUPT";
        break;
    case SQLITE_FULL:
        zVal = "SQLITE_FULL";
        break;
    case SQLITE_CANTOPEN:
        zVal = "SQLITE_CANTOPEN";
        break;
    case SQLITE_PROTOCOL:
        zVal = "SQLITE_PROTOCOL";
        break;
    case SQLITE_EMPTY:
        zVal = "SQLITE_EMPTY";
        break;
    case SQLITE_SCHEMA:
        zVal = "SQLITE_SCHEMA";
        break;
    case SQLITE_CONSTRAINT:
        zVal = "SQLITE_CONSTRAINT";
        break;
    case SQLITE_MISMATCH:
        zVal = "SQLITE_MISMATCH";
        break;
    case SQLITE_MISUSE:
        zVal = "SQLITE_MISUSE";
        break;
    case SQLITE_NOLFS:
        zVal = "SQLITE_NOLFS";
        break;
    case SQLITE_IOERR_READ:
        zVal = "SQLITE_IOERR_READ";
        break;
    case SQLITE_IOERR_SHORT_READ:
        zVal = "SQLITE_IOERR_SHORT_READ";
        break;
    case SQLITE_IOERR_WRITE:
        zVal = "SQLITE_IOERR_WRITE";
        break;
    case SQLITE_IOERR_FSYNC:
        zVal = "SQLITE_IOERR_FSYNC";
        break;
    case SQLITE_IOERR_DIR_FSYNC:
        zVal = "SQLITE_IOERR_DIR_FSYNC";
        break;
    case SQLITE_IOERR_TRUNCATE:
        zVal = "SQLITE_IOERR_TRUNCATE";
        break;
    case SQLITE_IOERR_FSTAT:
        zVal = "SQLITE_IOERR_FSTAT";
        break;
    case SQLITE_IOERR_UNLOCK:
        zVal = "SQLITE_IOERR_UNLOCK";
        break;
    case SQLITE_IOERR_RDLOCK:
        zVal = "SQLITE_IOERR_RDLOCK";
        break;
    case SQLITE_IOERR_DELETE:
        zVal = "SQLITE_IOERR_DELETE";
        break;
    case SQLITE_IOERR_BLOCKED:
        zVal = "SQLITE_IOERR_BLOCKED";
        break;
    case SQLITE_IOERR_NOMEM:
        zVal = "SQLITE_IOERR_NOMEM";
        break;
    case SQLITE_IOERR_ACCESS:
        zVal = "SQLITE_IOERR_ACCESS";
        break;
    case SQLITE_IOERR_CHECKRESERVEDLOCK:
        zVal = "SQLITE_IOERR_CHECKRESERVEDLOCK";
        break;
    case SQLITE_IOERR_LOCK:
        zVal = "SQLITE_IOERR_LOCK";
        break;
    case SQLITE_IOERR_CLOSE:
        zVal = "SQLITE_IOERR_CLOSE";
        break;
    case SQLITE_IOERR_DIR_CLOSE:
        zVal = "SQLITE_IOERR_DIR_CLOSE";
        break;
    case SQLITE_IOERR_SHMOPEN:
        zVal = "SQLITE_IOERR_SHMOPEN";
        break;
    case SQLITE_IOERR_SHMSIZE:
        zVal = "SQLITE_IOERR_SHMSIZE";
        break;
    case SQLITE_IOERR_SHMLOCK:
        zVal = "SQLITE_IOERR_SHMLOCK";
        break;
    case SQLITE_IOERR_SHMMAP:
        zVal = "SQLITE_IOERR_SHMMAP";
        break;
    case SQLITE_IOERR_SEEK:
        zVal = "SQLITE_IOERR_SEEK";
        break;
    case SQLITE_IOERR_GETTEMPPATH:
        zVal = "SQLITE_IOERR_GETTEMPPATH";
        break;
    case SQLITE_IOERR_CONVPATH:
        zVal = "SQLITE_IOERR_CONVPATH";
        break;
    case SQLITE_READONLY_DBMOVED:
        zVal = "SQLITE_READONLY_DBMOVED";
        break;
    case SQLITE_LOCKED_SHAREDCACHE:
        zVal = "SQLITE_LOCKED_SHAREDCACHE";
        break;
    case SQLITE_BUSY_RECOVERY:
        zVal = "SQLITE_BUSY_RECOVERY";
        break;
    case SQLITE_CANTOPEN_NOTEMPDIR:
        zVal = "SQLITE_CANTOPEN_NOTEMPDIR";
        break;
    default: {
        sqlite3_snprintf(sizeof(zBuf), zBuf, "%d", rc);
        zVal = zBuf;
        break;
    }
    }
    vfstrace_printf(pInfo, zFormat, zVal);
}

/*
** Append to a buffer.
*/
static void strappend(char *z, int *pI, const char *zAppend) {
    int i = *pI;
    while (zAppend[0]) {
        z[i++] = *(zAppend++);
    }
    z[i] = 0;
    *pI = i;
}

/*
** Close an vfstrace-file.
*/
static int vfstraceClose(sqlite3_file *pFile) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xClose(%s)", pInfo->zVfsName, p->zFName);
    rc = p->pReal->pMethods->xClose(p->pReal);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    if (rc == SQLITE_OK) {
        sqlite3_free((void *)p->base.pMethods);
        p->base.pMethods = 0;
    }
    return rc;
}

/*
** Read data from an vfstrace-file.
*/
static int vfstraceRead(sqlite3_file *pFile, void *zBuf, int iAmt, sqlite_int64 iOfst) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xRead(%s,n=%d,ofst=%lld)", pInfo->zVfsName, p->zFName, iAmt, iOfst);
    rc = p->pReal->pMethods->xRead(p->pReal, zBuf, iAmt, iOfst);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    return rc;
}

/*
** Write data to an vfstrace-file.
*/
static int vfstraceWrite(sqlite3_file *pFile, const void *zBuf, int iAmt, sqlite_int64 iOfst) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xWrite(%s,n=%d,ofst=%lld)", pInfo->zVfsName, p->zFName, iAmt, iOfst);
    rc = p->pReal->pMethods->xWrite(p->pReal, zBuf, iAmt, iOfst);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    return rc;
}

/*
** Truncate an vfstrace-file.
*/
static int vfstraceTruncate(sqlite3_file *pFile, sqlite_int64 size) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xTruncate(%s,%lld)", pInfo->zVfsName, p->zFName, size);
    rc = p->pReal->pMethods->xTruncate(p->pReal, size);
    vfstrace_printf(pInfo, " -> %d\n", rc);
    return rc;
}

/*
** Sync an vfstrace-file.
*/
static int vfstraceSync(sqlite3_file *pFile, int flags) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    int i;
    char zBuf[100];
    memcpy(zBuf, "|0", 3);
    i = 0;
    if (flags & SQLITE_SYNC_FULL)
        strappend(zBuf, &i, "|FULL");
    else if (flags & SQLITE_SYNC_NORMAL)
        strappend(zBuf, &i, "|NORMAL");
    if (flags & SQLITE_SYNC_DATAONLY)
        strappend(zBuf, &i, "|DATAONLY");
    if (flags & ~(SQLITE_SYNC_FULL | SQLITE_SYNC_DATAONLY)) {
        sqlite3_snprintf(sizeof(zBuf) - i, &zBuf[i], "|0x%x", flags);
    }
    vfstrace_printf(pInfo, "%s.xSync(%s,%s)", pInfo->zVfsName, p->zFName, &zBuf[1]);
    rc = p->pReal->pMethods->xSync(p->pReal, flags);
    vfstrace_printf(pInfo, " -> %d\n", rc);
    return rc;
}

/*
** Return the current file-size of an vfstrace-file.
*/
static int vfstraceFileSize(sqlite3_file *pFile, sqlite_int64 *pSize) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xFileSize(%s)", pInfo->zVfsName, p->zFName);
    rc = p->pReal->pMethods->xFileSize(p->pReal, pSize);
    vfstrace_print_errcode(pInfo, " -> %s,", rc);
    vfstrace_printf(pInfo, " size=%lld\n", *pSize);
    return rc;
}

/*
** Return the name of a lock.
*/
static const char *lockName(int eLock) {
    const char *azLockNames[] = {"NONE", "SHARED", "RESERVED", "PENDING", "EXCLUSIVE"};
    if (eLock < 0 || eLock >= sizeof(azLockNames) / sizeof(azLockNames[0])) {
        return "???";
    } else {
        return azLockNames[eLock];
    }
}

/*
** Lock an vfstrace-file.
*/
static int vfstraceLock(sqlite3_file *pFile, int eLock) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xLock(%s,%s)", pInfo->zVfsName, p->zFName, lockName(eLock));
    rc = p->pReal->pMethods->xLock(p->pReal, eLock);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    return rc;
}

/*
** Unlock an vfstrace-file.
*/
static int vfstraceUnlock(sqlite3_file *pFile, int eLock) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xUnlock(%s,%s)", pInfo->zVfsName, p->zFName, lockName(eLock));
    rc = p->pReal->pMethods->xUnlock(p->pReal, eLock);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    return rc;
}

/*
** Check if another file-handle holds a RESERVED lock on an vfstrace-file.
*/
static int vfstraceCheckReservedLock(sqlite3_file *pFile, int *pResOut) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xCheckReservedLock(%s,%d)", pInfo->zVfsName, p->zFName);
    rc = p->pReal->pMethods->xCheckReservedLock(p->pReal, pResOut);
    vfstrace_print_errcode(pInfo, " -> %s", rc);
    vfstrace_printf(pInfo, ", out=%d\n", *pResOut);
    return rc;
}

/*
** File control method. For custom operations on an vfstrace-file.
*/
static int vfstraceFileControl(sqlite3_file *pFile, int op, void *pArg) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    char zBuf[100];
    char *zOp;
    switch (op) {
    case SQLITE_FCNTL_LOCKSTATE:
        zOp = "LOCKSTATE";
        break;
    case SQLITE_GET_LOCKPROXYFILE:
        zOp = "GET_LOCKPROXYFILE";
        break;
    case SQLITE_SET_LOCKPROXYFILE:
        zOp = "SET_LOCKPROXYFILE";
        break;
    case SQLITE_LAST_ERRNO:
        zOp = "LAST_ERRNO";
        break;
    case SQLITE_FCNTL_SIZE_HINT: {
        sqlite3_snprintf(sizeof(zBuf), zBuf, "SIZE_HINT,%lld", *(sqlite3_int64 *)pArg);
        zOp = zBuf;
        break;
    }
    case SQLITE_FCNTL_CHUNK_SIZE: {
        sqlite3_snprintf(sizeof(zBuf), zBuf, "CHUNK_SIZE,%d", *(int *)pArg);
        zOp = zBuf;
        break;
    }
    case SQLITE_FCNTL_FILE_POINTER:
        zOp = "FILE_POINTER";
        break;
    case SQLITE_FCNTL_SYNC_OMITTED:
        zOp = "SYNC_OMITTED";
        break;
    case SQLITE_FCNTL_WIN32_AV_RETRY:
        zOp = "WIN32_AV_RETRY";
        break;
    case SQLITE_FCNTL_PERSIST_WAL:
        zOp = "PERSIST_WAL";
        break;
    case SQLITE_FCNTL_OVERWRITE:
        zOp = "OVERWRITE";
        break;
    case SQLITE_FCNTL_VFSNAME:
        zOp = "VFSNAME";
        break;
    case SQLITE_FCNTL_TEMPFILENAME:
        zOp = "TEMPFILENAME";
        break;
    case 0xca093fa0:
        zOp = "DB_UNCHANGED";
        break;
    case SQLITE_FCNTL_PRAGMA: {
        const char *const *a = (const char *const *)pArg;
        sqlite3_snprintf(sizeof(zBuf), zBuf, "PRAGMA,[%s,%s]", a[1], a[2]);
        zOp = zBuf;
        break;
    }
    default: {
        sqlite3_snprintf(sizeof zBuf, zBuf, "%d", op);
        zOp = zBuf;
        break;
    }
    }
    vfstrace_printf(pInfo, "%s.xFileControl(%s,%s)", pInfo->zVfsName, p->zFName, zOp);
    rc = p->pReal->pMethods->xFileControl(p->pReal, op, pArg);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    if (op == SQLITE_FCNTL_VFSNAME && rc == SQLITE_OK) {
        *(char **)pArg = sqlite3_mprintf("vfstrace.%s/%z", pInfo->zVfsName, *(char **)pArg);
    }
    if ((op == SQLITE_FCNTL_PRAGMA || op == SQLITE_FCNTL_TEMPFILENAME) && rc == SQLITE_OK &&
        *(char **)pArg) {
        vfstrace_printf(pInfo, "%s.xFileControl(%s,%s) returns %s", pInfo->zVfsName, p->zFName, zOp,
                        *(char **)pArg);
    }
    return rc;
}

/*
** Return the sector-size in bytes for an vfstrace-file.
*/
static int vfstraceSectorSize(sqlite3_file *pFile) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xSectorSize(%s)", pInfo->zVfsName, p->zFName);
    rc = p->pReal->pMethods->xSectorSize(p->pReal);
    vfstrace_printf(pInfo, " -> %d\n", rc);
    return rc;
}

/*
** Return the device characteristic flags supported by an vfstrace-file.
*/
static int vfstraceDeviceCharacteristics(sqlite3_file *pFile) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xDeviceCharacteristics(%s)", pInfo->zVfsName, p->zFName);
    rc = p->pReal->pMethods->xDeviceCharacteristics(p->pReal);
    vfstrace_printf(pInfo, " -> 0x%08x\n", rc);
    return rc;
}

/*
** Shared-memory operations.
*/
static int vfstraceShmLock(sqlite3_file *pFile, int ofst, int n, int flags) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    char zLck[100];
    int i = 0;
    memcpy(zLck, "|0", 3);
    if (flags & SQLITE_SHM_UNLOCK)
        strappend(zLck, &i, "|UNLOCK");
    if (flags & SQLITE_SHM_LOCK)
        strappend(zLck, &i, "|LOCK");
    if (flags & SQLITE_SHM_SHARED)
        strappend(zLck, &i, "|SHARED");
    if (flags & SQLITE_SHM_EXCLUSIVE)
        strappend(zLck, &i, "|EXCLUSIVE");
    if (flags & ~(0xf)) {
        sqlite3_snprintf(sizeof(zLck) - i, &zLck[i], "|0x%x", flags);
    }
    vfstrace_printf(pInfo, "%s.xShmLock(%s,ofst=%d,n=%d,%s)", pInfo->zVfsName, p->zFName, ofst, n,
                    &zLck[1]);
    rc = p->pReal->pMethods->xShmLock(p->pReal, ofst, n, flags);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    return rc;
}
static int vfstraceShmMap(sqlite3_file *pFile, int iRegion, int szRegion, int isWrite,
                          void volatile **pp) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xShmMap(%s,iRegion=%d,szRegion=%d,isWrite=%d,*)", pInfo->zVfsName,
                    p->zFName, iRegion, szRegion, isWrite);
    rc = p->pReal->pMethods->xShmMap(p->pReal, iRegion, szRegion, isWrite, pp);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    return rc;
}
static void vfstraceShmBarrier(sqlite3_file *pFile) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    vfstrace_printf(pInfo, "%s.xShmBarrier(%s)\n", pInfo->zVfsName, p->zFName);
    p->pReal->pMethods->xShmBarrier(p->pReal);
}
static int vfstraceShmUnmap(sqlite3_file *pFile, int delFlag) {
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = p->pInfo;
    int rc;
    vfstrace_printf(pInfo, "%s.xShmUnmap(%s,delFlag=%d)", pInfo->zVfsName, p->zFName, delFlag);
    rc = p->pReal->pMethods->xShmUnmap(p->pReal, delFlag);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    return rc;
}

/*
** Open an vfstrace file handle.
*/
static int vfstraceOpen(sqlite3_vfs *pVfs, const char *zName, sqlite3_file *pFile, int flags,
                        int *pOutFlags) {
    int rc;
    vfstrace_file *p = (vfstrace_file *)pFile;
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    p->pInfo = pInfo;
    p->zFName = zName ? zName : "<temp>";
    p->pReal = (sqlite3_file *)&p[1];
    rc = pRoot->xOpen(pRoot, zName, p->pReal, flags, pOutFlags);
    vfstrace_printf(pInfo, "%s.xOpen(%s,flags=0x%x)", pInfo->zVfsName, p->zFName, flags);
    if (p->pReal->pMethods) {
        sqlite3_io_methods *pNew = sqlite3_malloc(sizeof(*pNew));
        const sqlite3_io_methods *pSub = p->pReal->pMethods;
        memset(pNew, 0, sizeof(*pNew));
        pNew->iVersion = pSub->iVersion;
        pNew->xClose = vfstraceClose;
        pNew->xRead = vfstraceRead;
        pNew->xWrite = vfstraceWrite;
        pNew->xTruncate = vfstraceTruncate;
        pNew->xSync = vfstraceSync;
        pNew->xFileSize = vfstraceFileSize;
        pNew->xLock = vfstraceLock;
        pNew->xUnlock = vfstraceUnlock;
        pNew->xCheckReservedLock = vfstraceCheckReservedLock;
        pNew->xFileControl = vfstraceFileControl;
        pNew->xSectorSize = vfstraceSectorSize;
        pNew->xDeviceCharacteristics = vfstraceDeviceCharacteristics;
        if (pNew->iVersion >= 2) {
            pNew->xShmMap = pSub->xShmMap ? vfstraceShmMap : 0;
            pNew->xShmLock = pSub->xShmLock ? vfstraceShmLock : 0;
            pNew->xShmBarrier = pSub->xShmBarrier ? vfstraceShmBarrier : 0;
            pNew->xShmUnmap = pSub->xShmUnmap ? vfstraceShmUnmap : 0;
        }
        pFile->pMethods = pNew;
    }
    vfstrace_print_errcode(pInfo, " -> %s", rc);
    if (pOutFlags) {
        vfstrace_printf(pInfo, ", outFlags=0x%x\n", *pOutFlags);
    } else {
        vfstrace_printf(pInfo, "\n");
    }
    return rc;
}

/*
** Delete the file located at zPath. If the dirSync argument is true,
** ensure the file-system modifications are synced to disk before
** returning.
*/
static int vfstraceDelete(sqlite3_vfs *pVfs, const char *zPath, int dirSync) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    int rc;
    vfstrace_printf(pInfo, "%s.xDelete(\"%s\",%d)", pInfo->zVfsName, zPath, dirSync);
    rc = pRoot->xDelete(pRoot, zPath, dirSync);
    vfstrace_print_errcode(pInfo, " -> %s\n", rc);
    return rc;
}

/*
** Test for access permissions. Return true if the requested permission
** is available, or false otherwise.
*/
static int vfstraceAccess(sqlite3_vfs *pVfs, const char *zPath, int flags, int *pResOut) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    int rc;
    vfstrace_printf(pInfo, "%s.xAccess(\"%s\",%d)", pInfo->zVfsName, zPath, flags);
    rc = pRoot->xAccess(pRoot, zPath, flags, pResOut);
    vfstrace_print_errcode(pInfo, " -> %s", rc);
    vfstrace_printf(pInfo, ", out=%d\n", *pResOut);
    return rc;
}

/*
** Populate buffer zOut with the full canonical pathname corresponding
** to the pathname in zPath. zOut is guaranteed to point to a buffer
** of at least (DEVSYM_MAX_PATHNAME+1) bytes.
*/
static int vfstraceFullPathname(sqlite3_vfs *pVfs, const char *zPath, int nOut, char *zOut) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    int rc;
    vfstrace_printf(pInfo, "%s.xFullPathname(\"%s\")", pInfo->zVfsName, zPath);
    rc = pRoot->xFullPathname(pRoot, zPath, nOut, zOut);
    vfstrace_print_errcode(pInfo, " -> %s", rc);
    vfstrace_printf(pInfo, ", out=\"%.*s\"\n", nOut, zOut);
    return rc;
}

/*
** Open the dynamic library located at zPath and return a handle.
*/
static void *vfstraceDlOpen(sqlite3_vfs *pVfs, const char *zPath) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    vfstrace_printf(pInfo, "%s.xDlOpen(\"%s\")\n", pInfo->zVfsName, zPath);
    return pRoot->xDlOpen(pRoot, zPath);
}

/*
** Populate the buffer zErrMsg (size nByte bytes) with a human readable
** utf-8 string describing the most recent error encountered associated
** with dynamic libraries.
*/
static void vfstraceDlError(sqlite3_vfs *pVfs, int nByte, char *zErrMsg) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    vfstrace_printf(pInfo, "%s.xDlError(%d)", pInfo->zVfsName, nByte);
    pRoot->xDlError(pRoot, nByte, zErrMsg);
    vfstrace_printf(pInfo, " -> \"%s\"", zErrMsg);
}

/*
** Return a pointer to the symbol zSymbol in the dynamic library pHandle.
*/
static void (*vfstraceDlSym(sqlite3_vfs *pVfs, void *p, const char *zSym))(void) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    vfstrace_printf(pInfo, "%s.xDlSym(\"%s\")\n", pInfo->zVfsName, zSym);
    return pRoot->xDlSym(pRoot, p, zSym);
}

/*
** Close the dynamic library handle pHandle.
*/
static void vfstraceDlClose(sqlite3_vfs *pVfs, void *pHandle) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    vfstrace_printf(pInfo, "%s.xDlOpen()\n", pInfo->zVfsName);
    pRoot->xDlClose(pRoot, pHandle);
}

/*
** Populate the buffer pointed to by zBufOut with nByte bytes of
** random data.
*/
static int vfstraceRandomness(sqlite3_vfs *pVfs, int nByte, char *zBufOut) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    vfstrace_printf(pInfo, "%s.xRandomness(%d)\n", pInfo->zVfsName, nByte);
    return pRoot->xRandomness(pRoot, nByte, zBufOut);
}

/*
** Sleep for nMicro microseconds. Return the number of microseconds
** actually slept.
*/
static int vfstraceSleep(sqlite3_vfs *pVfs, int nMicro) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    return pRoot->xSleep(pRoot, nMicro);
}

/*
** Return the current time as a Julian Day number in *pTimeOut.
*/
static int vfstraceCurrentTime(sqlite3_vfs *pVfs, double *pTimeOut) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    return pRoot->xCurrentTime(pRoot, pTimeOut);
}
static int vfstraceCurrentTimeInt64(sqlite3_vfs *pVfs, sqlite3_int64 *pTimeOut) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    return pRoot->xCurrentTimeInt64(pRoot, pTimeOut);
}

/*
** Return th3 emost recent error code and message
*/
static int vfstraceGetLastError(sqlite3_vfs *pVfs, int iErr, char *zErr) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    return pRoot->xGetLastError(pRoot, iErr, zErr);
}

/*
** Override system calls.
*/
static int vfstraceSetSystemCall(sqlite3_vfs *pVfs, const char *zName, sqlite3_syscall_ptr pFunc) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    return pRoot->xSetSystemCall(pRoot, zName, pFunc);
}
static sqlite3_syscall_ptr vfstraceGetSystemCall(sqlite3_vfs *pVfs, const char *zName) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    return pRoot->xGetSystemCall(pRoot, zName);
}
static const char *vfstraceNextSystemCall(sqlite3_vfs *pVfs, const char *zName) {
    vfstrace_info *pInfo = (vfstrace_info *)pVfs->pAppData;
    sqlite3_vfs *pRoot = pInfo->pRootVfs;
    return pRoot->xNextSystemCall(pRoot, zName);
}

/*
** Clients invoke this routine to construct a new trace-vfs shim.
**
** Return SQLITE_OK on success.
**
** SQLITE_NOMEM is returned in the case of a memory allocation error.
** SQLITE_NOTFOUND is returned if zOldVfsName does not exist.
*/
int vfstrace_register(const char *zTraceName,            /* Name of the newly constructed VFS */
                      const char *zOldVfsName,           /* Name of the underlying VFS */
                      int (*xOut)(const char *, void *), /* Output routine.  ex: fputs */
                      void *pOutArg,                     /* 2nd argument to xOut.  ex: stderr */
                      int makeDefault                    /* True to make the new VFS the default */
) {
    sqlite3_vfs *pNew;
    sqlite3_vfs *pRoot;
    vfstrace_info *pInfo;
    int nName;
    int nByte;

    pRoot = sqlite3_vfs_find(zOldVfsName);
    if (pRoot == 0)
        return SQLITE_NOTFOUND;
    nName = strlen(zTraceName);
    nByte = sizeof(*pNew) + sizeof(*pInfo) + nName + 1;
    pNew = sqlite3_malloc(nByte);
    if (pNew == 0)
        return SQLITE_NOMEM;
    memset(pNew, 0, nByte);
    pInfo = (vfstrace_info *)&pNew[1];
    pNew->iVersion = pRoot->iVersion;
    pNew->szOsFile = pRoot->szOsFile + sizeof(vfstrace_file);
    pNew->mxPathname = pRoot->mxPathname;
    pNew->zName = (char *)&pInfo[1];
    memcpy((char *)&pInfo[1], zTraceName, nName + 1);
    pNew->pAppData = pInfo;
    pNew->xOpen = vfstraceOpen;
    pNew->xDelete = vfstraceDelete;
    pNew->xAccess = vfstraceAccess;
    pNew->xFullPathname = vfstraceFullPathname;
    pNew->xDlOpen = pRoot->xDlOpen == 0 ? 0 : vfstraceDlOpen;
    pNew->xDlError = pRoot->xDlError == 0 ? 0 : vfstraceDlError;
    pNew->xDlSym = pRoot->xDlSym == 0 ? 0 : vfstraceDlSym;
    pNew->xDlClose = pRoot->xDlClose == 0 ? 0 : vfstraceDlClose;
    pNew->xRandomness = vfstraceRandomness;
    pNew->xSleep = vfstraceSleep;
    pNew->xCurrentTime = vfstraceCurrentTime;
    pNew->xGetLastError = pRoot->xGetLastError == 0 ? 0 : vfstraceGetLastError;
    if (pNew->iVersion >= 2) {
        pNew->xCurrentTimeInt64 = pRoot->xCurrentTimeInt64 == 0 ? 0 : vfstraceCurrentTimeInt64;
        if (pNew->iVersion >= 3) {
            pNew->xSetSystemCall = pRoot->xSetSystemCall == 0 ? 0 : vfstraceSetSystemCall;
            pNew->xGetSystemCall = pRoot->xGetSystemCall == 0 ? 0 : vfstraceGetSystemCall;
            pNew->xNextSystemCall = pRoot->xNextSystemCall == 0 ? 0 : vfstraceNextSystemCall;
        }
    }
    pInfo->pRootVfs = pRoot;
    pInfo->xOut = xOut;
    pInfo->pOutArg = pOutArg;
    pInfo->zVfsName = pNew->zName;
    pInfo->pTraceVfs = pNew;
    vfstrace_printf(pInfo, "%s.enabled_for(\"%s\")\n", pInfo->zVfsName, pRoot->zName);
    return sqlite3_vfs_register(pNew, makeDefault);
}