Обсуждение: EXPLAIN time difference in real
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
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
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 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
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
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
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
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