pg.ddx.io pgsql-admin@postgresql.org mailing list archive
help / color / mirror / Atom feedFinding query execution time using \timing and EXPLAIN ANALYZE..
3+ messages / 2 participants
[nested] [flat]
* Finding query execution time using \timing and EXPLAIN ANALYZE..
@ 2022-11-21 11:28 Satalabaha Postgres <satalabaha.postgres@gmail.com>
2022-11-21 14:54 ` Re: Finding query execution time using \timing and EXPLAIN ANALYZE.. Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 3+ messages in thread
From: Satalabaha Postgres @ 2022-11-21 11:28 UTC (permalink / raw)
To: pgsql-admin@lists.postgresql.org; +Cc: Satalabaha Postgres <satalabaha.postgres@gmail.com>
Hi Listers,
I'm new to PostgreSQL. So please bear with me for any funny questions.
I was trying to get elapsed time for the sql using the \timing command in
psql as well as EXPLAIN ANALYZE.. I see both the commands reporting
different elapsed time. And this is after repeated execution of the same
query and not the first execution. In this case, which one would be the
right execution time for the query.
\timing in psql
=======================
session1=>select count(1) from demo;
count
---------
1000001
(1 row)
Time: 274.661 ms <<<<<
Using EXPLAIN ANALYZE..
============================
session1=>EXPLAIN(ANALYZE,BUFFERS,SETTINGS,TIMING) select count(1) from
demo;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=25439.55..25439.56 rows=1 width=8) (actual
time=66.963..68.989 rows=1 loops=1)
Buffers: shared hit=19231
-> Gather (cost=25439.34..25439.55 rows=2 width=8) (actual
time=64.863..68.980 rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=19231
-> Partial Aggregate (cost=24439.34..24439.35 rows=1 width=8)
(actual time=62.059..62.060 rows=1 loops=3)
Buffers: shared hit=19231
-> Parallel Seq Scan on demo (cost=0.00..23397.67
rows=416667 width=0) (actual time=0.007..35.838 rows=333334 loops=3)
Buffers: shared hit=19231
Settings: effective_cache_size = '43882472kB', maintenance_io_concurrency
= '1'
Planning:
Buffers: shared hit=4
Planning Time: 0.072 ms
Execution Time: 69.023 ms <<<<
Thanks,
Satalabaha
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Finding query execution time using \timing and EXPLAIN ANALYZE..
2022-11-21 11:28 Finding query execution time using \timing and EXPLAIN ANALYZE.. Satalabaha Postgres <satalabaha.postgres@gmail.com>
@ 2022-11-21 14:54 ` Tom Lane <tgl@sss.pgh.pa.us>
2022-11-22 06:26 ` Re: Finding query execution time using \timing and EXPLAIN ANALYZE.. Satalabaha Postgres <satalabaha.postgres@gmail.com>
0 siblings, 1 reply; 3+ messages in thread
From: Tom Lane @ 2022-11-21 14:54 UTC (permalink / raw)
To: Satalabaha Postgres <satalabaha.postgres@gmail.com>; +Cc: pgsql-admin@lists.postgresql.org
Satalabaha Postgres <satalabaha.postgres@gmail.com> writes:
> I was trying to get elapsed time for the sql using the \timing command in
> psql as well as EXPLAIN ANALYZE.. I see both the commands reporting
> different elapsed time. And this is after repeated execution of the same
> query and not the first execution. In this case, which one would be the
> right execution time for the query.
They're presumably both accurate, but they aren't measuring the same
thing. psql's \timing reports the end-to-end time from the client's
perspective. EXPLAIN ANALYZE reports the time for two components
of the server's processing. So \timing includes all of these:
1. Transmission of the query across the network to the server
2. Parsing and parse analysis of the query
3. Rewriting (a/k/a view expansion) of the query
4. Planning
5. Execution
6. Formatting of the query results as text
7. Transmission of the results across the network to the client.
while EXPLAIN is only telling you about steps 4 and 5.
Having said that, I'm a bit baffled by the size of the difference.
This example doesn't look like any of the other steps should take
very long: it's a short simple query, there doesn't seem to be
any view involved, and the result is only one row. Unless maybe
you're using tin-cans-and-string for the network connection?
There are various effects whereby the first execution of a query
can take longer than repeat executions, but you said you'd
controlled for that.
Also, how stable are these numbers if you repeat them several
times? It might be mostly about noise and/or the effects of
CPU power management. On my Linux box I find that I don't
get very reproducible numbers for short queries unless I've
done "sudo cpupower frequency-set --governor performance".
regards, tom lane
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Finding query execution time using \timing and EXPLAIN ANALYZE..
2022-11-21 11:28 Finding query execution time using \timing and EXPLAIN ANALYZE.. Satalabaha Postgres <satalabaha.postgres@gmail.com>
2022-11-21 14:54 ` Re: Finding query execution time using \timing and EXPLAIN ANALYZE.. Tom Lane <tgl@sss.pgh.pa.us>
@ 2022-11-22 06:26 ` Satalabaha Postgres <satalabaha.postgres@gmail.com>
0 siblings, 0 replies; 3+ messages in thread
From: Satalabaha Postgres @ 2022-11-22 06:26 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-admin@lists.postgresql.org
Hello Tom,
Thanks for the response and making things clear.
BTW this test case was from a RDS aurora postgres cluster. It is just a
dummy table that I created. And yes after repeated executions for both
\timing and explain ... , I get the same result.
Thanks,
Satalabaha
On Mon, 21 Nov 2022 at 20:24, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Satalabaha Postgres <satalabaha.postgres@gmail.com> writes:
> > I was trying to get elapsed time for the sql using the \timing command in
> > psql as well as EXPLAIN ANALYZE.. I see both the commands reporting
> > different elapsed time. And this is after repeated execution of the same
> > query and not the first execution. In this case, which one would be the
> > right execution time for the query.
>
> They're presumably both accurate, but they aren't measuring the same
> thing. psql's \timing reports the end-to-end time from the client's
> perspective. EXPLAIN ANALYZE reports the time for two components
> of the server's processing. So \timing includes all of these:
>
> 1. Transmission of the query across the network to the server
> 2. Parsing and parse analysis of the query
> 3. Rewriting (a/k/a view expansion) of the query
> 4. Planning
> 5. Execution
> 6. Formatting of the query results as text
> 7. Transmission of the results across the network to the client.
>
> while EXPLAIN is only telling you about steps 4 and 5.
>
> Having said that, I'm a bit baffled by the size of the difference.
> This example doesn't look like any of the other steps should take
> very long: it's a short simple query, there doesn't seem to be
> any view involved, and the result is only one row. Unless maybe
> you're using tin-cans-and-string for the network connection?
>
> There are various effects whereby the first execution of a query
> can take longer than repeat executions, but you said you'd
> controlled for that.
>
> Also, how stable are these numbers if you repeat them several
> times? It might be mostly about noise and/or the effects of
> CPU power management. On my Linux box I find that I don't
> get very reproducible numbers for short queries unless I've
> done "sudo cpupower frequency-set --governor performance".
>
> regards, tom lane
>
^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2022-11-22 06:26 UTC | newest]
Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2022-11-21 11:28 Finding query execution time using \timing and EXPLAIN ANALYZE.. Satalabaha Postgres <satalabaha.postgres@gmail.com>
2022-11-21 14:54 ` Tom Lane <tgl@sss.pgh.pa.us>
2022-11-22 06:26 ` Satalabaha Postgres <satalabaha.postgres@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox