explain
hello,
there is something I seem missing in explain analyze buffers results when
track_io_timing is on:
this is the first lines of an explain: (the request is of no interest, such
a result is quite frequent)
Nested Loop Left Join (cost=941400.77..966327.57 rows=3 width=653) (actual
time=52655.694..62533.811 rows=346 loops=1)
Buffers: shared hit=10068265 read=396705 dirtied=1858 written=218, temp
read=429687 written=115187
I/O Timings: read=79368.246 write=11.486
So, the total execution time is 52655 ms ok
and the total time for i/o is...79368 ms
how ???
thanks
Marc MILLAS
Senior Architect
+33607850334
www.mokadb.com
On Fri, 25 Apr 2025 at 01:32, Marc Millas <marc.millas@mokadb.com> wrote:
Nested Loop Left Join (cost=941400.77..966327.57 rows=3 width=653) (actual time=52655.694..62533.811 rows=346 loops=1)
Buffers: shared hit=10068265 read=396705 dirtied=1858 written=218, temp read=429687 written=115187
I/O Timings: read=79368.246 write=11.486So, the total execution time is 52655 ms ok
and the total time for i/o is...79368 mshow ???
The 79.3 seconds is the total time spent doing reads for all parallel
workers. 52.6 seconds is the wall clock time elapsed to execute the
query.
David
Thanks !
Marc MILLAS
Senior Architect
+33607850334
www.mokadb.com
On Thu, Apr 24, 2025 at 3:41 PM David Rowley <dgrowleyml@gmail.com> wrote:
Show quoted text
On Fri, 25 Apr 2025 at 01:32, Marc Millas <marc.millas@mokadb.com> wrote:
Nested Loop Left Join (cost=941400.77..966327.57 rows=3 width=653)
(actual time=52655.694..62533.811 rows=346 loops=1)
Buffers: shared hit=10068265 read=396705 dirtied=1858 written=218,
temp read=429687 written=115187
I/O Timings: read=79368.246 write=11.486
So, the total execution time is 52655 ms ok
and the total time for i/o is...79368 mshow ???
The 79.3 seconds is the total time spent doing reads for all parallel
workers. 52.6 seconds is the wall clock time elapsed to execute the
query.David
On Fri, 2025-04-25 at 01:41 +1200, David Rowley wrote:
On Fri, 25 Apr 2025 at 01:32, Marc Millas <marc.millas@mokadb.com> wrote:
Nested Loop Left Join (cost=941400.77..966327.57 rows=3 width=653) (actual time=52655.694..62533.811 rows=346 loops=1)
Buffers: shared hit=10068265 read=396705 dirtied=1858 written=218, temp read=429687 written=115187
I/O Timings: read=79368.246 write=11.486So, the total execution time is 52655 ms ok
and the total time for i/o is...79368 mshow ???
The 79.3 seconds is the total time spent doing reads for all parallel
workers. 52.6 seconds is the wall clock time elapsed to execute the
query.
But wouldn't it read "loops=3" or similar then?
Yours,
Laurenz Albe
On Fri, 25 Apr 2025 at 03:06, Laurenz Albe <laurenz.albe@cybertec.at> wrote:
On Fri, 2025-04-25 at 01:41 +1200, David Rowley wrote:
The 79.3 seconds is the total time spent doing reads for all parallel
workers. 52.6 seconds is the wall clock time elapsed to execute the
query.But wouldn't it read "loops=3" or similar then?
Only if the Nested Loop was below the Gather / Gather Merge node.
David
On Fri, 2025-04-25 at 12:36 +1200, David Rowley wrote:
On Fri, 25 Apr 2025 at 03:06, Laurenz Albe <laurenz.albe@cybertec.at> wrote:
On Fri, 2025-04-25 at 01:41 +1200, David Rowley wrote:
The 79.3 seconds is the total time spent doing reads for all parallel
workers. 52.6 seconds is the wall clock time elapsed to execute the
query.But wouldn't it read "loops=3" or similar then?
Only if the Nested Loop was below the Gather / Gather Merge node.
Ah, I see. The I/O time accrued in a different, lower, parallelized step
of the execution plan.
Yours,
Laurenz Albe