From: dan Date: Thu, 23 Oct 2014 17:26:22 +0000 (+0000) Subject: Add debugging code to count the number of iterations of each loop made as part of... X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=refs%2Fheads%2Fdebug-loopcounters;p=thirdparty%2Fsqlite.git Add debugging code to count the number of iterations of each loop made as part of statement execution. FossilOrigin-Name: c6a5b67ae1fb31120a40d2885b848ec2dab15c4e --- diff --git a/manifest b/manifest index 8290b14522..e12ffa66de 100644 --- a/manifest +++ b/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 diff --git a/manifest.uuid b/manifest.uuid index b84af28cee..7e57af4243 100644 --- a/manifest.uuid +++ b/manifest.uuid @@ -1 +1 @@ -3c933bf95f291f7957580d823dce92c981375a5c \ No newline at end of file +c6a5b67ae1fb31120a40d2885b848ec2dab15c4e \ No newline at end of file diff --git a/src/shell.c b/src/shell.c index 59cd2011e7..fc5459e3b2 100644 --- a/src/shell.c +++ b/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 ){ diff --git a/src/sqlite.h.in b/src/sqlite.h.in index f1d4e406e8..ba04cdaab7 100644 --- a/src/sqlite.h.in +++ b/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*); /* diff --git a/src/vdbe.c b/src/vdbe.c index 0f9f45c456..22e9539437 100644 --- a/src/vdbe.c +++ b/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]; diff --git a/src/vdbe.h b/src/vdbe.h index f975f95543..96ab5ffaaf 100644 --- a/src/vdbe.h +++ b/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 diff --git a/src/vdbeInt.h b/src/vdbeInt.h index bb504d64a1..b80a64cabd 100644 --- a/src/vdbeInt.h +++ b/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 }; /* diff --git a/src/vdbeapi.c b/src/vdbeapi.c index 0ab76e0784..e49c663064 100644 --- a/src/vdbeapi.c +++ b/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 + + diff --git a/src/vdbeaux.c b/src/vdbeaux.c index c0018bb71c..caaddd1565 100644 --- a/src/vdbeaux.c +++ b/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 } /* diff --git a/src/where.c b/src/where.c index f708d7fad7..ac54936592 100644 --- a/src/where.c +++ b/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; }