Parallel IO Read Timings

[lrweck]

When using "EXPLAIN (ANALYZE, TIMING)", IO timings can be confusing when measuring parallel nodes.

Example: https://explain.dalibo.com/plan/avr0

What do you think of showing the maximum time between all wokers on this tab, and individual worker timings for each worker on Misc tab?

[pgiraud]

@lrweck it looks like you removed this plan. Can you share it again?

[pgiraud]

@lrweck are you able to provide a plan so that I can better understand the issue?

[pgiraud]

@lrweck I'm still looking for more info. Thanks.

[pgiraud]

Here's a plan that should help reproduce the bug.

https://explain.dalibo.com/plan/6Z4#plan/node/3

                                                                QUERY PLAN                                                                 
-------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=1000.00..2345159.78 rows=1000000 width=45) (actual time=37.662..878.566 rows=1000000 loops=1)
   Buffers: shared hit=5 read=22612
   I/O Timings: read=4103.590
   ->  Gather  (cost=1000.00..6712463.06 rows=2863057 width=45) (actual time=0.268..706.579 rows=1000000 loops=1)
         Workers Planned: 8
         Workers Launched: 6
         Buffers: shared hit=5 read=22612
         I/O Timings: read=4103.590
         ->  Parallel Seq Scan on pwned_vm  (cost=0.00..6425157.36 rows=357882 width=45) (actual time=83.388..750.808 rows=142907 loops=7)
               Filter: (mod(n, 2) = 0)
               Rows Removed by Filter: 202716
               Buffers: shared hit=5 read=22612
               I/O Timings: read=4103.590
 Planning Time: 0.163 ms
 JIT:
   Functions: 15
   Options: Inlining true, Optimization true, Expressions true, Deforming true
   Timing: Generation 3.554 ms, Inlining 409.811 ms, Optimization 119.960 ms, Emission 54.414 ms, Total 587.740 ms
 Execution Time: 962.483 ms
(19 lignes)

[Krysztophe]

I can reproduce at will:

without parallelization: https://explain.dalibo.com/plan/4J with: https://explain.dalibo.com/plan/5gW

178 Mbytes read in both cases (from OS cache), but its 500 ms or 5 s.

I suspect that the track_io_timing is multiplied by the loops number. That's not a problem of pev2.

[Krysztophe]

According to @ioguix, adding the workers IO timings may be normal. If this is the case, I think that pev2 should add an hint, perhaps the average per worker (beware parallel_leader_participation), or just the words "cumulated" before "I/O timings".

Here is another example with pgbench size 100, with all caches dropped between each run (PG13) :

• text, cumulated io timings = 38s (for 7s execution) : https://explain.dalibo.com/plan/TXY
• same, verbose to have the details per worker : https://explain.dalibo.com/plan/yDbD (BTW : there is a problem in the 'Workers' tab! I only see the worker #0)
• same, verbose, JSON : https://explain.dalibo.com/plan/y9G (workers are all there, but the details about individual IO are not shown, although present in the JSON)
• same with set parallel_leader_participation to off ; : https://explain.dalibo.com/plan/qSU