1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
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>
|
