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@xxxxxxxxxxxxxxxxxxx>:
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@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
