/ Check-in [8a99efc0]
Login
SQLite training in Houston TX on 2019-11-05 (details)
Part of the 2019 Tcl Conference

Many hyperlinks are disabled.
Use anonymous login to enable hyperlinks.

Overview
Comment:Add extra instrumentation to test_osinst.c. Also the --binarylog option to the test scripts. (CVS 5106)
Downloads: Tarball | ZIP archive | SQL archive
Timelines: family | ancestors | descendants | both | trunk
Files: files | file ages | folders
SHA1: 8a99efc07f93bc11d21aa501349c81f0fd8abf7b
User & Date: danielk1977 2008-05-08 15:58:06
Context
2008-05-08
16:51
Fix recently introduced bug in tester.tcl. (CVS 5107) check-in: 4b573d4e user: danielk1977 tags: trunk
15:58
Add extra instrumentation to test_osinst.c. Also the --binarylog option to the test scripts. (CVS 5106) check-in: 8a99efc0 user: danielk1977 tags: trunk
15:18
Use a 6-byte rather than an 8-byte encoding for integers between 17592186044416 and 140737488355327. Ticket #3100. (CVS 5105) check-in: 0a4d26de user: drh tags: trunk
Changes
Hide Diffs Side-by-Side Diffs Ignore Whitespace Patch

Changes to src/test_osinst.c.

    22     22   **   sqlite3_instvfs_destroy()
    23     23   **   sqlite3_instvfs_configure()
    24     24   **
    25     25   **   sqlite3_instvfs_reset()
    26     26   **   sqlite3_instvfs_get()
    27     27   **
    28     28   **   sqlite3_instvfs_binarylog
           29  +**   sqlite3_instvfs_binarylog_marker
    29     30   **
    30     31   ** Tcl interface (omitted if SQLITE_TEST is not set):
    31     32   ** 
    32     33   **   sqlite3_instvfs create NAME ?PARENT?
    33     34   **
    34     35   **       Create and register new vfs called $NAME, which is a wrapper around
    35     36   **       the existing vfs $PARENT. If the PARENT argument is omitted, the
................................................................................
   113    114   #define OS_SYNC              17
   114    115   #define OS_TRUNCATE          18
   115    116   #define OS_UNLOCK            19
   116    117   #define OS_WRITE             20
   117    118   
   118    119   #define OS_NUMEVENTS         21
   119    120   
          121  +#define BINARYLOG_STRING     30
          122  +#define BINARYLOG_MARKER     31
          123  +
   120    124   struct InstVfs {
   121    125     sqlite3_vfs base;
   122    126     sqlite3_vfs *pVfs;
   123         -  
          127  +
   124    128     void *pClient;
   125    129     void (*xDel)(void *);
   126         -  void (*xCall)(void *, int, sqlite3_int64, const char *, int, int, sqlite3_int64);
          130  +  void (*xCall)(void *, int, int, sqlite3_int64, int, const char *, int, int, sqlite3_int64);
   127    131   
   128    132     /* Counters */
   129    133     sqlite3_int64 aTime[OS_NUMEVENTS];
   130    134     int aCount[OS_NUMEVENTS];
          135  +
          136  +  int iNextFileId;
   131    137   };
   132    138   typedef struct InstVfs InstVfs;
   133    139   
   134    140   #define REALVFS(p) (((InstVfs *)(p))->pVfs)
   135    141   
   136    142   typedef struct inst_file inst_file;
   137    143   struct inst_file {
   138    144     sqlite3_file base;
   139    145     sqlite3_file *pReal;
   140    146     InstVfs *pInstVfs;
   141    147     const char *zName;
          148  +  int iFileId;               /* File id number */
   142    149     int flags;
   143    150   };
   144    151   
   145    152   /*
   146    153   ** Method declarations for inst_file.
   147    154   */
   148    155   static int instClose(sqlite3_file*);
................................................................................
   169    176   static void *instDlOpen(sqlite3_vfs*, const char *zFilename);
   170    177   static void instDlError(sqlite3_vfs*, int nByte, char *zErrMsg);
   171    178   static void *instDlSym(sqlite3_vfs*,void*, const char *zSymbol);
   172    179   static void instDlClose(sqlite3_vfs*, void*);
   173    180   static int instRandomness(sqlite3_vfs*, int nByte, char *zOut);
   174    181   static int instSleep(sqlite3_vfs*, int microseconds);
   175    182   static int instCurrentTime(sqlite3_vfs*, double*);
          183  +
          184  +static void binarylog_blob(sqlite3_vfs *, const char *, int); 
   176    185   
   177    186   static sqlite3_vfs inst_vfs = {
   178    187     1,                      /* iVersion */
   179    188     sizeof(inst_file),      /* szOsFile */
   180    189     INST_MAX_PATHNAME,      /* mxPathname */
   181    190     0,                      /* pNext */
   182    191     0,                      /* zName */
................................................................................
   234    243     int rc;                                    \
   235    244     sqlite3_int64 t = osinst_hwtime();         \
   236    245     rc = Call;                                 \
   237    246     t = osinst_hwtime() - t;                   \
   238    247     pInstVfs->aTime[eEvent] += t;              \
   239    248     pInstVfs->aCount[eEvent] += 1;             \
   240    249     if( pInstVfs->xCall ){                     \
   241         -    pInstVfs->xCall(pInstVfs->pClient, eEvent, t, p->zName, p->flags, A, B); \
          250  +    pInstVfs->xCall(                         \
          251  +      pInstVfs->pClient,eEvent,p->iFileId,t,rc,p->zName,p->flags,A,B  \
          252  +    );                                       \
   242    253     }                                          \
   243    254     return rc;                                 \
   244    255   }
   245    256   
   246    257   #define OS_TIME_VFS(eEvent, Z, flags, A, B, Call) {      \
   247    258     InstVfs *pInstVfs = (InstVfs *)pVfs;   \
   248    259     int rc;                                \
   249    260     sqlite3_int64 t = osinst_hwtime();     \
   250    261     rc = Call;                             \
   251    262     t = osinst_hwtime() - t;               \
   252    263     pInstVfs->aTime[eEvent] += t;          \
   253    264     pInstVfs->aCount[eEvent] += 1;         \
   254    265     if( pInstVfs->xCall ){                 \
   255         -    pInstVfs->xCall(pInstVfs->pClient, eEvent, t, Z, flags, A, B); \
          266  +    pInstVfs->xCall(pInstVfs->pClient,eEvent,0, t, rc, Z, flags, A, B); \
   256    267     }                                      \
   257    268     return rc;                             \
   258    269   }
   259    270   
   260    271   /*
   261    272   ** Close an inst-file.
   262    273   */
................................................................................
   302    313     OS_TIME_IO(OS_SYNC, flags, 0, p->pReal->pMethods->xSync(p->pReal, flags));
   303    314   }
   304    315   
   305    316   /*
   306    317   ** Return the current file-size of an inst-file.
   307    318   */
   308    319   static int instFileSize(sqlite3_file *pFile, sqlite_int64 *pSize){
   309         -  OS_TIME_IO(OS_FILESIZE, 0, 0, p->pReal->pMethods->xFileSize(p->pReal, pSize));
          320  +  OS_TIME_IO(OS_FILESIZE, (int)(*pSize), 0, 
          321  +    p->pReal->pMethods->xFileSize(p->pReal, pSize)
          322  +  );
   310    323   }
   311    324   
   312    325   /*
   313    326   ** Lock an inst-file.
   314    327   */
   315    328   static int instLock(sqlite3_file *pFile, int eLock){
   316    329     OS_TIME_IO(OS_LOCK, eLock, 0, p->pReal->pMethods->xLock(p->pReal, eLock));
................................................................................
   363    376   ){
   364    377     inst_file *p = (inst_file *)pFile;
   365    378     pFile->pMethods = &inst_io_methods;
   366    379     p->pReal = (sqlite3_file *)&p[1];
   367    380     p->pInstVfs = (InstVfs *)pVfs;
   368    381     p->zName = zName;
   369    382     p->flags = flags;
          383  +  p->iFileId = ++p->pInstVfs->iNextFileId;
   370    384   
   371         -  OS_TIME_VFS(OS_OPEN, zName, flags, 0, 0,
          385  +  binarylog_blob(pVfs, zName, -1);
          386  +  OS_TIME_VFS(OS_OPEN, zName, flags, p->iFileId, 0,
   372    387       REALVFS(pVfs)->xOpen(REALVFS(pVfs), zName, p->pReal, flags, pOutFlags)
   373    388     );
   374    389   }
   375    390   
   376    391   /*
   377    392   ** Delete the file located at zPath. If the dirSync argument is true,
   378    393   ** ensure the file-system modifications are synced to disk before
   379    394   ** returning.
   380    395   */
   381    396   static int instDelete(sqlite3_vfs *pVfs, const char *zPath, int dirSync){
          397  +  binarylog_blob(pVfs, zPath, -1);
   382    398     OS_TIME_VFS(OS_DELETE, zPath, 0, dirSync, 0,
   383    399       REALVFS(pVfs)->xDelete(REALVFS(pVfs), zPath, dirSync) 
   384    400     );
   385    401   }
   386    402   
   387    403   /*
   388    404   ** Test for access permissions. Return true if the requested permission
   389    405   ** is available, or false otherwise.
   390    406   */
   391    407   static int instAccess(sqlite3_vfs *pVfs, const char *zPath, int flags){
          408  +  binarylog_blob(pVfs, zPath, -1);
   392    409     OS_TIME_VFS(OS_ACCESS, zPath, 0, flags, 0, 
   393    410       REALVFS(pVfs)->xAccess(REALVFS(pVfs), zPath, flags) 
   394    411     );
   395    412   }
   396    413   
   397    414   /*
   398    415   ** Populate buffer zBufOut with a pathname suitable for use as a 
................................................................................
   504    521     }
   505    522   
   506    523     return (sqlite3_vfs *)p;
   507    524   }
   508    525   
   509    526   void sqlite3_instvfs_configure(
   510    527     sqlite3_vfs *pVfs,
   511         -  void (*xCall)(void*, int, sqlite3_int64, const char*, int, int, sqlite3_int64),
          528  +  void (*xCall)(
          529  +      void*, 
          530  +      int,                           /* File id */
          531  +      int,                           /* Event code */
          532  +      sqlite3_int64, 
          533  +      int,                           /* Return code */
          534  +      const char*,                   /* File name */
          535  +      int, 
          536  +      int, 
          537  +      sqlite3_int64
          538  +  ),
   512    539     void *pClient,
   513    540     void (*xDel)(void *)
   514    541   ){
   515    542     InstVfs *p = (InstVfs *)pVfs;
   516    543     assert( pVfs->xOpen==instOpen );
   517    544     if( p->xDel ){
   518    545       p->xDel(p->pClient);
................................................................................
   604    631     p[2] = v>>8;
   605    632     p[3] = v;
   606    633   }
   607    634   
   608    635   static void binarylog_xcall(
   609    636     void *p,
   610    637     int eEvent,
          638  +  int iFileId,
   611    639     sqlite3_int64 nClick,
          640  +  int return_code,
   612    641     const char *zName,
   613    642     int flags,
   614    643     int nByte,
   615    644     sqlite3_int64 iOffset
   616    645   ){
   617    646     InstVfsBinaryLog *pLog = (InstVfsBinaryLog *)p;
   618    647     unsigned char *zRec;
   619         -  if( (20+pLog->nBuf)>BINARYLOG_BUFFERSIZE ){
          648  +  if( (28+pLog->nBuf)>BINARYLOG_BUFFERSIZE ){
   620    649       sqlite3_file *pFile = pLog->pOut;
   621    650       pFile->pMethods->xWrite(pFile, pLog->zBuf, pLog->nBuf, pLog->iOffset);
   622    651       pLog->iOffset += pLog->nBuf;
   623    652       pLog->nBuf = 0;
   624    653     }
   625    654     zRec = (unsigned char *)&pLog->zBuf[pLog->nBuf];
   626    655     put32bits(&zRec[0], eEvent);
   627         -  put32bits(&zRec[4], (int)nClick);
   628         -  put32bits(&zRec[8], flags);
   629         -  put32bits(&zRec[12], nByte);
   630         -  put32bits(&zRec[16], (int)iOffset);
   631         -  pLog->nBuf += 20;
          656  +  put32bits(&zRec[4], (int)iFileId);
          657  +  put32bits(&zRec[8], (int)nClick);
          658  +  put32bits(&zRec[12], return_code);
          659  +  put32bits(&zRec[16], flags);
          660  +  put32bits(&zRec[20], nByte);
          661  +  put32bits(&zRec[24], (int)iOffset);
          662  +  pLog->nBuf += 28;
   632    663   }
   633    664   
   634    665   static void binarylog_xdel(void *p){
   635    666     /* Close the log file and free the memory allocated for the 
   636    667     ** InstVfsBinaryLog structure.
   637    668     */
   638    669     InstVfsBinaryLog *pLog = (InstVfsBinaryLog *)p;
................................................................................
   641    672       pFile->pMethods->xWrite(pFile, pLog->zBuf, pLog->nBuf, pLog->iOffset);
   642    673     }
   643    674     pFile->pMethods->xClose(pFile);
   644    675     sqlite3_free(pLog->pOut);
   645    676     sqlite3_free(pLog->zBuf);
   646    677     sqlite3_free(pLog);
   647    678   }
          679  +
          680  +static void binarylog_blob(
          681  +  sqlite3_vfs *pVfs,
          682  +  const char *zBlob,
          683  +  int nBlob
          684  +){
          685  +  unsigned char *zRec;
          686  +  int nWrite;
          687  +  InstVfs *pInstVfs = (InstVfs *)pVfs;
          688  +  InstVfsBinaryLog *pLog;
          689  +
          690  +  if( pVfs->xOpen!=instOpen || pInstVfs->xCall!=binarylog_xcall ){
          691  +    return;
          692  +  }
          693  +
          694  +  pLog = (InstVfsBinaryLog *)pInstVfs->pClient;
          695  +  if( nBlob<0 ){
          696  +    nBlob = strlen(zBlob);
          697  +  }
          698  +  nWrite = nBlob + 28;
          699  +
          700  +  if( (nWrite+pLog->nBuf)>BINARYLOG_BUFFERSIZE ){
          701  +    sqlite3_file *pFile = pLog->pOut;
          702  +    pFile->pMethods->xWrite(pFile, pLog->zBuf, pLog->nBuf, pLog->iOffset);
          703  +    pLog->iOffset += pLog->nBuf;
          704  +    pLog->nBuf = 0;
          705  +  }
          706  +
          707  +  zRec = (unsigned char *)&pLog->zBuf[pLog->nBuf];
          708  +  memset(zRec, 0, nWrite);
          709  +  put32bits(&zRec[0], BINARYLOG_STRING);
          710  +  put32bits(&zRec[4], (int)nBlob);
          711  +  memcpy(&zRec[28], zBlob, nBlob);
          712  +  pLog->nBuf += nWrite;
          713  +}
          714  +
          715  +void sqlite3_instvfs_binarylog_marker(
          716  +  sqlite3_vfs *pVfs,
          717  +  const char *zMarker
          718  +){
          719  +  InstVfs *pInstVfs = (InstVfs *)pVfs;
          720  +  InstVfsBinaryLog *pLog = (InstVfsBinaryLog *)pInstVfs->pClient;
          721  +  binarylog_blob(pVfs, zMarker, -1);
          722  +  binarylog_xcall(pLog, BINARYLOG_MARKER, 0, 0, 0, 0, 0, 0, 0);
          723  +}
   648    724   
   649    725   sqlite3_vfs *sqlite3_instvfs_binarylog(
   650    726     const char *zVfs,
   651    727     const char *zParentVfs, 
   652    728     const char *zLog
   653    729   ){
   654    730     InstVfsBinaryLog *p;
................................................................................
   703    779     Tcl_Obj *pScript;
   704    780   };
   705    781   typedef struct InstVfsCall InstVfsCall;
   706    782   
   707    783   static void test_instvfs_xcall(
   708    784     void *p,
   709    785     int eEvent,
          786  +  int iFileId,
   710    787     sqlite3_int64 nClick,
          788  +  int return_code,
   711    789     const char *zName,
   712    790     int flags,
   713    791     int nByte,
   714    792     sqlite3_int64 iOffset
   715    793   ){
   716    794     int rc;
   717    795     InstVfsCall *pCall = (InstVfsCall *)p;
................................................................................
   741    819   static int test_sqlite3_instvfs(
   742    820     void * clientData,
   743    821     Tcl_Interp *interp,
   744    822     int objc,
   745    823     Tcl_Obj *CONST objv[]
   746    824   ){
   747    825     static const char *IV_strs[] = 
   748         -               { "create",  "destroy",  "reset",  "report", "configure", "binarylog", 0 };
   749         -  enum IV_enum { IV_CREATE, IV_DESTROY, IV_RESET, IV_REPORT, IV_CONFIGURE, IV_BINARYLOG };
          826  +               { "create",  "destroy",  "reset",  "report", "configure", "binarylog", "marker", 0 };
          827  +  enum IV_enum { IV_CREATE, IV_DESTROY, IV_RESET, IV_REPORT, IV_CONFIGURE, IV_BINARYLOG, IV_MARKER };
   750    828     int iSub;
   751    829   
   752    830     if( objc<2 ){
   753    831       Tcl_WrongNumArgs(interp, 1, objv, "SUB-COMMAND ...");
   754    832     }
   755    833     if( Tcl_GetIndexFromObj(interp, objv[1], IV_strs, "sub-command", 0, &iSub) ){
   756    834       return TCL_ERROR;
................................................................................
   803    881         }
   804    882         if( isDefault ){
   805    883           sqlite3_vfs_register(p, 1);
   806    884         }
   807    885         Tcl_SetObjResult(interp, objv[2]);
   808    886         break;
   809    887       }
          888  +
          889  +    case IV_MARKER: {
          890  +      sqlite3_vfs *p;
          891  +      if( objc!=4 ){
          892  +        Tcl_WrongNumArgs(interp, 2, objv, "VFS MARKER");
          893  +        return TCL_ERROR;
          894  +      }
          895  +      p = sqlite3_vfs_find(Tcl_GetString(objv[2]));
          896  +      if( !p || p->xOpen!=instOpen ){
          897  +        Tcl_AppendResult(interp, "no such vfs: ", Tcl_GetString(objv[2]), 0);
          898  +        return TCL_ERROR;
          899  +      }
          900  +      sqlite3_instvfs_binarylog_marker(p, Tcl_GetString(objv[3]));
          901  +      Tcl_ResetResult(interp);
          902  +      break;
          903  +    }
   810    904   
   811    905       case IV_CONFIGURE: {
   812    906         InstVfsCall *pCall;
   813    907   
   814    908         sqlite3_vfs *p;
   815    909         if( objc!=4 ){
   816    910           Tcl_WrongNumArgs(interp, 2, objv, "NAME SCRIPT");

Changes to test/tester.tcl.

     7      7   #    May you find forgiveness for yourself and forgive others.
     8      8   #    May you share freely, never taking more than you give.
     9      9   #
    10     10   #***********************************************************************
    11     11   # This file implements some common TCL routines used for regression
    12     12   # testing the SQLite library
    13     13   #
    14         -# $Id: tester.tcl,v 1.119 2008/05/05 17:14:54 danielk1977 Exp $
           14  +# $Id: tester.tcl,v 1.120 2008/05/08 15:58:06 danielk1977 Exp $
    15     15   
    16     16   #
    17     17   # What for user input before continuing.  This gives an opportunity
    18     18   # to connect profiling tools to the process.
    19     19   #
    20     20   for {set i 0} {$i<[llength $argv]} {incr i} {
    21     21     if {[regexp {^-+pause$} [lindex $argv $i] all value]} {
................................................................................
    84     84       set ostrace_fd [open ostrace.sql w]
    85     85       puts $ostrace_fd "BEGIN;"
    86     86       if {[lindex $argv $i] eq "--ostrace"} {
    87     87         set    s "CREATE TABLE ostrace"
    88     88         append s "(method TEXT, clicks INT, file TEXT, i32 INT, i64 INT);"
    89     89         puts $ostrace_fd $s
    90     90         sqlite3_instvfs configure ostrace ostrace_call
           91  +      sqlite3_instvfs configure ostrace ostrace_call
    91     92       }
    92     93       set argv [lreplace $argv $i $i]
           94  +  }
           95  +  if {[lindex $argv $i] eq "--binarylog"} {
           96  +    set tester_do_binarylog 1
           97  +    sqlite3_instvfs binarylog -default binarylog ostrace.bin
           98  +    set argv [lreplace $argv $i $i]
    93     99     }
    94    100   }
    95    101   
    96    102   # 
    97    103   # Check the command-line arguments to set the maximum number of
    98    104   # errors tolerated before halting.
    99    105   #
................................................................................
   155    161   }
   156    162   
   157    163   # Invoke the do_test procedure to run a single test 
   158    164   #
   159    165   proc do_test {name cmd expected} {
   160    166     global argv nErr nTest skip_test maxErr
   161    167     sqlite3_memdebug_settitle $name
          168  +  if {$::tester_do_binarylog} {
          169  +    sqlite3_instvfs marker binarylog "Start of $name"
          170  +  }
   162    171     if {$skip_test} {
   163    172       set skip_test 0
   164    173       return
   165    174     }
   166    175     if {[llength $argv]==0} { 
   167    176       set go 1
   168    177     } else {
................................................................................
   188    197       incr nErr
   189    198       lappend ::failList $name
   190    199       if {$nErr>=$maxErr} {puts "*** Giving up..."; finalize_testing}
   191    200     } else {
   192    201       puts " Ok"
   193    202     }
   194    203     flush stdout
          204  +  if {$::tester_do_binarylog} {
          205  +    sqlite3_instvfs marker binarylog "End of $name"
          206  +  }
   195    207   }
   196    208   
   197    209   # Run an SQL script.  
   198    210   # Return the number of microseconds per statement.
   199    211   #
   200    212   proc speed_trial {name numstmt units sql} {
   201    213     puts -nonewline [format {%-21.21s } $name...]
................................................................................
   278    290     if {$nErr>0 && ![working_64bit_int]} {
   279    291       puts "******************************************************************"
   280    292       puts "N.B.:  The version of TCL that you used to build this test harness"
   281    293       puts "is defective in that it does not support 64-bit integers.  Some or"
   282    294       puts "all of the test failures above might be a result from this defect"
   283    295       puts "in your TCL build."
   284    296       puts "******************************************************************"
          297  +  }
          298  +  if {[info exists ::tester_do_binarylog]} {
          299  +    sqlite3_instvfs destroy binarylog
   285    300     }
   286    301     if {$sqlite_open_file_count} {
   287    302       puts "$sqlite_open_file_count files were left open"
   288    303       incr nErr
   289    304     }
   290    305     if {[info exists ::tester_do_ostrace]} {
   291    306       puts "Writing ostrace.sql..."