Re: Help interpreting explain analyze output

On Sun, Aug 15, 2004 at 07:47:53PM +0200, Ole Tange wrote:

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

The first time given is not the time when this stage of the plan starts
to execute, but the time when it returns its first row. So most of the
time in this query is being spent doing the two sorts - in a sort, of
course, most of the work has to be done before any rows can be returned.

Richard