Обсуждение: 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.  

-- 
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