1

I'm having trouble understanding this EXPLAIN on Postgres 12.3:

EXPLAIN (ANALYZE, VERBOSE, BUFFERS) SELECT count(1) FROM mytable WHERE page ~ 'foo';

This is a 22GB table with 30 million rows, on a server with 16GB memory. The query counts 7 matching rows.

I interpret the output as saying 164 seconds was spent on I/O, yet the whole query only took 65 seconds. I thought it might be double counting some parallel workers, but when I add VERBOSE, it doesn't seem to add up either.

It looks like it's saying each of 2 workers spent ~55 seconds reading. If that sums to 110 seconds, how do I get to 164 seconds of I/O? (Since this query takes ~10 seconds when pages are cached, I'm guessing the actual time reading isn't too far from 50 seconds here, FWIW)

I'm also confused how the Parallel Seq Scan seems to take 32 seconds, but then there's still another 30+ seconds left to get the final result. I would think that because of the 7 rows it finds, there's really almost no work to do besides the scan. Am I reading this section wrong?

                                                                       QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=3092377.14..3092377.15 rows=1 width=8) (actual time=65028.818..65028.818 rows=1 loops=1)
   Output: count(1)
   Buffers: shared hit=75086 read=2858433 dirtied=1
   I/O Timings: read=164712.060
   ->  Gather  (cost=3092376.92..3092377.13 rows=2 width=8) (actual time=65028.732..65030.093 rows=3 loops=1)
         Output: (PARTIAL count(1))
         Workers Planned: 2
         Workers Launched: 2
         Buffers: shared hit=75086 read=2858433 dirtied=1
         I/O Timings: read=164712.060
         ->  Partial Aggregate  (cost=3091376.92..3091376.93 rows=1 width=8) (actual time=65026.990..65026.990 rows=1 loops=3)
               Output: PARTIAL count(1)
               Buffers: shared hit=75086 read=2858433 dirtied=1
               I/O Timings: read=164712.060
               Worker 0: actual time=65026.164..65026.164 rows=1 loops=1
                 Buffers: shared hit=25002 read=952587
                 I/O Timings: read=54906.994
               Worker 1: actual time=65026.264..65026.264 rows=1 loops=1
                 Buffers: shared hit=25062 read=954370 dirtied=1
                 I/O Timings: read=54889.244
               ->  Parallel Seq Scan on public.ui_events_v2  (cost=0.00..3091374.68 rows=896 width=0) (actual time=31764.552..65026.980 rows=2 loops=3)
                     Filter: (ui_events_v2.page ~ 'foo'::text)
                     Rows Removed by Filter: 10112272
                     Buffers: shared hit=75086 read=2858433 dirtied=1
                     I/O Timings: read=164712.060
                     Worker 0: actual time=16869.988..65026.156 rows=2 loops=1
                       Buffers: shared hit=25002 read=952587
                       I/O Timings: read=54906.994
                     Worker 1: actual time=64091.539..65026.258 rows=1 loops=1
                       Buffers: shared hit=25062 read=954370 dirtied=1
                       I/O Timings: read=54889.244
 Planning Time: 0.333 ms
 Execution Time: 65030.133 ms

1

Since parallel_leader_participation is at its default value off, the leader participates in the sequential scan. The I/O times of the worker processes are listed individually, but the I/O time of the leader can only be found by subtracting the workers' times from the total time.

The parallel sequential scan took 65026.980 milliseconds, almost all of the time. The fist number (31764.552) is the startup time, that is the time it took until the first result row was returned. If anything surprises me here, it is that high startup time.

2
  • Ah right, that is the startup portion. How do I figure out what's delaying startup? Is it saying that worker 1 spent almost all of its time on startup (64/65 seconds)? It's interesting that worker 0 had much less startup (16s?). Is the query waiting for workers to free up so as to not exceed max_parallel_workers? max_parallel_workers is set to 8, the default from RDS (though they say the instance has 4 vCPU - and PGTune app recommends 4 instead of 8, hmmm), and max_parallel_workers_per_gather is 2. If the leader participates, is it considered 3 workers or 2?
    – dcc310
    Nov 27 '20 at 17:04
  • No, the parallel workers are running from the beginning. As I said, I have no idea where the startup time is spent. Nov 27 '20 at 17:29

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.