Add further instrumentation to the bc_test1.c test app.

FossilOrigin-Name: 5528de4a53c19557798b6169e1d738f1a301e131

manifest

@@ -1,5 +1,5 @@
-C Use\spthreads\smutexes\sand\sconditions\sto\ssynchronize\sthreads\sin\sbc_test1.
+C Add\sfurther\sinstrumentation\sto\sthe\sbc_test1.c\stest\sapp.
-D 2016-05-21T18:50:56.299
+D 2016-05-26T20:52:15.750
 F Makefile.in 9e816d0323e418fbc0f8b2c05fc14e0b3763d9e8
 F Makefile.linux-gcc 7bc79876b875010e8c8f9502eb935ca92aa3c434
 F Makefile.msc 71b8b16cf9393f68e2e2035486ca104872558836
@@ -521,7 +521,7 @@ F test/backup_malloc.test 7162d604ec2b4683c4b3799a48657fb8b5e2d450
 F test/badutf.test d5360fc31f643d37a973ab0d8b4fb85799c3169f
 F test/badutf2.test f5bc7f2d280670ecd79b9cf4f0f1760c607fe51f
 F test/bc_common.tcl b5e42d80305be95697e6370e015af571e5333a1c
-F test/bc_test1.c 874d03ffabbd565a6cf9a7eec23d3deafd3c8f1c
+F test/bc_test1.c 05cd99276a5dc2de0e28f3b1095c343393e12f87
 F test/bestindex1.test 0cf1bd2d7b97d3a3a8c10736125274f64765c4ee
 F test/bestindex2.test 4a06b8922ab2fd09434870da8d1cdf525aaf7060
 F test/between.test 34d375fb5ce1ae283ffe82b6b233e9f38e84fc6c
@@ -1295,7 +1295,7 @@ F test/triggerC.test 302d8995f5ffe63bbc15053abb3ef7a39cf5a092
 F test/triggerD.test 8e7f3921a92a5797d472732108109e44575fa650
 F test/triggerE.test 15fa63f1097db1f83dd62d121616006978063d1f
 F test/tt3_checkpoint.c 9e75cf7c1c364f52e1c47fd0f14c4340a9db0fe1
-F test/tt3_core.c 77d7acbe43f78802284da8ef04650f6f5f32f7a0
+F test/tt3_core.c 01a7cd1a4f10a666f404c46360da15468522d52e
 F test/tt3_index.c 39eec10a35f57672225be4d182862152896dee4a
 F test/tt3_lookaside1.c 0377e202c3c2a50d688cb65ba203afeda6fafeb9
 F test/tt3_stress.c c57d804716165811d979d4a719e05baccd79277f
@@ -1491,7 +1491,7 @@ F vsixtest/vsixtest.tcl 6a9a6ab600c25a91a7acc6293828957a386a8a93
 F vsixtest/vsixtest.vcxproj.data 2ed517e100c66dc455b492e1a33350c1b20fbcdc
 F vsixtest/vsixtest.vcxproj.filters 37e51ffedcdb064aad6ff33b6148725226cd608e
 F vsixtest/vsixtest_TemporaryKey.pfx e5b1b036facdb453873e7084e1cae9102ccc67a0
-P ec6ef5f2c2dc18e1a19c205f365f4071f0870b68
+P f33aa76f074d8686a5a5c0edecabb71cb259c48d
-R 9d74e8a08d57f3a5262646881b7fcf49
+R 3e6ef002903d2cc9312cf24b4caaa4ad
 U dan
-Z 51f0c57ee889307d403d3ab523c9aec8
+Z 14c81df2e8a28af21f0d7f0b336be7a7

manifest.uuid

@@ -1 +1 @@
-f33aa76f074d8686a5a5c0edecabb71cb259c48d
+5528de4a53c19557798b6169e1d738f1a301e131

test/bc_test1.c

@@ -17,8 +17,28 @@
 #include <stddef.h>
 #include "tt3_core.c"
 
+#ifdef USE_OSINST
+# include "../src/test_osinst.c"
+#else
+# define vfslog_time() 0
+#endif
 
 typedef struct Config Config;
+typedef struct ThreadCtx ThreadCtx;
+
+#define THREAD_TIME_INSERT   0
+#define THREAD_TIME_COMMIT   1
+#define THREAD_TIME_ROLLBACK 2
+#define THREAD_TIME_WRITER   3
+#define THREAD_TIME_CKPT     4
+
+struct ThreadCtx {
+  Config *pConfig;
+  Sqlite *pDb;
+  Error *pErr;
+  sqlite3_int64 aTime[5];
+};
+
 struct Config {
   int nIPT;                       /* --inserts-per-transaction */
   int nThread;                    /* --threads */
@@ -26,6 +46,12 @@ struct Config {
   int bMutex;                     /* --mutex */
   int nAutoCkpt;                  /* --autockpt */
   int bRm;                        /* --rm */
+  int bClearCache;                /* --clear-cache */
+  int nMmap;                      /* mmap limit in MB */
+  char *zFile;
+  int bOsinst;                    /* True to use osinst */
+
+  ThreadCtx *aCtx;                /* Array of size nThread */
 
   pthread_cond_t cond;
   pthread_mutex_t mutex;
@@ -33,17 +59,12 @@ struct Config {
   sqlite3_vfs *pVfs;
 };
 
-typedef struct WalHookCtx WalHookCtx;
-struct WalHookCtx {
-  Config *pConfig;
-  Sqlite *pDb;
-  Error *pErr;
-};
 
 typedef struct VfsWrapperFd VfsWrapperFd;
 struct VfsWrapperFd {
   sqlite3_file base;              /* Base class */
   int bWriter;                    /* True if holding shm WRITER lock */
+  int iTid;
   Config *pConfig;
   sqlite3_file *pFd;              /* Underlying file descriptor */
 };
@@ -107,6 +128,11 @@ static int vfsWrapOpen(
   VfsWrapperFd *pWrapper = (VfsWrapperFd*)pFd;
   int rc;
 
+  memset(pWrapper, 0, sizeof(VfsWrapperFd));
+  if( flags & SQLITE_OPEN_MAIN_DB ){
+    pWrapper->iTid = (int)sqlite3_uri_int64(zName, "tid", 0);
+  }
+
   pWrapper->pFd = (sqlite3_file*)&pWrapper[1];
   pWrapper->pConfig = pConfig;
   rc = pConfig->pVfs->xOpen(pConfig->pVfs, zName, pWrapper->pFd, flags, fout);
@@ -258,18 +284,24 @@ static int vfsWrapShmLock(sqlite3_file *pFd, int offset, int n, int flags){
     pthread_mutex_lock(&pConfig->mutex);
     pWrapper->bWriter = 1;
     bMutex = 1;
-  }
+    if( pWrapper->iTid ){
-
+      sqlite3_int64 t = vfslog_time();
-  if( offset==0 && (flags & SQLITE_SHM_UNLOCK) && pWrapper->bWriter ){
+      pConfig->aCtx[pWrapper->iTid-1].aTime[THREAD_TIME_WRITER] -= t;
-    pthread_mutex_unlock(&pConfig->mutex);
+    }
-    pWrapper->bWriter = 0;
   }
 
   rc = pWrapper->pFd->pMethods->xShmLock(pWrapper->pFd, offset, n, flags);
 
-  if( rc!=SQLITE_OK && bMutex ){
+  if( (rc!=SQLITE_OK && bMutex)
+   || (offset==0 && (flags & SQLITE_SHM_UNLOCK) && pWrapper->bWriter)
+  ){
+    assert( pWrapper->bWriter );
     pthread_mutex_unlock(&pConfig->mutex);
     pWrapper->bWriter = 0;
+    if( pWrapper->iTid ){
+      sqlite3_int64 t = vfslog_time();
+      pConfig->aCtx[pWrapper->iTid-1].aTime[THREAD_TIME_WRITER] += t;
+    }
   }
 
   return rc;
@@ -317,15 +349,16 @@ static void create_vfs(Config *pConfig){
 ** Wal hook used by connections in thread_main().
 */
 static int thread_wal_hook(
-  void *pArg,                     /* Pointer to Config object */
+  void *pArg,                     /* Pointer to ThreadCtx object */
   sqlite3 *db,
   const char *zDb, 
   int nFrame
 ){
-  WalHookCtx *pCtx = (WalHookCtx*)pArg;
+  ThreadCtx *pCtx = (ThreadCtx*)pArg;
   Config *pConfig = pCtx->pConfig;
 
-  if( nFrame>=pConfig->nAutoCkpt ){
+  if( pConfig->nAutoCkpt && nFrame>=pConfig->nAutoCkpt ){
+    pCtx->aTime[THREAD_TIME_CKPT] -= vfslog_time();
     pthread_mutex_lock(&pConfig->mutex);
     if( pConfig->nCondWait>=0 ){
       pConfig->nCondWait++;
@@ -338,6 +371,7 @@ static int thread_wal_hook(
       pConfig->nCondWait--;
     }
     pthread_mutex_unlock(&pConfig->mutex);
+    pCtx->aTime[THREAD_TIME_CKPT] += vfslog_time();
   }
 
   return SQLITE_OK;
@@ -345,35 +379,63 @@ static int thread_wal_hook(
 
 
 static char *thread_main(int iTid, void *pArg){
-  WalHookCtx ctx;
   Config *pConfig = (Config*)pArg;
   Error err = {0};                /* Error code and message */
   Sqlite db = {0};                /* SQLite database connection */
   int nAttempt = 0;               /* Attempted transactions */
   int nCommit = 0;                /* Successful transactions */
   int j;
+  ThreadCtx *pCtx = &pConfig->aCtx[iTid-1];
+  char *zUri = 0;
+
+#ifdef USE_OSINST
+  char *zOsinstName = 0;
+  char *zLogName = 0;
+  if( pConfig->bOsinst ){
+    zOsinstName = sqlite3_mprintf("osinst%d", iTid);
+    zLogName = sqlite3_mprintf("bc_test1.log.%d.%d", (int)getpid(), iTid);
+    zUri = sqlite3_mprintf(
+        "file:%s?vfs=%s&tid=%d", pConfig->zFile, zOsinstName, iTid
+    );
+    sqlite3_vfslog_new(zOsinstName, 0, zLogName);
+    opendb(&err, &db, zUri, 0);
+  }else
+#endif
+  {
+    zUri = sqlite3_mprintf("file:%s?tid=%d", pConfig->zFile, iTid);
+    opendb(&err, &db, zUri, 0);
+  }
 
-  opendb(&err, &db, "xyz.db", 0);
   sqlite3_busy_handler(db.db, 0, 0);
   sql_script_printf(&err, &db, 
-      "PRAGMA wal_autocheckpoint = %d;"
+      "PRAGMA wal_autocheckpoint = 0;"
-      "PRAGMA synchronous = 0;", pConfig->nAutoCkpt
+      "PRAGMA synchronous = 0;"
+      "PRAGMA mmap_limit = %lld;",
+      (i64)(pConfig->nMmap) * 1024 * 1024
   );
 
-  ctx.pConfig = pConfig;
+  pCtx->pConfig = pConfig;
-  ctx.pErr = &err;
+  pCtx->pErr = &err;
-  ctx.pDb = &db;
+  pCtx->pDb = &db;
-  sqlite3_wal_hook(db.db, thread_wal_hook, (void*)&ctx);
+  sqlite3_wal_hook(db.db, thread_wal_hook, (void*)pCtx);
 
   while( !timetostop(&err) ){
     execsql(&err, &db, "BEGIN CONCURRENT");
+
+    pCtx->aTime[THREAD_TIME_INSERT] -= vfslog_time();
     for(j=0; j<pConfig->nIPT; j++){
       execsql(&err, &db, 
           "INSERT INTO t1 VALUES"
           "(randomblob(10), randomblob(20), randomblob(30), randomblob(200))"
       );
     }
+    pCtx->aTime[THREAD_TIME_INSERT] += vfslog_time();
+
+    pCtx->aTime[THREAD_TIME_COMMIT] -= vfslog_time();
     execsql(&err, &db, "COMMIT");
+    pCtx->aTime[THREAD_TIME_COMMIT] += vfslog_time();
+
+    pCtx->aTime[THREAD_TIME_ROLLBACK] -= vfslog_time();
     nAttempt++;
     if( err.rc==SQLITE_OK ){
       nCommit++;
@@ -381,16 +443,41 @@ static char *thread_main(int iTid, void *pArg){
       clear_error(&err, SQLITE_BUSY);
       execsql(&err, &db, "ROLLBACK");
     }
+    pCtx->aTime[THREAD_TIME_ROLLBACK] += vfslog_time();
+
+    if( pConfig->bClearCache ){
+      sqlite3_db_release_memory(db.db);
+    }
   }
 
   closedb(&err, &db);
 
+#ifdef USE_OSINST
+  if( pConfig->bOsinst ){
+    sqlite3_vfslog_finalize(zOsinstName);
+    sqlite3_free(zOsinstName);
+    sqlite3_free(zLogName);
+  }
+#endif
+  sqlite3_free(zUri);
+
   pthread_mutex_lock(&pConfig->mutex);
   pConfig->nCondWait = -1;
   pthread_cond_broadcast(&pConfig->cond);
   pthread_mutex_unlock(&pConfig->mutex);
 
-  return sqlite3_mprintf("%d/%d successful commits", nCommit, nAttempt);
+  return sqlite3_mprintf("commits: %d/%d insert: %dms"
+      " commit: %dms"
+      " rollback: %dms" 
+      " writer: %dms"
+      " checkpoint: %dms", 
+      nCommit, nAttempt, 
+      (int)(pCtx->aTime[THREAD_TIME_INSERT]/1000), 
+      (int)(pCtx->aTime[THREAD_TIME_COMMIT]/1000), 
+      (int)(pCtx->aTime[THREAD_TIME_ROLLBACK]/1000),
+      (int)(pCtx->aTime[THREAD_TIME_WRITER]/1000),
+      (int)(pCtx->aTime[THREAD_TIME_CKPT]/1000)
+  );
 }
 
 int main(int argc, const char **argv){
@@ -407,6 +494,10 @@ int main(int argc, const char **argv){
     { "--mutex",   CMDLINE_BOOL, offsetof(Config, bMutex) },
     { "--rm",      CMDLINE_BOOL, offsetof(Config, bRm) },
     { "--autockpt",CMDLINE_INT,  offsetof(Config, nAutoCkpt) },
+    { "--mmap",    CMDLINE_INT,  offsetof(Config, nMmap) },
+    { "--clear-cache",    CMDLINE_BOOL,  offsetof(Config, bClearCache) },
+    { "--file",    CMDLINE_STRING,  offsetof(Config, zFile) },
+    { "--osinst",  CMDLINE_BOOL,  offsetof(Config, bOsinst) },
     { 0, 0, 0 }
   };
 
@@ -416,6 +507,9 @@ int main(int argc, const char **argv){
     printf("With: %s\n", z);
     sqlite3_free(z);
   }
+  if( conf.zFile==0 ){
+    conf.zFile = "xyz.db";
+  }
 
   /* Create the special VFS - "wrapper". And the mutex and condition 
   ** variable. */
@@ -423,8 +517,11 @@ int main(int argc, const char **argv){
   pthread_mutex_init(&conf.mutex, 0);
   pthread_cond_init(&conf.cond, 0);
 
+  conf.aCtx = sqlite3_malloc(sizeof(ThreadCtx) * conf.nThread);
+  memset(conf.aCtx, 0, sizeof(ThreadCtx) * conf.nThread);
+
   /* Ensure the schema has been created */
-  opendb(&err, &db, "xyz.db", conf.bRm);
+  opendb(&err, &db, conf.zFile, conf.bRm);
   sql_script(&err, &db,
       "PRAGMA journal_mode = wal;"
       "CREATE TABLE IF NOT EXISTS t1(a PRIMARY KEY, b, c, d) WITHOUT ROWID;"
@@ -434,7 +531,7 @@ int main(int argc, const char **argv){
 
   setstoptime(&err, conf.nSecond*1000);
   if( conf.nThread==1 ){
-    char *z = thread_main(0, (void*)&conf);
+    char *z = thread_main(1, (void*)&conf);
     printf("Thread 0 says: %s\n", (z==0 ? "..." : z));
     fflush(stdout);
   }else{
@@ -445,10 +542,11 @@ int main(int argc, const char **argv){
   }
 
   if( err.rc==SQLITE_OK ){
-    printf("Database is %dK\n", (int)(filesize(&err, "xyz.db") / 1024));
+    printf("Database is %dK\n", (int)(filesize(&err, conf.zFile) / 1024));
   }
   if( err.rc==SQLITE_OK ){
-    printf("Wal file is %dK\n", (int)(filesize(&err, "xyz.db-wal") / 1024));
+    char *zWal = sqlite3_mprintf("%s-wal", conf.zFile);
+    printf("Wal file is %dK\n", (int)(filesize(&err, zWal) / 1024));
   }
 
   closedb(&err, &db);

test/tt3_core.c

@@ -69,8 +69,9 @@
 /************************************************************************
 ** Start of command line processing utilities.
 */
-#define CMDLINE_INT   1
+#define CMDLINE_INT     1
-#define CMDLINE_BOOL  2
+#define CMDLINE_BOOL    2
+#define CMDLINE_STRING  3
 
 typedef struct CmdlineArg CmdlineArg;
 struct CmdlineArg {
@@ -98,6 +99,7 @@ static void cmdline_usage(const char *zPrg, CmdlineArg *apArg){
   for(i=0; apArg[i].zSwitch; i++){
     const char *zExtra = "";
     switch( apArg[i].eType ){
+      case CMDLINE_STRING: zExtra = "STRING"; break;
       case CMDLINE_INT: zExtra = "N"; break;
       case CMDLINE_BOOL: zExtra = ""; break;
       default:
@@ -120,6 +122,14 @@ static char *cmdline_construct(CmdlineArg *apArg, void *pObj){
     CmdlineArg *pArg = &apArg[iArg];
 
     switch( pArg->eType ){
+      case CMDLINE_STRING: {
+        char *zVal = *(char**)(p + pArg->iOffset);
+        if( zVal ){
+          zRet = sqlite3_mprintf("%z%s%s %s", zRet, zSpace, pArg->zSwitch,zVal);
+        }
+        break;
+      };
+
       case CMDLINE_INT: {
         zRet = sqlite3_mprintf("%z%s%s %d", zRet, zSpace, pArg->zSwitch, 
             *(int*)(p + pArg->iOffset)
@@ -171,6 +181,14 @@ static void cmdline_process(
             *(int*)(p + apArg[iArg].iOffset) = atoi(argv[i]);
             break;
 
+          case CMDLINE_STRING:
+            i++;
+            if( i==argc ){
+              cmdline_error("option requires an argument: %s", z);
+            }
+            *(char**)(p + apArg[iArg].iOffset) = sqlite3_mprintf("%s", argv[i]);
+            break;
+
           case CMDLINE_BOOL:
             *(int*)(p + apArg[iArg].iOffset) = 1;
             break;