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
  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


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
  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?

  • But the first query took longer. Perhaps you can use auto_explain to see what the query that times out really does. Feb 17 at 14:26
  • What timeout is this?
    – jjanes
    Feb 18 at 14:16
  • Since the faster one is the one that times out, it seems like an entirely client side issue. But you haven't shown any client code.
    – jjanes
    Feb 18 at 14:18
  • "That is, Npgsql reads all the data requested, then throws a TimeoutException" How do you know this?
    – jjanes
    Feb 18 at 14:19
  • After rebuilding the cluster (due to dba.stackexchange.com/q/323452/79063) I could no longer repro this timeout at the end. I still got some intermittent timeouts in the middle of reading the data (about two thirds of the way), but those were worked around by increasing the timeout from 120 to 300 seconds. Haven't seen any timeouts since (fingers crossed!) but I don't know whether the cluster corruption was the cause of the issue or rebuilding the cluster worked around it some other way.
    – EM0
    Mar 3 at 14:18


Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.