Add debugging code to count the number of iterations of each loop made as part of statement execution.

FossilOrigin-Name: c6a5b67ae1fb31120a40d2885b848ec2dab15c4e

manifest

@@ -1,5 +1,5 @@
-C Take\ssteps\sto\savoid\smisestimating\srange\squery\scosts\sbased\son\sSTAT4\sdata\ndue\sto\sthe\sroundoff\serror\sof\sconverting\sfrom\sintegers\sto\sLogEst\sand\sback\nto\sintegers.
-D 2014-10-22T15:27:05.734
+C Add\sdebugging\scode\sto\scount\sthe\snumber\sof\siterations\sof\seach\sloop\smade\sas\spart\sof\sstatement\sexecution.
+D 2014-10-23T17:26:22.165
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in cf57f673d77606ab0f2d9627ca52a9ba1464146a
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -228,8 +228,8 @@ F src/random.c d10c1f85b6709ca97278428fd5db5bbb9c74eece
 F src/resolve.c a3466128b52a86c466e47ac1a19e2174f7b5cf89
 F src/rowset.c eccf6af6d620aaa4579bd3b72c1b6395d9e9fa1e
 F src/select.c 428165951748151e87a15295b7357221433e311b
-F src/shell.c 282f8f5278e0c78eb442217531172ec9e1538796
-F src/sqlite.h.in 4a5e5158c189d2bcd45c7c4607c2c0eb6d25c153
+F src/shell.c ed2796b3bb5e21c8a7965c846fb5eba87d26aa65
+F src/sqlite.h.in 7b30552eaf9ddd2a820ef39b4d8b656a866abb77
 F src/sqlite3.rc 992c9f5fb8285ae285d6be28240a7e8d3a7f2bad
 F src/sqlite3ext.h 17d487c3c91b0b8c584a32fbeb393f6f795eea7d
 F src/sqliteInt.h d6d423b0f62846eb441236bc15417aeede2ebbdc
@@ -289,11 +289,11 @@ F src/update.c 729f6f18fc27740591d085e1172cebe311144bf0
 F src/utf.c fc6b889ba0779b7722634cdeaa25f1930d93820c
 F src/util.c 4006c01772bd8d8ac4306d523bbcee41d3e392d8
 F src/vacuum.c 59f03f92bcff57faa6a8ca256eb29ccddfb0614a
-F src/vdbe.c 5ee15a66ce07e0482b92aa29e4dd0c5827a22d79
-F src/vdbe.h 09f5b4e3719fa454f252322b1cdab5cf1f361327
-F src/vdbeInt.h e2a060a55ee18a6ab973353a5e2ec7ee569bf787
-F src/vdbeapi.c 37a6c6ae284a97bcace365f2f0a225680c0499d9
-F src/vdbeaux.c edbb7a9c8b2a8f7a68ac75c2475edd4040266b76
+F src/vdbe.c 5acb0a03f449f6488dbfb12f7fbe5953431e0c0e
+F src/vdbe.h 6bf91795a5775a1950fd01e716906eeb114734c6
+F src/vdbeInt.h 0fdc28cfa597bf8fd763eb085cc84945a7517b88
+F src/vdbeapi.c cbfb0fed9b36cf7db75e7b9fa721ba981b13e8e8
+F src/vdbeaux.c f9954f3100cbf92a2a976f34de0a109c10bfa8ab
 F src/vdbeblob.c 848238dc73e93e48432991bb5651bf87d865eca4
 F src/vdbemem.c 31d8eabb0cd78bfeab4e5124c7363c3e9e54db9f
 F src/vdbesort.c 975aeffa99acb0991b2f288d30294756bff41438
@@ -302,7 +302,7 @@ F src/vtab.c cb0c194303fea276b48d7d4b6d970b5a96bde8de
 F src/wal.c 10e7de7ce90865a68153f001a61f1d985cd17983
 F src/wal.h df01efe09c5cb8c8e391ff1715cca294f89668a4
 F src/walker.c c253b95b4ee44b21c406e2a1052636c31ea27804
-F src/where.c 5099c42e24c63969b3cf3b52e18c1a36cb841a34
+F src/where.c c9613a13a066a650675e66515d28fd4ecab5ab17
 F src/whereInt.h 4b459cdbfc9b01f5f27673a35f9967e4dea917e8
 F test/8_3_names.test ebbb5cd36741350040fd28b432ceadf495be25b2
 F test/aggerror.test a867e273ef9e3d7919f03ef4f0e8c0d2767944f2
@@ -1205,7 +1205,10 @@ F tool/vdbe_profile.tcl 67746953071a9f8f2f668b73fe899074e2c6d8c1
 F tool/warnings-clang.sh f6aa929dc20ef1f856af04a730772f59283631d4
 F tool/warnings.sh 0abfd78ceb09b7f7c27c688c8e3fe93268a13b32
 F tool/win/sqlite.vsix deb315d026cc8400325c5863eef847784a219a2f
-P 3e922208b68563489c7766abb9afb4885113e7b8
-R 5c508733aebac553de79291a7eabd709
-U drh
-Z a3d7104c7f173585d7e788d6453aa065
+P 3c933bf95f291f7957580d823dce92c981375a5c
+R dd407ae864af5a809eb144aec1696724
+T *branch * debug-loopcounters
+T *sym-debug-loopcounters *
+T -sym-trunk *
+U dan
+Z b7fd2f254655f3286afc23e1478fb538

manifest.uuid

@@ -1 +1 @@
-3c933bf95f291f7957580d823dce92c981375a5c
+c6a5b67ae1fb31120a40d2885b848ec2dab15c4e

src/shell.c

@@ -457,6 +457,7 @@ struct ShellState {
   int echoOn;            /* True to echo input commands */
   int autoEQP;           /* Run EXPLAIN QUERY PLAN prior to seach SQL stmt */
   int statsOn;           /* True to display memory stats before each finalize */
+  int loopCountersOn;    /* True to display loop counters */
   int outCount;          /* Revert to stdout when reaching zero */
   int cnt;               /* Number of records displayed so far */
   FILE *out;             /* Write results here */
@@ -1089,6 +1090,30 @@ static char *save_err_msg(
   return zErrMsg;
 }
 
+static void display_loop_counters(
+  sqlite3 *db,                /* Database to query */
+  ShellState *pArg            /* Pointer to ShellState */
+){
+#if !defined(SQLITE_DEBUG) || !defined(SQLITE_ENABLE_LOOPCOUNTERS)
+  fprintf(pArg->out, 
+      "No loop counters. "
+      "Rebuild with SQLITE_DEBUG and SQLITE_ENABLE_LOOPCOUNTERS"
+  );
+#else
+  int i;
+  for(i=0; 1; i++){
+    int nTest;
+    int nVisit;
+    int iSub;
+    int iLoop;
+    const char *zLoop;
+    zLoop = sqlite3_stmt_loopcounter(pArg->pStmt, i, &iSub, &iLoop, &nTest, &nVisit);
+    if( zLoop==0 ) break;
+    fprintf(pArg->out, "loop %d.%d: (%d/%d) %s\n", iSub, iLoop, nVisit, nTest, zLoop);
+  }
+#endif
+}
+
 /*
 ** Display memory stats.
 */
@@ -1423,6 +1448,11 @@ static int shell_exec(
         display_stats(db, pArg, 0);
       }
 
+      /* print loop-counters if required */
+      if( pArg && pArg->loopCountersOn ){
+        display_loop_counters(db, pArg);
+      }
+
       /* Finalize the statement just executed. If this fails, save a 
       ** copy of the error message. Otherwise, set zSql to point to the
       ** next statement to execute. */
@@ -2819,6 +2849,16 @@ static int do_meta_command(char *zLine, ShellState *p){
     }
   }else
 
+  if( c=='l' && strncmp(azArg[0], "loopcounters", n)==0 ){
+    if( nArg==2 ){
+      p->loopCountersOn = booleanValue(azArg[1]);
+    }else{
+      fprintf(stderr, "Usage: .loopcounters on|off\n");
+      rc = 1;
+    }
+  }else
+
+
   if( c=='m' && strncmp(azArg[0], "mode", n)==0 ){
     const char *zMode = nArg>=2 ? azArg[1] : "";
     int n2 = (int)strlen(zMode);
@@ -4140,6 +4180,8 @@ int main(int argc, char **argv){
       data.autoEQP = 1;
     }else if( strcmp(z,"-stats")==0 ){
       data.statsOn = 1;
+    }else if( strcmp(z,"-loopcounters")==0 ){
+      data.loopCountersOn = 1;
     }else if( strcmp(z,"-bail")==0 ){
       bail_on_error = 1;
     }else if( strcmp(z,"-version")==0 ){

src/sqlite.h.in

@@ -7406,6 +7406,29 @@ int sqlite3_vtab_on_conflict(sqlite3 *);
 /* #define SQLITE_ABORT 4  // Also an error code */
 #define SQLITE_REPLACE  5
 
+/*
+** This API function is only available if SQLite is compiled with both 
+** SQLITE_DEBUG and SQLITE_ENABLE_LOOPCOUNTERS defined. It is primarily 
+** useful with SELECT statements.
+**
+** Each call returns information corresponding to a single "loop" run as
+** part of the statement. Each loop corresponds to a single "SEARCH" or "SCAN"
+** row that would be returned by EXPLAIN QUERY PLAN on the same SQL statement.
+** The second parameter - idx - determines which loop information is returned
+** regarding. If idx is less than 0 or greater than or equal to the number of
+** loops in the statement, NULL Is returned and the final values of the four
+** output parameters are undefined. Otherwise, the return value points to a
+** string describing the loop in question - the same string as would appear as
+** the fourth column of EXPLAIN QUERY PLAN output. The first two integer output
+** parameters are set to the values that would be returned as the first two
+** columns of the same row of EQP output.
+**
+** The third output parameter is set to the number of rows that were visited
+** by the loop the last time the statement was run. The fourth output parameter
+** is set to the number of rows visited including those excluded by non-indexed
+** WHERE terms.
+*/
+const char *sqlite3_stmt_loopcounter(sqlite3_stmt*, int idx, int*, int*, int*, int*);
 
 
 /*

src/vdbe.c

@@ -605,6 +605,9 @@ int sqlite3VdbeExec(
     if( db->mallocFailed ) goto no_mem;
 #ifdef VDBE_PROFILE
     start = sqlite3Hwtime();
+#endif
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+    if( p->pFrame==0 ) p->anExec[pc]++;
 #endif
     nVmStep++;
     pOp = &aOp[pc];

src/vdbe.h

@@ -282,4 +282,10 @@ void sqlite3VdbeLinkSubProgram(Vdbe *, SubProgram *);
 # define VDBE_OFFSET_LINENO(x) 0
 #endif
 
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+void sqlite3VdbeLoopCounter(Vdbe*, int addrExplain, int addrTest, int addrBody);
+#else
+# define sqlite3VdbeLoopCounter(a,b,c,d)
+#endif
+
 #endif

src/vdbeInt.h

@@ -295,6 +295,13 @@ struct Explain {
 */
 typedef unsigned bft;  /* Bit Field Type */
 
+typedef struct LoopCounter LoopCounter;
+struct LoopCounter {
+  int addrExplain;                /* OP_Explain for loop */
+  int addrTest;                   /* Address of non-indexed WHERE term tests */
+  int addrBody;                   /* Address of loop body */
+};
+
 /*
 ** An instance of the virtual machine.  This structure contains the complete
 ** state of the virtual machine.
@@ -367,6 +374,11 @@ struct Vdbe {
   int nOnceFlag;          /* Size of array aOnceFlag[] */
   u8 *aOnceFlag;          /* Flags for OP_Once */
   AuxData *pAuxData;      /* Linked list of auxdata allocations */
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+  int *anExec;            /* Number of times each op has been executed */
+  int nLoop;              /* Entries in aLoop[] */
+  LoopCounter *aLoop;     /* Loop definitions for sqlite3_stmt_loopcounter() */
+#endif
 };
 
 /*

src/vdbeapi.c

@@ -482,6 +482,9 @@ static int sqlite3Step(Vdbe *p){
       sqlite3OsCurrentTimeInt64(db->pVfs, &p->startTime);
     }
 #endif
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+    memset(p->anExec, 0, sizeof(int) * p->nOp);
+#endif
 
     db->nVdbeActive++;
     if( p->readOnly==0 ) db->nVdbeWrite++;
@@ -1454,3 +1457,19 @@ int sqlite3_stmt_status(sqlite3_stmt *pStmt, int op, int resetFlag){
   if( resetFlag ) pVdbe->aCounter[op] = 0;
   return (int)v;
 }
+
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+const char *sqlite3_stmt_loopcounter(
+    sqlite3_stmt *pStmt, int idx, int *piSub, int *piLoop, int *pnTest, int *pnVisit
+){
+  Vdbe *p = (Vdbe*)pStmt;
+  if( idx>=p->nLoop || idx<0 ) return 0;
+  *piSub = p->aOp[p->aLoop[idx].addrExplain].p1;
+  *piLoop = p->aOp[p->aLoop[idx].addrExplain].p2;
+  *pnTest = p->anExec[ p->aLoop[idx].addrTest ];
+  *pnVisit = p->anExec[ p->aLoop[idx].addrBody ];
+  return p->aOp[p->aLoop[idx].addrExplain].p4.z;
+}
+#endif
+
+

src/vdbeaux.c

@@ -597,6 +597,29 @@ int sqlite3VdbeAddOpList(Vdbe *p, int nOp, VdbeOpList const *aOp, int iLineno){
   return addr;
 }
 
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+void sqlite3VdbeLoopCounter(
+  Vdbe *p, 
+  int addrExplain, 
+  int addrTest, 
+  int addrBody
+){
+  int nByte = (p->nLoop+1) * sizeof(LoopCounter);
+  if( addrTest>=0 ){
+    p->aLoop = (LoopCounter*)sqlite3DbReallocOrFree(p->db, p->aLoop, nByte);
+    p->nLoop++;
+  }
+  if( p->aLoop ){
+    LoopCounter *pNew = &p->aLoop[p->nLoop-1];
+    pNew->addrExplain = addrExplain;
+    if( addrTest>=0 ){
+      pNew->addrTest = addrTest;
+      pNew->addrBody = addrBody;
+    }
+  }
+}
+#endif
+
 /*
 ** Change the value of the P1 operand for a specific instruction.
 ** This routine is useful when a large program is loaded from a
@@ -1702,6 +1725,10 @@ void sqlite3VdbeMakeReady(
     zEnd = &zCsr[nByte];
   }while( nByte && !db->mallocFailed );
 
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+  p->anExec = (int*)sqlite3DbMallocZero(db, sizeof(int) * p->nOp);
+#endif
+
   p->nCursor = nCursor;
   p->nOnceFlag = nOnce;
   if( p->aVar ){
@@ -2679,6 +2706,10 @@ void sqlite3VdbeClearObject(sqlite3 *db, Vdbe *p){
   sqlite3DbFree(db, p->aColName);
   sqlite3DbFree(db, p->zSql);
   sqlite3DbFree(db, p->pFree);
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+  sqlite3DbFree(db, p->aLoop);
+  sqlite3DbFree(db, p->anExec);
+#endif
 }
 
 /*

src/where.c

@@ -2908,17 +2908,19 @@ static Bitmask codeOneLoopStart(
   WhereLoop *pLoop;    /* The WhereLoop object being coded */
   WhereClause *pWC;    /* Decomposition of the entire WHERE clause */
   WhereTerm *pTerm;               /* A WHERE clause term */
-  Parse *pParse;                  /* Parsing context */
+  Parse *pParse = pWInfo->pParse; /* Parsing context */
   sqlite3 *db;                    /* Database connection */
-  Vdbe *v;                        /* The prepared stmt under constructions */
+  Vdbe *v = pParse->pVdbe;        /* The prepared stmt under constructions */
   struct SrcList_item *pTabItem;  /* FROM clause term being coded */
   int addrBrk;                    /* Jump here to break out of the loop */
   int addrCont;                   /* Jump here to continue with next cycle */
   int iRowidReg = 0;        /* Rowid is stored in this register, if not zero */
   int iReleaseReg = 0;      /* Temp register to free before returning */
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+  int addrExplain = sqlite3VdbeCurrentAddr(v)-1;
+  int addrTest;             /* Address of non-indexed WHERE clause test */
+#endif
 
-  pParse = pWInfo->pParse;
-  v = pParse->pVdbe;
   pWC = &pWInfo->sWC;
   db = pParse->db;
   pLevel = &pWInfo->a[iLevel];
@@ -3555,6 +3557,7 @@ static Bitmask codeOneLoopStart(
         assert( pSubWInfo || pParse->nErr || db->mallocFailed );
         if( pSubWInfo ){
           WhereLoop *pSubLoop;
+          sqlite3VdbeLoopCounter(v, sqlite3VdbeCurrentAddr(v), -1, -1);
           explainOneScan(
               pParse, pOrTab, &pSubWInfo->a[0], iLevel, pLevel->iFrom, 0
           );
@@ -3688,6 +3691,10 @@ static Bitmask codeOneLoopStart(
     }
   }
 
+#if defined(SQLITE_DEBUG) && defined(SQLITE_ENABLE_LOOPCOUNTERS)
+  addrTest = sqlite3VdbeCurrentAddr(v);
+#endif 
+
   /* Insert code to test every subexpression that can be completely
   ** computed using the current set of tables.
   */
@@ -3766,6 +3773,10 @@ static Bitmask codeOneLoopStart(
     }
   }
 
+  if( pParse->pTriggerTab==0 && 0==(pLoop->wsFlags & WHERE_MULTI_OR) ){
+    sqlite3VdbeLoopCounter(v, addrExplain, addrTest, sqlite3VdbeCurrentAddr(v));
+  }
+
   return pLevel->notReady;
 }