Re: Understanding EXPLAIN ANALYZE output

On Thursday February 10 2005 5:01, David Fetter wrote:
> On Thu, Feb 10, 2005 at 05:19:41PM -0500, Tom Lane wrote:
> > David Fetter <david(at)fetter(dot)org> writes:
> > > I'd be delighted to, but I'm not sure how to see to it
> > > that EXPLAIN gets the CMD_SELECT flag. What all files
> > > need to change to effect this? Or have I drastically
> > > misunderstood what's involved?
> >
> > It doesn't. See
> > http://archives.postgresql.org/pgsql-committers/2005-02/msg0
> >0073.php
>
> Yay!!
>
> Thanks a big bunch, Tom :)

Doodz, u r so phat! We'd still be working out who
should be invited to the first requirements analysis
meeting if this were at company X...

This is close but my regexes are not quite right...

CREATE TYPE pg_explain_analyze_in AS (
exp text
);

CREATE TYPE pg_explain_analyze_out AS (
node_id integer,
node varchar,
parent_node_id integer,
level integer,
index varchar,
relation varchar,
plan_startup_cost float,
plan_total_cost float,
plan_rows bigint,
plan_width integer,
act_startup_cost float,
act_total_cost float,
act_rows bigint,
act_loops bigint,
condition varchar,
filter varchar,
total_time float,
raw_out varchar
);

CREATE OR REPLACE FUNCTION pg_explain_analyze(query text) RETURNS SETOF pg_explain_analyze_out AS $$
DECLARE
row pg_explain_analyze_in;
ret pg_explain_analyze_out;
i integer;
indent integer;
BEGIN
i = 0;
FOR row IN EXECUTE 'EXPLAIN ANALYZE ' || query LOOP
ret.node_id := i;
row.exp := replace(row.exp, '-> ', '');
ret.node := substring(row.exp FROM '[-> ]?(\\S[^\\(:]+) \\(');
ret.parent_node_id := -1;
ret.level := length(substring(row.exp FROM '^(\\s*)\\S'));
ret.index := substring(row.exp FROM 'Index Scan using (\\S+) on \\S+');
ret.relation := substring(row.exp FROM 'Scan using \\S+ on (\\S+)');
ret.plan_startup_cost := substring(row.exp FROM 'cost=(\\d+\\.\\d+)');
ret.plan_total_cost := substring(row.exp FROM 'cost=\\d+\\.\\d+\\.\\.(\\d+\\.\\d+) rows');
ret.plan_rows := substring(row.exp FROM ' rows=([[:digit:]]+) width');
ret.plan_width := substring(row.exp FROM ' width=([[:digit:]]+)');
ret.act_startup_cost := substring(row.exp FROM ' width=([[:digit:]]+)');
ret.act_total_cost := substring(row.exp FROM ' width=([[:digit:]]+)');
ret.act_startup_cost := substring(row.exp FROM 'time=(\\d+\\.\\d+)');
ret.act_total_cost := substring(row.exp FROM 'time=\\d+\\.\\d+\\.\\.(\\d+\\.\\d+) rows');
ret.act_rows := substring(row.exp FROM ' rows=([[:digit:]]+) loops');
ret.act_loops := substring(row.exp FROM ' rows=[[:digit:]]+ loops=([[:digit:]]+)\\)');
ret.condition := substring(row.exp FROM 'Cond: \\((\\.+)\\)');
ret.filter := substring(row.exp FROM 'Filter: \\((\\.*)\\)');
ret.total_time := substring(row.exp FROM 'Total runtime: (\\d+\\.\\d+) ms');
ret.raw_out := row.exp;

IF substring(row.exp FROM '\\S') IS NOT NULL THEN
RETURN NEXT ret;
END IF;
i := i + 1;
END LOOP;

RETURN;
END;
$$ LANGUAGE plpgsql VOLATILE STRICT;

% psql -c "explain analyze select * from foobarbaz_view where id < 3;"
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.00..15.13 rows=2 width=12) (actual time=0.060..0.090 rows=2 loops=1)
-> Nested Loop (cost=0.00..9.08 rows=2 width=12) (actual time=0.043..0.059 rows=2 loops=1)
-> Index Scan using baz_pkey on baz (cost=0.00..3.03 rows=2 width=8) (actual time=0.017..0.021 rows=2 loops=1)
Index Cond: (id < 3)
-> Index Scan using bar_pkey on bar (cost=0.00..3.01 rows=1 width=8) (actual time=0.012..0.014 rows=1 loops=2)
Index Cond: ("outer".bar_id = bar.id)
-> Index Scan using foo_pkey on foo (cost=0.00..3.01 rows=1 width=4) (actual time=0.010..0.011 rows=1 loops=2)
Index Cond: ("outer".foo_id = foo.id)
Total runtime: 0.226 ms
(9 rows)

% psql -c "SELECT case when node notnull then node||'(cost='||plan_startup_cost||'..'||plan_total_cost||' rows='||plan_rows||' width='||plan_width||') (actual time='||act_startup_cost||'..'||act_total_cost||' rows='||act_rows||' loops='||act_loops||' per row='||case when act_rows > 0 then to_char(act_total_cost/act_rows, '9.999') else '0.00' end||')' else 'Total runtime: '||total_time||' ms' end FROM pg_explain_analyze('select * from foobarbaz_view where id < 3');"
case
-------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0..15.13 rows=2 width=12) (actual time=0.058..0.088 rows=2 loops=1 per row= .044)
Nested Loop (cost=0..9.08 rows=2 width=12) (actual time=0.04..0.056 rows=2 loops=1 per row= .028)
Index Scan using baz_pkey on baz (cost=0..3.03 rows=2 width=8) (actual time=0.016..0.02 rows=2 loops=1 per row= .010)

Index Scan using bar_pkey on bar (cost=0..3.01 rows=1 width=8) (actual time=0.011..0.012 rows=1 loops=2 per row= .012)

Index Scan using foo_pkey on foo (cost=0..3.01 rows=1 width=4) (actual time=0.01..0.011 rows=1 loops=2 per row= .011)

Total runtime: 0.2 ms
(9 rows)