Message-ID: <535BACAC.90600@is.it-management.at>
Date: Sat, 26 Apr 2014 14:55:08 +0200
From: Michael Monnerie <lists.michael.monnerie@is.it-management.at>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
 rv:24.0) Gecko/20100101 Thunderbird/24.3.0
MIME-Version: 1.0
To: pgsql-admin@postgresql.org
Subject: EXPLAIN time difference in real
Content-Type: text/plain; charset=ISO-8859-15; format=flowed
Content-Transfer-Encoding: 8bit
Precedence: bulk
Sender: pgsql-admin-owner@postgresql.org

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