Date: Thu, 10 Mar 2022 14:05:28 +0800
From: Julien Rouhaud <rjuju123@gmail.com>
To: Jayadevan M <maymala.jayadevan@gmail.com>
Cc: pgsql-performance@lists.postgresql.org
Subject: Re: Explain analyse with track_io_timing
Message-ID: <20220310060528.qik2ptwjkhzvxgex@jrouhaud>
References: 
 <CAFS1N4j=QMEsQgnb4ZLjoAgZNwaK-aNkL8y9EBvFVV2PS=dZ8w@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <CAFS1N4j=QMEsQgnb4ZLjoAgZNwaK-aNkL8y9EBvFVV2PS=dZ8w@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/20220310060528.qik2ptwjkhzvxgex%40jrouhaud>
Precedence: bulk

Hi,

On Thu, Mar 10, 2022 at 10:40:17AM +0530, Jayadevan M wrote:
>
> What is the unit of I/O Timings in explain (analyze, buffers) ?

milliseconds

> There is a plan with quite a few nodes.  In each case, the value of I/O
> Timings is much more than the time for the outer node. A few lines from the
> plan -
>
>  Hash Left Join  (cost=14320945.22..7099974624.27 rows=194335062701
> width=5511) (actual time=107913.021..*108109*.313 rows=759 loops=1)
>    Buffers: shared hit=738871 read=1549646, temp read=92710 written=92973
>    I/O Timings: read=*228324*.357
>    ->  Hash Left Join  (cost=14049069.69..246411189.41 rows=18342148438
> width=5467) (actual time=96579.630..*96774*.534 rows=759 loops=1)
>          Buffers: shared hit=684314 read=1377851, temp read=92710
> written=92973
>          I/O Timings: read=*217899*.233
> At the end, there is
> Execution Time: 108117.006 ms
>
> So it takes about 108 seconds. But the I/O Timings are higher.

Is it a parallel query?  If yes the total time is only the time spent in the
main process, and the IO time is sum of all IO time spent in main process and
the parallel workers, which can obviously be a lot more than the total
execution time.