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