PostgreSQL 15.2. We have a table like this (simplified):
create table behavior.event_59 (
event_id integer not null primary key,
second_offset integer not null,
-- ... more columns
)
create index event_59_ix_second_offset on behavior.event_59 using brin (second_offset);
It has over 1.1 billion rows.
Our application uses Npgsql to read all or some of the data from it like this:
set enable_seqscan = off; -- Doesn't seem to make a difference here - see note below
select *
from behavior.event_59
where second_offset >= OPTIONAL_FROM_TIME
and second_offset <= OPTIONAL_TO_TIME
order by event_id;
- When we read the entire table (don't filter by
second_offset) it works fine. - When we filter by <= or >= it works fine.
- When we filter by both of those ~~but the range is large enough it~~ it sometimes works fine.
But.. sometimes with both >= and <= filters on second_offset are used we get a timeout after all the data is read. That is, Npgsql reads all the data requested (which I can tell by looking at the last row returned), then waits for a long time before NpgsqlDataReader.Read() finally returns false. This is shown if I add some logging with timestamps:
2023-02-20 13:55:15 Loaded 146,000,000 events
2023-02-20 13:55:16 Loaded 147,000,000 events
2023-02-20 13:55:17 Loaded 148,000,000 events
2023-02-20 14:01:14 Loaded a total of 148,081,519 events (finished)
So it's normally reading ~1M rows/second, but then waits for 6 minutes at the end. With a CommandTimeout value of less than 6 minutes it throws a TimeoutException. I don't want to have such a long timeout, however, and even if it "works", I'd like to avoid this extra delay at the end.
So it seems like the server is taking too long looking for more rows that may match the filter (there aren't any). This is 100% reproducible for specific values of second_offset, but which values trigger it seems a bit erratic.
Running this query manually with explain analyze I can see that different query plans are chosen depending on the second_offset filter values. Sometimes an Index Scan and sometimes a Bitmap Heap Scan.
Index Scan using event_59_pkey on event_59 (cost=0.58..48284497.83 rows=143418782 width=59) (actual time=321.235..455714.741 rows=145158667 loops=1)
Filter: ((second_offset >= 380394000) AND (second_offset <= 382297015))
Rows Removed by Filter: 977953763
Planning Time: 0.342 ms
JIT:
Functions: 2
Options: Inlining true, Optimization true, Expressions true, Deforming true
Timing: Generation 0.552 ms, Inlining 1.817 ms, Optimization 9.505 ms, Emission 3.714 ms, Total 15.588 ms
Execution Time: 459737.126 ms
or
Sort (cost=20663255.83..20678499.99 rows=6097663 width=59) (actual time=134301.366..135077.460 rows=6732766 loops=1)
Sort Key: event_id
Sort Method: external merge Disk: 429696kB
-> Bitmap Heap Scan on event_59 (cost=2261.61..19746794.05 rows=6097663 width=59) (actual time=356.105..132458.869 rows=6732766 loops=1)
Recheck Cond: ((second_offset >= 382208400) AND (second_offset <= 382297015))
Rows Removed by Index Recheck: 295436882
Heap Blocks: lossy=3142644
-> Bitmap Index Scan on event_59_ix_second_offset (cost=0.00..737.19 rows=6104341 width=0) (actual time=259.724..259.724 rows=33212620 loops=1)
Index Cond: ((second_offset >= 382208400) AND (second_offset <= 382297015))
Planning Time: 0.386 ms
JIT:
Functions: 2
Options: Inlining true, Optimization true, Expressions true, Deforming true
Timing: Generation 0.529 ms, Inlining 32.950 ms, Optimization 5.892 ms, Emission 4.476 ms, Total 43.848 ms
Execution Time: 135253.975 ms
I previously thought that this delay at the end only happens with the Bitmap Heap Scan, but no, auto_explain showed that the original case I started investigating actually does an Index Scan.
The set enable_seqscan = off in the query is because we have already had a similar problem with PG sometimes choosing a sequential scan plan, which is never better in my experience, but removing that doesn't make a different to this case.
How do I avoid this delay at the end, that requires an extra-long timeout to work around?
