Thread: 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
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
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 ms > > how ??? 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 Thu, Apr 24, 2025 at 3:41 PM David Rowley <dgrowleyml@gmail.com> 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.486
>
> So, the total execution time is 52655 ms ok
> and the total time for i/o is...79368 ms
>
> how ???
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.486 > > > > So, the total execution time is 52655 ms ok > > and the total time for i/o is...79368 ms > > > > how ??? > > 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