Help interpreting explain analyze output

Поиск
Список
Период
Сортировка
От Ole Tange
Тема Help interpreting explain analyze output
Дата
Msg-id Pine.LNX.4.58.0408151947250.22644@tigger.tange.dk
обсуждение исходный текст
Ответы Re: Help interpreting explain analyze output
Re: Help interpreting explain analyze output
Список pgsql-performance
Using this SQL:

EXPLAIN ANALYZE
SELECT DISTINCT
        sessionid,
        '2004-33' AS "yearweek",
        nd.niveau
INTO TEMP
        distinct_session
FROM
        httplog h ,niveaudir nd
WHERE
        hitDateTime>('now'::timestamp with time zone-'1440 min'::interval)
        and h.hostid=(select hostnameid from hostname where hostname='www.forbrug.dk')
        and h.statusid!=404
        and h.pathid=nd.pathid
;


I get this output:

QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Unique  (cost=5680.00..5766.70 rows=8670 width=26) (actual
time=17030.802..20044.614 rows=68213 loops=1)
   InitPlan
     ->  Index Scan using hostname_hostname_key on hostname
(cost=0.00..5.42 rows=1 width=4) (actual time=0.101..0.106 rows=1 loops=1)
           Index Cond: (hostname = 'www.forbrug.dk'::text)
   ->  Sort  (cost=5674.58..5696.25 rows=8670 width=26) (actual
time=17030.792..17689.650 rows=174714 loops=1)
         Sort Key: h.sessionid, '2004-33'::text, nd.niveau
         ->  Merge Join  (cost=4500.70..5107.48 rows=8670 width=26)
(actual time=3226.955..3966.011 rows=174714 loops=1)
               Merge Cond: ("outer".pathid = "inner".pathid)
               ->  Index Scan using niveaudir_pathid on niveaudir nd
(cost=0.00..465.59 rows=22715 width=26) (actual time=0.181..52.248
rows=22330 loops=1)
               ->  Sort  (cost=4500.70..4522.38 rows=8670 width=8) (actual
time=3226.666..3443.092 rows=174714 loops=1)
                     Sort Key: h.pathid
                     ->  Index Scan using httplog_hitdatetime on httplog h
(cost=0.00..3933.61 rows=8670 width=8) (actual time=0.425..1048.428
rows=174714 loops=1)
                           Index Cond: (hitdatetime > '2004-08-14
16:41:16.855829+02'::timestamp with time zone)
                           Filter: ((hostid = $0) AND (statusid <> 404))
 Total runtime: 20478.174 ms
(15 rows)

As I read it the output tells me what was done during the milliseconds:

0.101..0.106
0.181..52.248
0.425..1048.428
3226.666..3443.092
3226.955..3966.011
17030.792..17689.650
17030.802..20044.614

However, there are a few large gaps. What is happening during:

1048.428..3226.666 (2 secs)
3966.011..17030.792 (13 secs!)

This is the major part of the time but this is not accounted for in the
explain analyze output. It seems PostgreSQL is doing stuff that is not
part of the query plan. How do I get to know what this "stuff" is?


/Ole

В списке pgsql-performance по дате отправления:

Предыдущее
От: Tom Lane
Дата:
Сообщение: Re: Slow joins against set-returning functions
Следующее
От: Tom Lane
Дата:
Сообщение: Re: Help interpreting explain analyze output