Small. Fast. Reliable.
Choose any three.
Choose any three.
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 following option:
-DSQLITE_ENABLE_STMT_SCANSTATUS
Building SQLite with this option enables the sqlite3_stmt_scanstatus_v2() API, which provides access to the various profiling metrics. The remainder of this page discusses the profiling reports generated by the SQLite command-line shell using these metrics, rather than the API directly.
The profiling reports generated by the shell are very similar to the query plan reports generated by the EXPLAIN QUERY PLAN command. This page assumes that the reader is familiar with this format.
Within a command-line shell compiled with the option above, query profiling is enabled using the ".scanstats on" command:
sqlite> .scanstats on
Once enabled, the shell automatically outputs a query profile after each SQL query executed. Query profiling can be disabled using ".scanstats off". For example:
sqlite> .scanstats on
sqlite> SELECT a FROM t1, t2 WHERE a IN (1,2,3) AND a=d+e;
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 255M 100% 1 3
|--SEARCH t1 USING INTEGER PRIMARY KEY (rowid=?) 60.0M 23% 1 3
`--SCAN t2 134M 52% 3 150K
Consider a database with the following schema:
CREATE VIRTUAL TABLE ft USING fts5(text); CREATE TABLE t1(a, b); CREATE TABLE t2(c INTEGER PRIMARY KEY, d);
Then, after first executing ".scanstats on":
sqlite3> SELECT * FROM t1, t2 WHERE t2.c=t1.a;
<...query results...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 1.14M 100%
|--SCAN t1 455K 40% 1 500
`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) 620K 54% 500 250
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 EXPLAIN QUERY PLAN 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.
The value of "1" in the "Loops" column to the right of the EXPLAIN QUERY PLAN output on the "SCAN t1" line indicates that this loop - the full-table scan of table "t1" - ran exactly once. The value of "500" under the "Rows column indicates that that single scan generates 500 rows.
The "SEARCH t2 USING ..." line contains "500" for "Loops" 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". The "250" under "Row" means that, altogether, those 500 loops generated 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.
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:
sqlite3> SELECT * FROM t1, t2 WHERE t1.b<=100 AND t2.c=t1.a;
<...query results...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 561K 100%
|--SCAN t1 345K 62% 1 500
`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) 129K 23% 100 50
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.
The "cycles" measurements are based on the CPU time-stamp counter , and so are a good proxy for wall-clock time. For the query above, the total number of cycles was about 561,000. (All of the values displayed are rounded to three significant digits.) 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.
The cycles count for the "SCAN t1" loop was 345K - 62% of the total for the query. The 100 lookups peformed by the "SEARCH t1" loop took 129K cycles, 23% of the total.
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:
sqlite3> SELECT * FROM ft('sqlite'), t2 WHERE t2.c=ft.rowid;
<...query results...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 836K 100%
|--SCAN ft VIRTUAL TABLE INDEX 0:M1 740K 91% 1 48
`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) 62.9K 8% 48 25
In this case the single query (Loops: 1) on fts5 table "ft" returned 48 rows (Rows: 48) and consumed about 740K cycles, which was roughly 88% of the total query time.
Using the same schema as in the previous section, consider this more complicated example:
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...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 178M 100%
|--CO-ROUTINE v1
| |--SCAN t1 397K 0% 1 500
| `--USE TEMP B-TREE FOR GROUP BY
|--MATERIALIZE cnt 1.28M 1%
| |--SETUP
| | `--SCAN CONSTANT ROW
| `--RECURSIVE STEP
| `--SCAN cnt 129K 0% 100 100
|--SCAN v1 4.50M 3% 1 500
|--SCAN ft VIRTUAL TABLE INDEX 0:M1= 162M 91% 500 271
|--SCAN cnt 7.33M 4% 95 9500
`--CORRELATED SCALAR SUBQUERY 3 169K 0% 37
`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) 94.7K 0% 37 21
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 EXPLAIN QUERY PLAN command.
The following query uses an automatic index and an external sort:
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...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 6.23M 100%
|--MATERIALIZE v2 2.35M 38%
| |--SCAN t2 188K 3% 1 250
| `--USE TEMP B-TREE FOR GROUP BY
|--SCAN t2 456K 7% 1 250
|--CREATE AUTOMATIC INDEX ON v2(d, cnt) 1.67M 27% 1 250
|--SEARCH v2 USING AUTOMATIC COVERING INDEX (d=?) 933K 15% 200 200
`--USE TEMP B-TREE FOR ORDER BY 662K 11% 1 200
Points of interest are:
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.
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.
As well as ".scanstats on" to enable profiling and ".scanstats off" to disable it, the shell also accepts ".scanstats est":
sqlite> .scanstats est
This enables a special kind of profiling report that includes two extra values associated with each "SCAN..." and "SEARCH..." element of a query profile. The "Loops" and "Rows" columns show the actual number of invocations of each step and the actual number of rows generated, but now both numbers are also followed by the estimated values for those quantities that the query planner used to pick the algorithm.
sqlite> SELECT a FROM t1, t2 WHERE a IN (1,2,3) AND a=d+e ORDER BY a;
<query results...>
Cycles Loops (est) Rows (est)
---------- ------------ ------------
QUERY PLAN 264M 100%
|--SEARCH t1 USING INTEGER PRIMARY KEY (rowid=?) 60.5M 23% 1 1 3 3
`--SCAN t2 139M 53% 3 1.24K 450K 3.12M
The output below is from query 15c of the Join Order Benchmark.
.scanstatus est
SELECT MIN(chn.name) AS character,
MIN(t.title) AS movie_with_american_producer
FROM char_name AS chn,
cast_info AS ci,
company_name AS cn,
company_type AS ct,
movie_companies AS mc,
role_type AS rt,
title AS t
WHERE ci.note LIKE '%(producer)%'
AND cn.country_code = '[us]'
AND t.production_year > 1990
AND t.id = mc.movie_id
AND t.id = ci.movie_id
AND ci.movie_id = mc.movie_id
AND chn.id = ci.person_role_id
AND rt.id = ci.role_id
AND cn.id = mc.company_id
AND ct.id = mc.company_type_id;
<... query results omitted ...>
Cycles Loops (est) Rows (est)
---------- ------------ ------------
QUERY PLAN 87.1G 100%
|--SEARCH cn USING COVERING INDEX extra_cncc (country_code=?) 13.3M 0% 1 1 84.8K 81.9K
|--SEARCH mc USING INDEX company_id_movie_companies (company_id=?) 3.11G 4% 84.8K 81.9K 1.15M 983K
|--SEARCH t USING INTEGER PRIMARY KEY (rowid=?) 3.10G 4% 1.15M 983K 1.15M 860K
|--SEARCH ci USING INDEX movie_id_cast_info (movie_id=?) 77.3G 89% 609K 860K 21.0M 3.01M
|--SEARCH rt USING INTEGER PRIMARY KEY (rowid=?) 40.4M 0% 802K 3.01M 802K 3.01M
|--SEARCH chn USING INTEGER PRIMARY KEY (rowid=?) 20.7M 0% 802K 3.01M 26 3.01M
`--SEARCH ct USING INTEGER PRIMARY KEY (rowid=?) 10.6K 0% 26 3.01M 26 3.01M
Notice that most of the Loops and Rows values predicted by the query planner are reasonably accurate, except for the case of the join against the "char_name" (alias "chn") table. The join against the "chn" table dramatically reduced the number of rows in the processing chain - a reduction that the query planner failed to predict. If the query planner had known that the join against "chn" would have this effect, it could have picked a different join order that processed the "chn" table sooner, and thus reduced downstream processing. The following output is from a variation of the 15c benchmark that uses CROSS JOIN to force the join against "chn" to happen much earlier:
Cycles Loops (est) Rows (est)
---------- ------------ ------------
QUERY PLAN 6.95G 100%
|--SCAN ci 3.67G 53% 1 1 36.2M 7.86M
|--SEARCH chn USING INTEGER PRIMARY KEY (rowid=?) 36.9M 1% 1.43M 7.86M 25 7.86M
|--SEARCH t USING INTEGER PRIMARY KEY (rowid=?) 221K 0% 25 7.86M 25 6.88M
|--SEARCH mc USING INDEX movie_id_movie_companies (movie_id=?) 455K 0% 22 6.88M 43 18.9M
|--SEARCH cn USING INTEGER PRIMARY KEY (rowid=?) 209K 0% 43 18.9M 43 17.7M
|--SEARCH ct USING INTEGER PRIMARY KEY (rowid=?) 6491 0% 26 17.7M 26 17.7M
`--SEARCH rt USING INTEGER PRIMARY KEY (rowid=?) 2853 0% 26 17.7M 26 17.7M
This alternative query plan runs about 12.5 times faster. But based on the row count estimates, the query planner reasoned that this plan should have run about 5.9 times slower, which is what it didn't pick it.
An important use case for the ".scanstatus est" feature is to help the developers quickly see when the query planner is making bad choices based on row-count estimates that differ wildly from the actual query. The question of how the query planner could have known that the join against "chn" would so dramatically reduce the row count is an area of on-going research as of this writing (2026-02-04).
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:
sqlite> .scanstats vm
Then:
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
This page was last updated on 2026-02-04 23:39:31Z