Re: EXPLAIN time difference in real

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(dot)michael(dot)monnerie(at)is(dot)it-management(dot)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(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-admin
>