Slow window query execution introduced in 3.41.2

(1) By MichalCermak on 2023-07-28 14:20:24 [source]

Hi SQLite community,

I recently updated SQLite and in version 3.41.2, I am getting much slower execution for a specific query containing a window function:

WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable)
UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)

The point of this query is to add a monotonic sequence (ContId) to the sorted Id column.

When I executed EXPLAIN QUERY PLAN with the older version (3.41.1), I got this:
id	parent	notused	detail
4	0	0	SCAN TestTable
9	0	0	CORRELATED SCALAR SUBQUERY 2
12	9	0	CO-ROUTINE T
15	12	0	CO-ROUTINE (subquery-3)
18	15	0	SCAN TestTable
25	15	0	USE TEMP B-TREE FOR ORDER BY
39	12	0	SCAN (subquery-3)
89	9	0	SEARCH T USING AUTOMATIC COVERING INDEX (Id=?)

Version 3.41.2 gives me a different result:
id	parent	notused	detail
4	0	0	SCAN TestTable
14	0	0	CORRELATED SCALAR SUBQUERY 2
17	14	0	CO-ROUTINE T
20	17	0	CO-ROUTINE (subquery-3)
23	20	0	SCAN TestTable USING COVERING INDEX Index
35	17	0	SCAN (subquery-3)
73	14	0	SCAN T

I generated a random table with 10000 rows. In version 3.41.1 it was executed in 42ms, In version 3.41.2 it takes 19971ms.

Thanks,
Michal

(2) By Richard Hipp (drh) on 2023-07-28 14:26:51 in reply to 1 [link] [source]

Here is what you need to do:

Retest using the latest release: 3.42.0. Even better is to also try on the latest (unreleased) trunk version and/or on the latest pre-release snapshot.
If the problem has not yet been resolved, then provide us with a test case that we can run. Your test case should include the input database (or a script to generate the input database if the database is large) and a script to run in the SQLite CLI that gives poor performance.

(3) By MichalCermak on 2023-07-30 13:06:53 in reply to 2 [link] [source]

Retested with 3.42.0 and pre-release package, the issue is still present.

Here is a git repo with simple Windows batch file showing the issue:
https://github.com/MichalCermak123/slow_sqlite_window_function

When I run it, I got this:

c:\slow_sqlite_window_function>run.bat

c:\slow_sqlite_window_function>set QUERY=WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable) UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)

c:\slow_sqlite_window_function>set QUERY_PLAN=EXPLAIN QUERY PLAN WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable) UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)

c:\slow_sqlite_window_function>copy /y test_db.db test_db_3410100.db
        1 file(s) copied.

c:\slow_sqlite_window_function>sqlite-tools-win32-x86-3410100\sqlite3.exe test_db_3410100.db "EXPLAIN QUERY PLAN WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable) UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)"
QUERY PLAN
|--SCAN TestTable
`--CORRELATED SCALAR SUBQUERY 2
   |--CO-ROUTINE T
   |  |--CO-ROUTINE (subquery-3)
   |  |  |--SCAN TestTable
   |  |  `--USE TEMP B-TREE FOR ORDER BY
   |  `--SCAN (subquery-3)
   `--SEARCH T USING AUTOMATIC COVERING INDEX (Id=?)

c:\slow_sqlite_window_function>echo Working (3410100) version start - 15:00:45.00
Working (3410100) version start - 15:00:45.00

c:\slow_sqlite_window_function>sqlite-tools-win32-x86-3410100\sqlite3.exe test_db_3410100.db -stats "WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable) UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)"
Memory Used:                         2147944 (max 4482648) bytes
Number of Outstanding Allocations:   688 (max 726)
Number of Pcache Overflow Bytes:     2000008 (max 2092856) bytes
Largest Allocation:                  2048000 bytes
Largest Pcache Allocation:           4256 bytes
Lookaside Slots Used:                53 (max 123)
Successful lookaside attempts:       20206
Lookaside failures due to size:      2
Lookaside failures due to OOM:       22
Pager Heap Usage:                    2075864 bytes
Page cache hits:                     7
Page cache misses:                   1057
Page cache writes:                   528
Page cache spills:                   90
Schema Heap Usage:                   624 bytes
Statement Heap/Lookaside Usage:      16352 bytes
Fullscan Steps:                      19998
Sort Operations:                     1
Autoindex Inserts:                   0
Bloom filter bypass taken:           0/10000
Virtual Machine Steps:               570038
Reprepare operations:                0
Number of times run:                 1
Memory used by prepared stmt:        16352

c:\slow_sqlite_window_function>echo Working (3410100) version finish - 15:00:45.08
Working (3410100) version finish - 15:00:45.08

c:\slow_sqlite_window_function>copy /y test_db.db test_db_3410200.db
        1 file(s) copied.

c:\slow_sqlite_window_function>sqlite-tools-win32-x86-3410200\sqlite3.exe test_db_3410200.db "EXPLAIN QUERY PLAN WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable) UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)"
QUERY PLAN
|--SCAN TestTable
`--CORRELATED SCALAR SUBQUERY 2
   |--CO-ROUTINE T
   |  |--CO-ROUTINE (subquery-3)
   |  |  |--SCAN TestTable
   |  |  `--USE TEMP B-TREE FOR ORDER BY
   |  `--SCAN (subquery-3)
   `--SCAN T

c:\slow_sqlite_window_function>echo First slow (3410200) version start - 15:00:45.51
First slow (3410200) version start - 15:00:45.51

c:\slow_sqlite_window_function>sqlite-tools-win32-x86-3410200\sqlite3.exe test_db_3410200.db -stats "WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable) UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)"
Memory Used:                         2151000 (max 4485488) bytes
Number of Outstanding Allocations:   686 (max 713)
Number of Pcache Overflow Bytes:     2003752 (max 2028352) bytes
Largest Allocation:                  2048000 bytes
Largest Pcache Allocation:           4264 bytes
Lookaside Slots Used:                54 (max 123)
Successful lookaside attempts:       50035206
Lookaside failures due to size:      2
Lookaside failures due to OOM:       15
Pager Heap Usage:                    2079776 bytes
Page cache hits:                     2582440
Page cache misses:                   2718624
Page cache writes:                   528
Page cache spills:                   92
Schema Heap Usage:                   624 bytes
Statement Heap/Lookaside Usage:      15664 bytes
Fullscan Steps:                      99999999
Sort Operations:                     10000
Autoindex Inserts:                   0
Virtual Machine Steps:               1950575003
Reprepare operations:                0
Number of times run:                 1
Memory used by prepared stmt:        15664

c:\slow_sqlite_window_function>echo First slow (3410200) version finish - 15:01:43.67
First slow (3410200) version finish - 15:01:43.67

c:\slow_sqlite_window_function>copy /y test_db.db test_db_3420000.db
        1 file(s) copied.

c:\slow_sqlite_window_function>sqlite-tools-win32-x86-3420000\sqlite3.exe test_db_3420000.db "EXPLAIN QUERY PLAN WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable) UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)"
QUERY PLAN
|--SCAN TestTable
`--CORRELATED SCALAR SUBQUERY 2
   |--CO-ROUTINE T
   |  |--CO-ROUTINE (subquery-3)
   |  |  |--SCAN TestTable
   |  |  `--USE TEMP B-TREE FOR ORDER BY
   |  `--SCAN (subquery-3)
   `--SCAN T

c:\slow_sqlite_window_function>echo Latest (3420000) version start - 15:01:43.76
Latest (3420000) version start - 15:01:43.76

c:\slow_sqlite_window_function>sqlite-tools-win32-x86-3420000\sqlite3.exe test_db_3420000.db -stats "WITH T(Id, ContId) AS(SELECT ROWID, row_number() OVER(ORDER BY ID) -1 FROM TestTable) UPDATE TestTable SET ContId=(SELECT ContId FROM T WHERE TestTable.ROWID=T.Id)"
Memory Used:                         2153192 (max 4487680) bytes
Number of Outstanding Allocations:   677 (max 704)
Number of Pcache Overflow Bytes:     2003752 (max 2028352) bytes
Largest Allocation:                  2048000 bytes
Largest Pcache Allocation:           4264 bytes
Lookaside Slots Used:                53 (max 123)
Successful lookaside attempts:       50035208
Lookaside failures due to size:      2
Lookaside failures due to OOM:       10
Pager Heap Usage:                    2079776 bytes
Page cache hits:                     2582440
Page cache misses:                   2718624
Page cache writes:                   528
Page cache spills:                   92
Schema Heap Usage:                   624 bytes
Statement Heap/Lookaside Usage:      20416 bytes
Fullscan Steps:                      99999999
Sort Operations:                     10000
Autoindex Inserts:                   0
Virtual Machine Steps:               1950575003
Reprepare operations:                0
Number of times run:                 1
Memory used by prepared stmt:        20416

c:\slow_sqlite_window_function>echo Latest (3420000) version finish - 15:02:42.00
Latest (3420000) version finish - 15:02:42.00

c:\slow_sqlite_window_function>sqlite-tools-win32-x86-3420000\sqldiff.exe test_db_3410100.db test_db_3410200.db

c:\slow_sqlite_window_function>sqlite-tools-win32-x86-3420000\sqldiff.exe test_db_3410100.db test_db_3420000.db

(4.1) By Richard Hipp (drh) on 2023-07-31 11:35:28 edited from 4.0 in reply to 3 [link] [source]

The problem bisects to check-in 2c56b984a0bd3be5.

(5) By Richard Hipp (drh) on 2023-07-31 12:02:51 in reply to 3 [link] [source]

Simplified test script that runs in the CLI:

.echo on
CREATE TABLE t1(a INTEGER PRIMARY KEY, b INT);
CREATE TABLE t2(d INT);
WITH RECURSIVE c(x) AS (VALUES(1) UNION ALL SELECT x+1 FROM c WHERE x<10000)
  INSERT INTO t1(a,b) SELECT x, x+1 FROM c;
WITH RECURSIVE c(x) AS (VALUES(1) UNION ALL SELECT x+1 FROM c WHERE x<1000)
  INSERT INTO t2(d) SELECT x*2 FROM c;
.timer on
.eqp on
WITH t3(x,y) AS (SELECT d, row_number()OVER() FROM t2)
  UPDATE t1 SET b=(SELECT y FROM t3 WHERE t1.a=t3.x);

Run in 0.02 seconds in 3.40.0 but takes about 4.0 seconds in 3.42.0.

(6) By Richard Hipp (drh) on 2023-08-01 13:02:38 in reply to 3 [link] [source]

Should now be fixed on trunk. The latest changes (including this fix) are in the pre-release snapshot tarball.