I have a query that fetches 10,000 records from an indexed table. It takes 3s. Calling the same subsequent query still takes 3s.

[Update] This is not a cache problem. It has to do with getting text fields.

I have used pragma cache_size = 200000;

The query uses index:

sqlite> explain select * from instruction_trace where grid_x = 1 and grid_y = 1;
addr  opcode         p1    p2    p3    p4             p5  comment      
----  -------------  ----  ----  ----  -------------  --  -------------
0     Init           0     23    0                    0   Start at 23
1     OpenRead       0     2     0     12             0   root=2 iDb=0; instruction_trace
2     OpenRead       1     3     0     k(3,,,)        2   root=3 iDb=0; idx_instr_x_y
3     Integer        1     1     0                    0   r[1]=1
4     Integer        1     2     0                    0   r[2]=1
5     SeekGE         1     22    1     2              0   key=r[1..2]
6       IdxGT          1     22    1     2              0   key=r[1..2]
7       DeferredSeek   1     0     0                    0   Move 0 to 1.rowid if needed
8       Column         1     0     3                    0   r[3]=instruction_trace.grid_x
9       Column         1     1     4                    0   r[4]=instruction_trace.grid_y
10      Column         0     2     5                    0   r[5]=instruction_trace.cycle
11      Column         0     3     6                    0   r[6]=instruction_trace.op_addr
12      Column         0     4     7                    0   r[7]=instruction_trace.op_name
13      Column         0     5     8                    0   r[8]=instruction_trace.dest
14      Column         0     6     9                    0   r[9]=instruction_trace.src0
15      Column         0     7     10                   0   r[10]=instruction_trace.src1
16      Column         0     8     11                   0   r[11]=instruction_trace.src2
17      Column         0     9     12                   0   r[12]=instruction_trace.source
18      Column         0     10    13                   0   r[13]=instruction_trace.source_line
19      Column         0     11    14                   0   r[14]=instruction_trace.task
20      ResultRow      3     12    0                    0   output=r[3..14]
21    Next           1     6     1                    0   
22    Halt           0     0     0                    0   
23    Transaction    0     0     4     1              1   usesStmtJournal=0
24    Goto           0     1     0                    0   
Run Time: real 0.000 user 0.000000 sys 0.000235

My table has a lot of text fields:

CREATE TABLE instruction_trace
         (grid_x INT NOT NULL,
         grid_y INT NOT NULL,
         cycle INT NOT NULL,
         op_addr VARCHAR(50),
         op_name VARCHAR(50),
         dest VARCHAR(50),
         src0 VARCHAR(50),
         src1 VARCHAR(50),
         src2 VARCHAR(50),
         source VARCHAR(300),
         source_line VARCHAR(50),
         task INT)

When I query for

SELECT grid_x, grid_y, cycle, task FROM instruction_trace WHERE grid_x = 1 and grid_y = 1;

the query returns in real 0.042 user 0.019853 sys 0.009128 (42ms)

But if I query for any of the text field,

SELECT grid_x, grid_y, cycle, task, src0 FROM instruction_trace WHERE grid_x = 1 and grid_y = 1;

the query takes real 0.844 user 0.019822 sys 0.012217 844ms, though src0 is usually 10 characters long.

If I query for the largest text field (source),

SELECT grid_x, grid_y, cycle, task, source FROM instruction_trace WHERE grid_x = 1 and grid_y = 1;

it takes real 2.537 user 0.023738 sys 0.011474 2.5seconds. source has about 200 characters of text.

If I query for everything,

select * from instruction_trace where grid_x = 1 and grid_y = 1;

it takes real 4.557 user 0.036197 sys 0.018135, around 4 seconds.

Why does it take so much time to retrieve text fields? Is something wrong with my environment. Because I have tried with a few other databases, it is showing similar results.

I have used pragma cache_size = 200000;

With the default 4k page size, that’s nearly 1 GiB. Are you sure the allocation even succeeded? Even if your AWS instance big enough to allow it, regular application programs can't expect to hog up a large fraction of the available virtual memory space in a single allocation.

The query uses index…explain select…

The output of EXPLAIN QUERY PLAN is clearer for verifying that.

Thanks for replying. It appears to be a problem with text fields, and not cache. When I remove all text fields in the query, the query runs in 42ms. But if I add text fields, it goes upto 800ms+. If I add the longest text field (200 chars long), it takes more time.

The table schema is:

CREATE TABLE instruction_trace
         (grid_x INT NOT NULL,
         grid_y INT NOT NULL,
         cycle INT NOT NULL,
         op_addr VARCHAR(50),
         op_name VARCHAR(50),
         dest VARCHAR(50),
         src0 VARCHAR(50),
         src1 VARCHAR(50),
         src2 VARCHAR(50),
         source VARCHAR(300),
         source_line VARCHAR(50),
         task INT)

There are two indexes:

CREATE INDEX idx_instr_x_y ON instruction_trace (grid_x, grid_y)
CREATE INDEX idx_instr_cycle ON instruction_trace (cycle)

All the queries use the same index. But one takes < 100ms, and the other takes close to a second.

I was able to reproduce the problem in another table as well. I used StackOverflow for that. It is also unrelated to text fields.

It is is the question itself. There is a scroll at the bottom.

When I query for

SELECT grid_x, grid_y, cycle, task FROM instruction_trace WHERE grid_x = 1 and grid_y = 1;

the query returns in real 0.042 user 0.019853 sys 0.009128 (42ms)

But if I query for any of the text field,

SELECT grid_x, grid_y, cycle, task, src0 FROM instruction_trace WHERE grid_x = 1 and grid_y = 1;

the query takes real 0.844 user 0.019822 sys 0.012217 844ms, though src0 is usually 10 characters long.

If I query for the largest text field (source),

SELECT grid_x, grid_y, cycle, task, source FROM instruction_trace WHERE grid_x = 1 and grid_y = 1;

it takes real 2.537 user 0.023738 sys 0.011474 2.5seconds. source has about 200 characters of text.

If I query for everything,

select * from instruction_trace where grid_x = 1 and grid_y = 1;

it takes real 4.557 user 0.036197 sys 0.018135, around 4 seconds.

That's weird timings.

Is this from the CLI itself? How many rows are produced?
i.e. what does this return?:

SELECT COUNT(*) FROM instruction_trace WHERE grid_x = 1 and grid_y = 1;

Can you share the database file? Obscure some text values if need be.

It is a 77 MB database.

I am running it on a linux VM (r5.large with 16 GB RAM). It is located on EBS volume - gp2 with 600 IOPS and 3000 IOPS burst.

To rule out I/O issues, I moved the SQLite file to another EBS volume - io2 with 25000 IOPS. Still the same results.

sqlite> select count(*) from instruction_trace where grid_x = 1 and grid_y = 1;

9865

It is a 77 MB file.

It is from the CLI itself.

Yes, the real time is high. But the first query when I select cycle + task should fetch the rows from the disk or cache. It takes only 40ms. The other queries which take more than 1s gets some more text fields. It is the still the same process - disk or cache. Multiple requests (which should come from the cache) does not lower the query time.

You are right in saying that it is an environment issue. If I download the file to my Mac and run it, it is all ok. The query times for select-all query are consistently in the 55ms range.

Do you cache direct/overflow reads (SQLITE_DIRECT_OVERFLOW_READ)?

Do you mutex memory allocations (SQLITE_DEFAULT_MEMSTATUS)?

I am using sqlite3 CLI utility. I have set a cache_size of 200,000 pages but that does not seem to have any effect. The query repeatedly takes over 1s when there are some fields.

The dropbox link for the file is https://www.dropbox.com/s/x9pdsxlhxjs4l6k/simfab.sqlite?dl=0

It works fine in Mac.

Only in AWS environment, it is showing this discrepancy. r5.large / linux - centos / EBS type: io2 with 25000 IOPS

If you are using the CLI in AWS, have you tried (for the entertainment value) to load the database into memory and then run the queries?

After loading the database into memory you will eliminate the I/O channel as the culprit.

That is (modified to remove init processing):

2022-04-13 13:52:48 PY64 3.10 [D:\work\simfab]
>sqlite -init nul
-- Loading resources from nul
SQLite version 3.39.0 2022-04-13 15:25:31
Enter ".help" for usage hints.
sqlite> .timer on
sqlite> .restore simfab.sqlite
sqlite> .once nul
sqlite> select * from instruction_trace where grid_x = 1 and grid_y = 1;
Run Time: real 0.047 user 0.046875 sys 0.000000
sqlite>

NOTE that on Linux you need to do .once /dev/nul to discard the output

I will note that running on CentOS Stream 9 is mucho more efficient than running on Windowz:

SQLite version 3.39.0 2022-03-08 02:57:45
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.
sqlite> .restore simfab.sqlite
sqlite> .timer on
sqlite> .once /dev/nul
sqlite> select * from instruction_trace where grid_x = 1 and grid_y = 1;
Run Time: real 0.023 user 0.011830 sys 0.001518
sqlite>

Thank you, I tried the steps above. This is what I got:

sqlite> .once /dev/null
sqlite> select * from instruction_trace where grid_x = 1 and grid_y = 1;
Run Time: real 0.029 user 0.028384 sys 0.000000

The query took only 29ms. So, what does it mean? Does it mean sqlite3_column_xxx calls are taking time? Or is it a problem with std output?

If I print in the console, it still takes a long time:

Run Time: real 4.386 user 0.033024 sys 0.018677

Thanks for the excellent way to check.

Even without loading the DB in memory, I was able to execute the query in 22ms.

sqlite> .once /dev/null
sqlite> select * from instruction_trace where grid_x = 1 and grid_y = 1;
Run Time: real 0.022 user 0.019676 sys 0.002211

I understand printing to console is the problem. Thanks for your help. Please consider this issue as closed.