pg.ddx.io pgsql-admin@postgresql.org mailing list archive
help / color / mirror / Atom feedEXPLAIN time difference in real
6+ messages / 3 participants
[nested] [flat]
* EXPLAIN time difference in real
@ 2014-04-26 12:55 Michael Monnerie <lists.michael.monnerie@is.it-management.at>
0 siblings, 1 reply; 6+ messages in thread
From: Michael Monnerie @ 2014-04-26 12:55 UTC (permalink / raw)
To: pgsql-admin
Hi, I'm trying to find ways to optimize our db for dbmail (mailserver
from dbmail.org), and found lots of the same SELECTs I want to look at.
So I did use EXPLAIN ANALYZE:
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.00..2621.33 rows=1 width=8) (actual
time=9.296..9.296 rows=0 loops=1)
Output: m.message_idnr
-> Nested Loop (cost=0.00..2619.88 rows=1 width=16) (actual
time=0.158..8.137 rows=83 loops=1)
Output: m.message_idnr, h.headervalue_id
-> Nested Loop (cost=0.00..2606.02 rows=49 width=24) (actual
time=0.136..4.039 rows=1845 loops=1)
Output: m.message_idnr, h.headername_id, h.headervalue_id
-> Nested Loop (cost=0.00..2499.00 rows=3 width=24)
(actual time=0.123..2.205 rows=83 loops=1)
Output: m.message_idnr, m.physmessage_id, p.id
-> Index Scan using dbmail_messages_1 on
public.dbmail_messages m (cost=0.00..20.90 rows=354 width=16) (actual
time=0.098..0.267 rows=366 loops=1)
Output: m.message_idnr, m.mailbox_idnr,
m.physmessage_id, m.seen_flag, m.answered_flag, m.deleted_flag,
m.flagged_flag, m.recent_flag, m.draft_flag, m.unique_id, m.status
Index Cond: (m.mailbox_idnr = 3945)
-> Index Scan using dbmail_physmessage_pkey on
public.dbmail_physmessage p (cost=0.00..6.99 rows=1 width=8) (actual
time=0.005..0.005 rows=0 loops=366)
Output: p.id, p.messagesize, p.rfcsize,
p.internal_date
Index Cond: (p.id = m.physmessage_id)
Filter: (p.internal_date > (now() - '3
days'::interval))
-> Index Scan using dbmail_header_pkey on
public.dbmail_header h (cost=0.00..35.47 rows=16 width=24) (actual
time=0.010..0.017 rows=22 loops=83)
Output: h.physmessage_id, h.headername_id,
h.headervalue_id
Index Cond: (h.physmessage_id = m.physmessage_id)
-> Index Scan using dbmail_headername_pkey on
public.dbmail_headername n (cost=0.00..0.27 rows=1 width=8) (actual
time=0.002..0.002 rows=0 loops=1845)
Output: n.id, n.headername
Index Cond: (n.id = h.headername_id)
Filter: ((n.headername)::text = ANY
('{resent-message-id,message-id}'::text[]))
-> Index Scan using dbmail_headervalue_pkey on
public.dbmail_headervalue v (cost=0.00..1.44 rows=1 width=8) (actual
time=0.014..0.014 rows=0 loops=83)
Output: v.id, v.hash, v.headervalue, v.sortfield, v.datefield
Index Cond: (v.id = h.headervalue_id)
Filter: ("substring"(v.headervalue, 0, 255) = '%e%'::text)
Total runtime: 9.371 ms
(27 rows)
So in the end, EXPLAIN says runtime 9.371ms, but in the postgres log:
EXPLAIN:LOG: duration: 1340.939 ms statement: EXPLAIN ANALYZE VERBOSE
SELECT m.message_idnr FROM....
Which duration is correct now, the one from EXPLAIN or from the log?
Because I got most of these SELECTs in the postgres log with ~1300ms.
But looking on EXPLAIN, it takes <10ms, so I wonder if I can optimize
here or not? And why the huge difference in times?
--
mit freundlichen Grüssen,
Michael Monnerie, Ing. BSc, Tel: +43 660 415 6531
Protéger.at Internet Services Austria
Web: http://protéger.at und http://proteger.at
Facebook https://facebook.com/protegerat
Mitglied im it-management Netzwerk http://it-management.at
--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: EXPLAIN time difference in real
@ 2014-04-26 14:17 Jov <amutu@amutu.com>
parent: Michael Monnerie <lists.michael.monnerie@is.it-management.at>
0 siblings, 1 reply; 6+ messages in thread
From: Jov @ 2014-04-26 14:17 UTC (permalink / raw)
To: Michael Monnerie <lists.michael.monnerie@is.it-management.at>; +Cc: pgsql-admin
Maybe your data or index is read from disk for some write heavy load
time,your sql get 1300ms.when you explain analyze the sql,the data and
index already in cached in the memory.
you can verify this by restart the server and run the sql from a fresh
start postgresql.
Jov
blog: http:amutu.com/blog <http://amutu.com/blog;
2014-04-26 20:55 GMT+08:00 Michael Monnerie <
lists.michael.monnerie@is.it-management.at>:
> Hi, I'm trying to find ways to optimize our db for dbmail (mailserver from
> dbmail.org), and found lots of the same SELECTs I want to look at. So I
> did use EXPLAIN ANALYZE:
>
> QUERY PLAN
> ------------------------------------------------------------
> ------------------------------------------------------------
> ------------------------------------------------------------
> ------------------
> Nested Loop (cost=0.00..2621.33 rows=1 width=8) (actual
> time=9.296..9.296 rows=0 loops=1)
> Output: m.message_idnr
> -> Nested Loop (cost=0.00..2619.88 rows=1 width=16) (actual
> time=0.158..8.137 rows=83 loops=1)
> Output: m.message_idnr, h.headervalue_id
> -> Nested Loop (cost=0.00..2606.02 rows=49 width=24) (actual
> time=0.136..4.039 rows=1845 loops=1)
> Output: m.message_idnr, h.headername_id, h.headervalue_id
> -> Nested Loop (cost=0.00..2499.00 rows=3 width=24)
> (actual time=0.123..2.205 rows=83 loops=1)
> Output: m.message_idnr, m.physmessage_id, p.id
> -> Index Scan using dbmail_messages_1 on
> public.dbmail_messages m (cost=0.00..20.90 rows=354 width=16) (actual
> time=0.098..0.267 rows=366 loops=1)
> Output: m.message_idnr, m.mailbox_idnr,
> m.physmessage_id, m.seen_flag, m.answered_flag, m.deleted_flag,
> m.flagged_flag, m.recent_flag, m.draft_flag, m.unique_id, m.status
> Index Cond: (m.mailbox_idnr = 3945)
> -> Index Scan using dbmail_physmessage_pkey on
> public.dbmail_physmessage p (cost=0.00..6.99 rows=1 width=8) (actual
> time=0.005..0.005 rows=0 loops=366)
> Output: p.id, p.messagesize, p.rfcsize,
> p.internal_date
> Index Cond: (p.id = m.physmessage_id)
> Filter: (p.internal_date > (now() - '3
> days'::interval))
> -> Index Scan using dbmail_header_pkey on
> public.dbmail_header h (cost=0.00..35.47 rows=16 width=24) (actual
> time=0.010..0.017 rows=22 loops=83)
> Output: h.physmessage_id, h.headername_id,
> h.headervalue_id
> Index Cond: (h.physmessage_id = m.physmessage_id)
> -> Index Scan using dbmail_headername_pkey on
> public.dbmail_headername n (cost=0.00..0.27 rows=1 width=8) (actual
> time=0.002..0.002 rows=0 loops=1845)
> Output: n.id, n.headername
> Index Cond: (n.id = h.headername_id)
> Filter: ((n.headername)::text = ANY
> ('{resent-message-id,message-id}'::text[]))
> -> Index Scan using dbmail_headervalue_pkey on
> public.dbmail_headervalue v (cost=0.00..1.44 rows=1 width=8) (actual
> time=0.014..0.014 rows=0 loops=83)
> Output: v.id, v.hash, v.headervalue, v.sortfield, v.datefield
> Index Cond: (v.id = h.headervalue_id)
> Filter: ("substring"(v.headervalue, 0, 255) = '%e%'::text)
> Total runtime: 9.371 ms
> (27 rows)
>
> So in the end, EXPLAIN says runtime 9.371ms, but in the postgres log:
>
> EXPLAIN:LOG: duration: 1340.939 ms statement: EXPLAIN ANALYZE VERBOSE
> SELECT m.message_idnr FROM....
>
> Which duration is correct now, the one from EXPLAIN or from the log?
> Because I got most of these SELECTs in the postgres log with ~1300ms. But
> looking on EXPLAIN, it takes <10ms, so I wonder if I can optimize here or
> not? And why the huge difference in times?
>
> --
> mit freundlichen Grüssen,
> Michael Monnerie, Ing. BSc, Tel: +43 660 415 6531
>
> Protéger.at Internet Services Austria
> Web: http://protéger.at <http://xn--protger-eya.at; und http://proteger.at
> Facebook https://facebook.com/protegerat
> Mitglied im it-management Netzwerk http://it-management.at
>
>
>
> --
> Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-admin
>
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: EXPLAIN time difference in real
@ 2014-04-26 17:48 Michael Monnerie <lists.michael.monnerie@is.it-management.at>
parent: Jov <amutu@amutu.com>
0 siblings, 1 reply; 6+ messages in thread
From: Michael Monnerie @ 2014-04-26 17:48 UTC (permalink / raw)
To: pgsql-admin
Am 26.04.2014 16:17, schrieb Jov:
> Maybe your data or index is read from disk for some write heavy load
> time,your sql get 1300ms.when you explain analyze the sql,the data and
> index already in cached in the memory.
>
> you can verify this by restart the server and run the sql from a fresh
> start postgresql.
>
Tried that:
EXPLAIN ANALYZE....
Total runtime: 280.537 ms
EXPLAIN:LOG: duration: 1501.807 ms statement: EXPLAIN ANALYZE VERBOSE
SELECT
So again 1500ms versus 280ms. Why?
--
mit freundlichen Grüssen,
Michael Monnerie, Ing. BSc, Tel: +43 660 415 6531
Protéger.at Internet Services Austria
Web: http://protéger.at und http://proteger.at
Facebook https://facebook.com/protegerat
Mitglied im it-management Netzwerk http://it-management.at
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: EXPLAIN time difference in real
@ 2014-04-26 18:27 Tom Lane <tgl@sss.pgh.pa.us>
parent: Michael Monnerie <lists.michael.monnerie@is.it-management.at>
0 siblings, 1 reply; 6+ messages in thread
From: Tom Lane @ 2014-04-26 18:27 UTC (permalink / raw)
To: Michael Monnerie <lists.michael.monnerie@is.it-management.at>; +Cc: pgsql-admin
Michael Monnerie <lists.michael.monnerie@is.it-management.at> writes:
> Tried that:
> EXPLAIN ANALYZE....
> Total runtime: 280.537 ms
> EXPLAIN:LOG: duration: 1501.807 ms statement: EXPLAIN ANALYZE VERBOSE
> SELECT
> So again 1500ms versus 280ms. Why?
Could the planning time possibly account for that? How long does a plain
EXPLAIN of the same query take?
regards, tom lane
--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: EXPLAIN time difference in real
@ 2014-04-27 10:57 Michael Monnerie <lists.michael.monnerie@is.it-management.at>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 6+ messages in thread
From: Michael Monnerie @ 2014-04-27 10:57 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-admin
Am 26.04.2014 20:27, schrieb Tom Lane:
> Could the planning time possibly account for that? How long does a
> plain EXPLAIN of the same query take? regards, tom lane
But I see lots of log entries with this query, all around 1200ms. That's
why I started investigating:
Apr 27 08:00:27 mail2 postgres[18740]: [29-1] 535bffef.4934 PARSE:LOG:
duration: 1151.523 ms parse 1160283289: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m
Apr 27 08:17:42 mail2 postgres[18740]: [30-1] 535bffef.4934 PARSE:LOG:
duration: 1148.042 ms parse 866717455: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m.
Apr 27 08:19:40 mail2 postgres[18740]: [31-1] 535bffef.4934 PARSE:LOG:
duration: 1172.965 ms parse 1037202578: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m
Apr 27 08:31:41 mail2 postgres[18740]: [32-1] 535bffef.4934 PARSE:LOG:
duration: 1153.232 ms parse 790322190: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m.
Apr 27 08:31:56 mail2 postgres[18740]: [33-1] 535bffef.4934 PARSE:LOG:
duration: 1184.642 ms parse 1338450192: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m
Apr 27 08:38:27 mail2 postgres[18740]: [34-1] 535bffef.4934 PARSE:LOG:
duration: 1144.726 ms parse 2071873295: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m
Apr 27 08:50:18 mail2 postgres[18740]: [35-1] 535bffef.4934 PARSE:LOG:
duration: 1168.980 ms parse 1321777959: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m
Apr 27 09:10:34 mail2 postgres[18740]: [36-1] 535bffef.4934 PARSE:LOG:
duration: 1148.291 ms parse 930586157: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m.
Apr 27 09:22:03 mail2 postgres[18740]: [37-1] 535bffef.4934 PARSE:LOG:
duration: 1167.311 ms parse 1114429065: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m
Apr 27 09:46:34 mail2 postgres[18740]: [38-1] 535bffef.4934 PARSE:LOG:
duration: 1156.446 ms parse 1841623092: SELECT m.message_idnr FROM
dbmail_messages m LEFT JOIN dbmail_physmessage p ON m
Here's the EXPLAIN w/o ANALYZE (exactly the same):
Nested Loop (cost=0.00..2713.94 rows=1 width=8)
Output: m.message_idnr
-> Nested Loop (cost=0.00..2712.49 rows=1 width=16)
Output: m.message_idnr, h.headervalue_id
-> Nested Loop (cost=0.00..2698.63 rows=49 width=24)
Output: m.message_idnr, h.headername_id, h.headervalue_id
-> Nested Loop (cost=0.00..2591.60 rows=3 width=24)
Output: m.message_idnr, m.physmessage_id, p.id
-> Index Scan using dbmail_messages_1 on
public.dbmail_messages m (cost=0.00..50.07 rows=365 width=16)
Output: m.message_idnr, m.mailbox_idnr,
m.physmessage_id, m.seen_flag, m.answered_flag, m.deleted_flag,
m.flagged_flag, m.recent_flag, m.draft_flag, m.unique_id, m.status
Index Cond: (m.mailbox_idnr = 3945)
-> Index Scan using dbmail_physmessage_pkey on
public.dbmail_physmessage p (cost=0.00..6.95 rows=1 width=8)
Output: p.id, p.messagesize, p.rfcsize,
p.internal_date
Index Cond: (p.id = m.physmessage_id)
Filter: (p.internal_date > (now() - '3
days'::interval))
-> Index Scan using dbmail_header_pkey on
public.dbmail_header h (cost=0.00..35.47 rows=16 width=24)
Output: h.physmessage_id, h.headername_id,
h.headervalue_id
Index Cond: (h.physmessage_id = m.physmessage_id)
-> Index Scan using dbmail_headername_pkey on
public.dbmail_headername n (cost=0.00..0.27 rows=1 width=8)
Output: n.id, n.headername
Index Cond: (n.id = h.headername_id)
Filter: ((n.headername)::text = ANY
('{resent-message-id,message-id}'::text[]))
-> Index Scan using dbmail_headervalue_pkey on
public.dbmail_headervalue v (cost=0.00..1.44 rows=1 width=8)
Output: v.id, v.hash, v.headervalue, v.sortfield, v.datefield
Index Cond: (v.id = h.headervalue_id)
Filter: ("substring"(v.headervalue, 0, 255) = '%e%'::text)
(26 rows)
PS: Is there anything I could possibly optimize in that query by another
index? I don't see anything obvious.
SELECT m.message_idnr FROM dbmail_messages m LEFT JOIN
dbmail_physmessage p ON m.physmessage_id=p.id LEFT JOIN dbmail_header h
ON p.id=h.physmessage_id LEFT JOIN dbmail_headername n ON
h.headername_id=n.id LEFT JOIN dbmail_headervalue v ON
h.headervalue_id=v.id WHERE m.mailbox_idnr=3945 AND n.headername IN
('resent-message-id','message-id') AND
SUBSTRING(v.headervalue,0,255)='%e%' AND p.internal_date > NOW() -
INTERVAL '3 DAY';
--
mit freundlichen Grüssen,
Michael Monnerie, Ing. BSc, Tel: +43 660 415 6531
Protéger.at Internet Services Austria
Web: http://protéger.at und http://proteger.at
Facebook https://facebook.com/protegerat
Mitglied im it-management Netzwerk http://it-management.at
--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: EXPLAIN time difference in real
@ 2014-04-27 15:43 Tom Lane <tgl@sss.pgh.pa.us>
parent: Michael Monnerie <lists.michael.monnerie@is.it-management.at>
0 siblings, 0 replies; 6+ messages in thread
From: Tom Lane @ 2014-04-27 15:43 UTC (permalink / raw)
To: Michael Monnerie <lists.michael.monnerie@is.it-management.at>; +Cc: pgsql-admin
Michael Monnerie <lists.michael.monnerie@is.it-management.at> writes:
> Am 26.04.2014 20:27, schrieb Tom Lane:
>> Could the planning time possibly account for that? How long does a
>> plain EXPLAIN of the same query take? regards, tom lane
> But I see lots of log entries with this query, all around 1200ms. That's
> why I started investigating:
Hmm ... that leads to a different idea: maybe you have got some other
operation that is (repeatedly) holding an exclusive lock on one of these
tables for about 1200ms? The time needed to acquire AccessShareLock on
a table being selected from is spent in the parser, so that wouldn't be
accounted for either by EXPLAIN's total runtime.
That theory isn't totally satisfying because you wouldn't expect unrelated
processes to all suffer the same wait time, but it's worth eliminating
lock waits as a factor in this. Try turning on log_lock_waits with a
threshold of a few hundred ms.
> Here's the EXPLAIN w/o ANALYZE (exactly the same):
This output doesn't answer my question, which is how long did the EXPLAIN
command take? You could run it with psql's \timing turned on.
> PS: Is there anything I could possibly optimize in that query by another
> index? I don't see anything obvious.
Optimization isn't the problem here: whatever is delaying these queries is
happening outside execution proper.
regards, tom lane
--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
^ permalink raw reply [nested|flat] 6+ messages in thread
end of thread, other threads:[~2014-04-27 15:43 UTC | newest]
Thread overview: 6+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2014-04-26 12:55 EXPLAIN time difference in real Michael Monnerie <lists.michael.monnerie@is.it-management.at>
2014-04-26 14:17 ` Jov <amutu@amutu.com>
2014-04-26 17:48 ` Michael Monnerie <lists.michael.monnerie@is.it-management.at>
2014-04-26 18:27 ` Tom Lane <tgl@sss.pgh.pa.us>
2014-04-27 10:57 ` Michael Monnerie <lists.michael.monnerie@is.it-management.at>
2014-04-27 15:43 ` Tom Lane <tgl@sss.pgh.pa.us>
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