diff options
Diffstat (limited to '')
| -rw-r--r-- | www/profile.html | 450 |
1 files changed, 450 insertions, 0 deletions
diff --git a/www/profile.html b/www/profile.html new file mode 100644 index 0000000..25864e2 --- /dev/null +++ b/www/profile.html @@ -0,0 +1,450 @@ +<!DOCTYPE html> +<html><head> +<meta name="viewport" content="width=device-width, initial-scale=1.0"> +<meta http-equiv="content-type" content="text/html; charset=UTF-8"> +<link href="sqlite.css" rel="stylesheet"> +<title>Profiling SQL Queries</title> +<!-- path= --> +</head> +<body> +<div class=nosearch> +<a href="index.html"> +<img class="logo" src="images/sqlite370_banner.gif" alt="SQLite" border="0"> +</a> +<div><!-- IE hack to prevent disappearing logo --></div> +<div class="tagline desktoponly"> +Small. Fast. Reliable.<br>Choose any three. +</div> +<div class="menu mainmenu"> +<ul> +<li><a href="index.html">Home</a> +<li class='mobileonly'><a href="javascript:void(0)" onclick='toggle_div("submenu")'>Menu</a> +<li class='wideonly'><a href='about.html'>About</a> +<li class='desktoponly'><a href="docs.html">Documentation</a> +<li class='desktoponly'><a href="download.html">Download</a> +<li class='wideonly'><a href='copyright.html'>License</a> +<li class='desktoponly'><a href="support.html">Support</a> +<li class='desktoponly'><a href="prosupport.html">Purchase</a> +<li class='search' id='search_menubutton'> +<a href="javascript:void(0)" onclick='toggle_search()'>Search</a> +</ul> +</div> +<div class="menu submenu" id="submenu"> +<ul> +<li><a href='about.html'>About</a> +<li><a href='docs.html'>Documentation</a> +<li><a href='download.html'>Download</a> +<li><a href='support.html'>Support</a> +<li><a href='prosupport.html'>Purchase</a> +</ul> +</div> +<div class="searchmenu" id="searchmenu"> +<form method="GET" action="search"> +<select name="s" id="searchtype"> +<option value="d">Search Documentation</option> +<option value="c">Search Changelog</option> +</select> +<input type="text" name="q" id="searchbox" value=""> +<input type="submit" value="Go"> +</form> +</div> +</div> +<script> +function toggle_div(nm) { +var w = document.getElementById(nm); +if( w.style.display=="block" ){ +w.style.display = "none"; +}else{ +w.style.display = "block"; +} +} +function toggle_search() { +var w = document.getElementById("searchmenu"); +if( w.style.display=="block" ){ +w.style.display = "none"; +} else { +w.style.display = "block"; +setTimeout(function(){ +document.getElementById("searchbox").focus() +}, 30); +} +} +function div_off(nm){document.getElementById(nm).style.display="none";} +window.onbeforeunload = function(e){div_off("submenu");} +/* Disable the Search feature if we are not operating from CGI, since */ +/* Search is accomplished using CGI and will not work without it. */ +if( !location.origin || !location.origin.match || !location.origin.match(/http/) ){ +document.getElementById("search_menubutton").style.display = "none"; +} +/* Used by the Hide/Show button beside syntax diagrams, to toggle the */ +function hideorshow(btn,obj){ +var x = document.getElementById(obj); +var b = document.getElementById(btn); +if( x.style.display!='none' ){ +x.style.display = 'none'; +b.innerHTML='show'; +}else{ +x.style.display = ''; +b.innerHTML='hide'; +} +return false; +} +var antiRobot = 0; +function antiRobotGo(){ +if( antiRobot!=3 ) return; +antiRobot = 7; +var j = document.getElementById("mtimelink"); +if(j && j.hasAttribute("data-href")) j.href=j.getAttribute("data-href"); +} +function antiRobotDefense(){ +document.body.onmousedown=function(){ +antiRobot |= 2; +antiRobotGo(); +document.body.onmousedown=null; +} +document.body.onmousemove=function(){ +antiRobot |= 2; +antiRobotGo(); +document.body.onmousemove=null; +} +setTimeout(function(){ +antiRobot |= 1; +antiRobotGo(); +}, 100) +antiRobotGo(); +} +antiRobotDefense(); +</script> +<div class=fancy> +<div class=nosearch> +<div class="fancy_title"> +Profiling SQL Queries +</div> +<div class="fancy_toc"> +<a onclick="toggle_toc()"> +<span class="fancy_toc_mark" id="toc_mk">►</span> +Table Of Contents +</a> +<div id="toc_sub"><div class="fancy-toc1"><a href="#_overview_">1. Overview </a></div> +<div class="fancy-toc1"><a href="#simple_cases_rows_loops_and_cycles">2. Simple Cases - Rows, Loops and Cycles</a></div> +<div class="fancy-toc1"><a href="#complex_cases_rows_loops_and_cycles">3. Complex Cases - Rows, Loops and Cycles</a></div> +<div class="fancy-toc1"><a href="#planner_estimates">4. Planner Estimates</a></div> +<div class="fancy-toc1"><a href="#low_level_profiling_data">5. Low-Level Profiling Data</a></div> +</div> +</div> +<script> +function toggle_toc(){ +var sub = document.getElementById("toc_sub") +var mk = document.getElementById("toc_mk") +if( sub.style.display!="block" ){ +sub.style.display = "block"; +mk.innerHTML = "▼"; +} else { +sub.style.display = "none"; +mk.innerHTML = "►"; +} +} +</script> +</div> + + + + +<h1 id="_overview_"><span>1. </span> Overview </h1> + +<p>SQLite contains built-in support for profiling SQL queries, but it is not +enabled by default. In order to enable support for query profiling, SQLite must +be compiled with the <a href="compile.html#enable_stmt_scanstatus">following option</a>: + +</p><div class="codeblock"><pre>-DSQLITE_ENABLE_STMT_SCANSTATUS +</pre></div> + +<p>Building SQLite with this option enables the <a href="c3ref/stmt_scanstatus.html">sqlite3_stmt_scanstatus_v2()</a> +API, which provides access to the various profiling metrics. The remainder of +this page discusses the profiling reports generated by the SQLite +<a href="cli.html">command-line shell</a> using these metrics, rather than the API directly. + +</p><p>The profiling reports generated by the shell are very similar to the query +plan reports generated by the <a href="eqp.html">EXPLAIN QUERY PLAN</a> command. This page assumes +that the reader is familiar with this format. + +</p><p>Within a command-line shell compiled with the option above, query profiling +is enabled using the ".scanstats on" command: + +</p><div class="codeblock"><pre>sqlite> .scanstats on +</pre></div> + +<p>Once enabled, the shell automatically outputs a query profile after each +SQL query executed. Query profiling can be disabled using ".scanstats off". +For example: + +</p><div class="codeblock"><pre>sqlite> .scanstats on +sqlite> SELECT a FROM t1, t2 WHERE a IN (1,2,3) AND a=d+e; +QUERY PLAN (cycles=255831538 [100%]) +|--SEARCH t1 USING INTEGER PRIMARY KEY (rowid=?) (cycles=60048488 [23%] loops=1 rows=3) +`--SCAN t2 (cycles=133558052 [52%] loops=3 rows=150000) +</pre></div> + +<h1 id="simple_cases_rows_loops_and_cycles"><span>2. </span>Simple Cases - Rows, Loops and Cycles</h1> + +<p>Consider a database with the following schema: + +</p><div class="codeblock"><pre>CREATE VIRTUAL TABLE ft USING fts5(text); +CREATE TABLE t1(a, b); +CREATE TABLE t2(c INTEGER PRIMARY KEY, d); +</pre></div> + +<p>Then, after first executing ".scanstats on": + +</p><div class="codeblock"><pre>sqlite3> SELECT * FROM t1, t2 WHERE t2.c=t1.a; +<...query results...> +QUERY PLAN (cycles=1140768 [100%]) +|--SCAN t1 (cycles=455974 [40%] loops=1 rows=500) +`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) (cycles=619820 [54%] loops=500 rows=250) +</pre></div> + +<p>The text in the example above following the snipped +"<...query results...>" is the profile report for the join query just +executed. The parts of the profile report that are similar to the +<a href="eqp.html">EXPLAIN QUERY PLAN</a> output indicate that the query is implemented by doing a +full table-scan of table "t1", with a lookup by INTEGER PRIMARY KEY on table +"t2" for each row visited. + +</p><p>The "loops=1" notation on the "SCAN t1" line indicates that this loop - the +full-table scan of table "t1" - ran exactly once. "rows=500" indicates that +that single scan visited 500 rows. + +</p><p>The "SEARCH t2 USING ..." line contains the annotation "loops=500" to indicate +that this "loop" (really a lookup by INTEGER PRIMARY KEY) ran 500 times. +Which makes sense - it ran once for each row visited by the full-table scan +of "t1". "rows=250" means that, altogether, those 500 loops visited 250 rows. +In other words, only half of the INTEGER PRIMARY KEY lookups on table t2 were +successful, for the other half of the lookups there was no row to find. + +</p><p>The loop-count for a SEARCH or SCAN entry is not necessarily the same as the +number of rows output by the outer loop. For example, if the query above +were modified as follows: + +</p><div class="codeblock"><pre>sqlite3> SELECT * FROM t1, t2 WHERE t1.b<=100 AND t2.c=t1.a; +<...query results...> +QUERY PLAN (cycles=561002 [100%]) +|--SCAN t1 (cycles=345950 [62%] loops=1 rows=500) +`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) (cycles=128690 [23%] loops=100 rows=50) +</pre></div> + +<p>This time, even though the "SCAN t1" loop still visits 500 rows, the +"SEARCH t2" lookup is only performed 100 times. This is because SQLite +was able to discard rows from t1 that did not match the "t1.b<=100" +constraint. + +</p><p>The "cycles" measurements are based on the +<a href="https://en.wikipedia.org/wiki/Time_Stamp_Counter">CPU time-stamp counter +</a>, and so are a good proxy for wall-clock time. For the query above, the +total number of cycles was 561002. For each of the two loops ("SCAN t1..." and +"SEARCH t2..."), the cycles count represents the time spent in operations that +can be directly attributed to that loop only. Specifically, this is the time +spent navigating and extracting data from the database b-trees for that loop. +These values never quite add up to the total cycles for the query, as there are +other internal operations performed by SQLite that are not directly +attributable to either loop. + +</p><p>The cycles count for the "SCAN t1" loop was 345950 - 62% of the total for the +query. The 100 lookups peformed by the "SEARCH t1" loop took 128690 cycles, 23% +of the total. + +</p><p>When a virtual table is used, the "rows" and "loops" metrics have the same +meaning as for loops on regular SQLite tables. The "cycles" meaurement is the +total cycles consumed within virtual table methods associated with the loop. +For example: + +</p><div class="codeblock"><pre>sqlite3> SELECT * FROM ft('sqlite'), t2 WHERE t2.c=ft.rowid; +<...query results...> +QUERY PLAN (cycles=836434 [100%] +|--SCAN ft VIRTUAL TABLE INDEX 0:M1 (cycles=739602 [88%] loops=1 rows=48) +`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) (cycles=62866 [8%] loops=48 rows=25) +</pre></div> + +<p>In this case the single query (loops=1) on fts5 table "ft" returned 48 rows +(rows=48) and consumed 739602 cycles (cycles=739602), which was roughly 88% of +the total query time. + +</p><h1 id="complex_cases_rows_loops_and_cycles"><span>3. </span>Complex Cases - Rows, Loops and Cycles</h1> + +<p>Using the same schema as in the previous section, consider this more +complicated example: + +</p><div class="codeblock"><pre>sqlite3> WITH cnt(i) AS ( + SELECT 1 UNION SELECT i+1 FROM cnt WHERE i<100 +) +SELECT + *, (SELECT d FROM t2 WHERE c=ft.rowid) +FROM + (SELECT count(*), a FROM t1 GROUP BY a) AS v1 CROSS JOIN + ft('sqlite'), + cnt +WHERE cnt.i=ft.rowid AND v1.a=ft.rowid; +<...query results...> +QUERY PLAN (cycles=177665334 [100%]) +|--CO-ROUTINE v1 (cycles=4500444 [3%]) +| |--SCAN t1 (cycles=397052 [0%] loops=1 rows=500) +| `--USE TEMP B-TREE FOR GROUP BY +|--MATERIALIZE cnt (cycles=1275068 [1%]) +| |--SETUP +| | `--SCAN CONSTANT ROW +| `--RECURSIVE STEP +| `--SCAN cnt (cycles=129166 [0%] loops=100 rows=100) +|--SCAN v1 (loops=1 rows=500) +|--SCAN ft VIRTUAL TABLE INDEX 0:M1= (cycles=161874340 [91%] loops=500 rows=271) +|--SCAN cnt (cycles=7336350 [4%] loops=95 rows=9500) +`--CORRELATED SCALAR SUBQUERY 3 (cycles=168538 [0%] loops=37) + `--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) (cycles=94724 [0%] loops=37 rows=21) +</pre></div> + +<p>The most complicated part of the example above is understanding the query +plan - the portion of the report that would also be generated by an +<a href="eqp.html">EXPLAIN QUERY PLAN</a> command. Other points of interest are: + +</p><ul> + <li><p> Sub-query "v1" is implemented as a <a href="optoverview.html#coroutines">co-routine</a>. + In this case the sub-query is reported on separately, and a "cycles" + count is available for the entire sub-query. There is also a "SCAN v1" + line - this represents the invocation of the sub-query co-routine + from the main query. This entry has no cycles associated with it, as + the entire cost of the sub-query is attributed to the co-routine. + It does have "loops" and "rows" values - the sub-query is scanned + once and returns 500 rows. + + </p></li><li><p>Recursive sub-query "cnt" is materialized (cached in a temp + table) before the main query is run. The entire cost of the materialization + is attributed to the "MATERIALIZE cnt" element. There is also a + "SCAN cnt" item representing the scans of the materialized sub-query. + The cycles value associated with this item represents the time taken + to scan the temp-table containing the materialized sub-query, which is + separate from the cycles used to populate it. + + </p></li><li><p>There are cycles and loops measurements for the scalar sub-query + as well. These represent the total cycles consumed while executing the + sub-query and the number of times it was executed, respectively. + + </p></li><li><p>Where one item is a parent of another, as in "CORRELATED SCALAR + SUBQUERY 3" and "SEARCH t2 USING...", then the cycles value associated + with the parent includes those cycles associated with all child elements. + In all cases, the percentage values relate to the total cycles used by + the query, not the cycles used by the parent. +</p></li></ul> + +<p>The following query uses an <a href="optoverview.html#autoindex">automatic index</a> and +an external sort: + +</p><div class="codeblock"><pre>sqlite> SELECT * FROM + t2, + (SELECT count(*) AS cnt, d FROM t2 GROUP BY d) AS v2 +WHERE v2.d=t2.d AND t2.d>100 +ORDER BY v2.cnt; +<...query results...> +QUERY PLAN (cycles=6234376 [100%]) +|--MATERIALIZE v2 (cycles=2351916 [38%]) +| |--SCAN t2 (cycles=188428 [3%] loops=1 rows=250) +| `--USE TEMP B-TREE FOR GROUP BY +|--SCAN t2 (cycles=455736 [7%] loops=1 rows=250) +|--CREATE AUTOMATIC INDEX ON v2(d, cnt) (cycles=1668380 [27%] loops=1 rows=250) +|--SEARCH v2 USING AUTOMATIC COVERING INDEX (d=?) (cycles=932824 [15%] loops=200 rows=200) +`--USE TEMP B-TREE FOR ORDER BY (cycles=662456 [11%] loops=1 rows=200) +</pre></div> + +<p>Points of interest are: + +</p><ul> + <li><p> This query materializes the sub-query into a temp table, then creates + an automatic (i.e. transient) index on it, then uses that index to optimize + the join. All three of these steps - "MATERIALIZE v2", "CREATE AUTOMATIC + INDEX" and "SEARCH ... USING AUTOMATIC INDEX" have separate cycle counts. + The "rows" associated with the "CREATE AUTOMATIC INDEX" line represents the + total number of rows included in the index. The "loops" and "rows" associated + with the "SEARCH ... USING AUTOMATIC INDEX" line represent the number of + lookups the index was used for and the total number of rows found by those + lookups. + + </p></li><li><p> The external sort "USE TEMP B-TREE FOR ORDER BY" is also accounted + for separately. The cycles count represents the extra cycles consumed by + sorting the returned rows, above those that would have been used if the rows + were returned in arbitrary order. The rows count represents the number of + rows sorted. +</p></li></ul> + +<h1 id="planner_estimates"><span>4. </span>Planner Estimates</h1> + +<p>As well as ".scanstats on" to enable profiling and ".scanstats off" to +disable it, the shell also accepts ".scanstats est": + +</p><div class="codeblock"><pre>sqlite> .scanstats est +</pre></div> + +<p>This enables a special kind of profiling report that includes two extra +values associated with each "SCAN..." and "SEARCH..." element of a query +profile: + +</p><ul> + <li> <b>rpl</b> (rows per loop): This is the value of the "rows" metric + divided by that of the "loops" metric. + </li><li> <b>est</b> (estimate): This is the number of rows per loop that the + query planner estimated would be returned by the current query + element. If this value is radically different from the actual + rows per loop value and query performance is unsatisfactory, + the quality of this estimate may be improved by running ANALYZE. +</li></ul> + +<div class="codeblock"><pre>sqlite> SELECT a FROM t1, t2 WHERE a IN (1,2,3) AND a=d+e ORDER BY a; +<query results...> +QUERY PLAN (cycles=264725190 [100%] +|--SEARCH t1 USING INTEGER PRIMARY KEY (rowid=?) (cycles=60511568 [23%] loops=1 rows=3 rpl=3.0 est=3.0) +`--SCAN t2 (cycles=139461608 [53%] loops=3 rows=150000 rpl=50000.0 est=1048576.0) +</pre></div> + +<h1 id="low_level_profiling_data"><span>5. </span>Low-Level Profiling Data</h1> + + + +<p> Also supported is the ".scanstats vm" command. This enables a lower-level +profiling report showing the number of times each VM instruction was executed +and the percentage of clock-cycles that passed while it was executing: + +</p><div class="codeblock"><pre>sqlite> .scanstats vm +</pre></div> + +<p>Then: + +</p><div class="codeblock"><pre>sqlite> SELECT count(*) FROM t2 WHERE (d % 5) = 0; +<query results...> +addr cycles nexec opcode p1 p2 p3 p4 p5 comment +---- ------ ------ ------------- ---- ---- ---- ------------- -- ------------- +0 0.0% 1 Init 1 18 0 0 Start at 18 +1 0.0% 1 Null 0 1 1 0 r[1..1]=NULL +2 0.0% 1 OpenRead 0 2 0 2 0 root=2 iDb=0; t2 +3 0.0% 1 ColumnsUsed 0 0 0 2 0 +4 0.0% 1 Explain 4 0 0 SCAN t2 0 +5 0.0% 1 CursorHint 0 0 0 EQ(REM(c1,5),0) 0 +6 0.0% 1 Rewind 0 14 0 0 +7 46.86% 150000 Column 0 1 3 0 r[3]= cursor 0 column 1 +8 18.94% 150000 Remainder 4 3 2 0 r[2]=r[3]%r[4] +9 5.41% 150000 ReleaseReg 3 1 0 0 release r[3] mask 0 +10 12.09% 150000 Ne 5 13 2 80 if r[2]!=r[5] goto 13 +11 1.02% 30000 ReleaseReg 2 1 0 0 release r[2] mask 0 +12 2.95% 30000 AggStep1 0 0 1 count(0) 0 accum=r[1] step(r[0]) +13 12.72% 150000 Next 0 7 0 1 +14 0.0% 1 AggFinal 1 0 0 count(0) 0 accum=r[1] N=0 +15 0.0% 1 Copy 1 6 0 0 r[6]=r[1] +16 0.0% 1 ResultRow 6 1 0 0 output=r[6] +17 0.01% 1 Halt 0 0 0 0 +18 0.0% 1 Transaction 0 0 1 0 1 usesStmtJournal=0 +19 0.0% 1 Integer 5 4 0 0 r[4]=5 +20 0.0% 1 Integer 0 5 0 0 r[5]=0 +21 0.0% 1 Goto 0 1 0 0 +</pre></div> + + + + + + + |