Understanding EXPLAIN ANALYZE output

On Wed, Feb 09, 2005 at 11:00:00AM -0700, Ed L. wrote:

34 -> Index Scan using idx_queryoutcome_occurrencehistory_key on queryoutcome (cost=0.00..10.28 rows=28 width=1065) (actual time=4.63..4.63 rows=0 loops=1014)

^^^^^^^^^^ ^^^^

35 Index Cond: ("outer"."key" = queryoutcome.occurrencehistory_key)

If I understand these correctly, line 22's nested loop finished
returning the last row 72.80ms into the query, and then line
21's nested loop returns its 0 rows 4769.59ms into the query.
That would seem to mean 4696.79ms were spent executing the
nested loop on line 21 prior to returning the first row.

4796.0 ms are the time it took for 34's index scan to complete the 1014
loops, I'd think.

--
Alvaro Herrera (<alvherre[@]dcc.uchile.cl>)
"La naturaleza, tan fr�gil, tan expuesta a la muerte... y tan viva"

On Wed, Feb 09, 2005 at 12:54:27PM -0700, Ed L. wrote:

On Wednesday February 9 2005 12:04, you wrote:

4796.0 ms are the time it took for 34's index scan to complete
the 1014 loops, I'd think.

Interesting. Reindexing the index

idx_queryoutcome_occurrencehistory_key

sped up the query to sub-second. This is a 7.3.4 cluster. I
wonder if this that 7.3 index bloat bug?

Hard to say, because you didn't provide more info (such as if the index
has the right deletion pattern), but it could be.

--
Alvaro Herrera (<alvherre[@]dcc.uchile.cl>)
"I call it GNU/Linux. Except the GNU/ is silent." (Ben Reiter)

On Wednesday February 9 2005 12:56, Alvaro Herrera wrote:

On Wed, Feb 09, 2005 at 12:54:27PM -0700, Ed L. wrote:

sped up the query to sub-second. This is a 7.3.4 cluster.
I wonder if this that 7.3 index bloat bug?

Hard to say, because you didn't provide more info (such as if
the index has the right deletion pattern), but it could be.

What delete pattern would cause the problem?

Ed

On Wed, Feb 09, 2005 at 01:11:36PM -0700, Ed L. wrote:

On Wednesday February 9 2005 12:56, Alvaro Herrera wrote:

On Wed, Feb 09, 2005 at 12:54:27PM -0700, Ed L. wrote:

sped up the query to sub-second. This is a 7.3.4 cluster.
I wonder if this that 7.3 index bloat bug?

Hard to say, because you didn't provide more info (such as if
the index has the right deletion pattern), but it could be.

What delete pattern would cause the problem?

A key on which you insert on one side and delete on the other. A table
indexed by date, and you regularly delete the oldest entries, for
example.

--
Alvaro Herrera (<alvherre[@]dcc.uchile.cl>)
"El Maquinismo fue proscrito so pena de cosquilleo hasta la muerte"
(Ijon Tichy en Viajes, Stanislaw Lem)

"Ed L." <pgsql@bluepolka.net> writes:

I'm trying to optimize a large query by looking at
EXPLAIN ANALYZE output. Here's what I think may be
the most relevant snippet:

21 -> Nested Loop (cost=0.00..108.85 rows=1 width=1196) (actual time=4769.59..4769.59 rows=0 loops=1)
22 -> Nested Loop (cost=0.00..64.78 rows=4 width=131) (actual time=0.41..72.80 rows=1014 loops=1)
...
34 -> Index Scan using idx_queryoutcome_occurrencehistory_key on queryoutcome (cost=0.00..10.28 rows=28 width=1065) (actual time=4.63..4.63 rows=0 loops=1014)
35 Index Cond: ("outer"."key" = queryoutcome.occurrencehistory_key)

If I understand these correctly, line 22's nested loop finished
returning the last row 72.80ms into the query, and then line
21's nested loop returns its 0 rows 4769.59ms into the query.

No, you don't understand correctly. The numbers are not "time into the
query", they are "elapsed time spent within this node and its
children". The above says that we spent a total of 72.80 msec executing
line 22 and its children, and a total of 4.63*1014 msec executing line
34 (which has no children, so that's all in the indexscan). That adds
up to 4767.62 msec, so the actual joining at line 21 took only 1.97 msec.
None of this tells you anything about how far "into the query" all this
stuff happened. It is however clear that line 34 is the bulk of the
time.

regards, tom lane

On Wednesday February 9 2005 2:21, Tom Lane wrote:

"Ed L." <pgsql@bluepolka.net> writes:

21 -> Nested Loop (cost=0.00..108.85 rows=1
width=1196) (actual time=4769.59..4769.59 rows=0 loops=1) 22
-> Nested Loop (cost=0.00..64.78 rows=4 width=131)
(actual time=0.41..72.80 rows=1014 loops=1) ...
34 -> Index Scan using
idx_queryoutcome_occurrencehistory_key on queryoutcome
(cost=0.00..10.28 rows=28 width=1065) (actual
time=4.63..4.63 rows=0 loops=1014) 35 Index
Cond: ("outer"."key" = queryoutcome.occurrencehistory_key)

If I understand these correctly, line 22's nested loop
finished returning the last row 72.80ms into the query, and
then line 21's nested loop returns its 0 rows 4769.59ms into
the query.

No, you don't understand correctly. The numbers are not "time
into the query", they are "elapsed time spent within this node
and its children". The above says that we spent a total of
72.80 msec executing line 22 and its children, and a total of
4.63*1014 msec executing line 34 (which has no children, so
that's all in the indexscan). That adds up to 4767.62 msec,
so the actual joining at line 21 took only 1.97 msec. None of
this tells you anything about how far "into the query" all
this stuff happened. It is however clear that line 34 is the
bulk of the time.

Very helpful, thanks. So time spent in that node & its children
= first number of "actual time" * loops? That seems consistent
with the fact that reindexing the index led to the huge speedup.
If the second number of the "actual time" part means time
elapsed in this node and its children until the last row was
returned, why does it say "actual time=4.63..4.63" instead of
"actual time=4.63..4767.62"? Would it say that if there had
been 1 row returned instead of none?

Ed

"Ed L." <pgsql@bluepolka.net> writes:

If the second number of the "actual time" part means time
elapsed in this node and its children until the last row was
returned, why does it say "actual time=4.63..4.63" instead of
"actual time=4.63..4767.62"?

The reason we do that is to make the "actual" numbers comparable to the
way that the estimated costs are presented. The estimated costs are for
a single execution of the node, but the inner side of a nestloop join is
re-executed for each row coming from the outer side. In this case, the
outer side produced 1014 rows so we ran 1014 separate executions of the
inner indexscan. If we just reported 4767.62 as the total time, it
would look like the estimated indexscan cost of 10.28 was completely out
of whack, which it isn't. So instead, we report a per-execution cost
and a "loops" number that you have to multiply by if you are thinking
about total time spent.

regards, tom lane

On Wed, Feb 09, 2005 at 02:37:39PM -0700, Ed L. wrote:

Very helpful, thanks. So time spent in that node & its children
= first number of "actual time" * loops? That seems consistent
with the fact that reindexing the index led to the huge speedup.
If the second number of the "actual time" part means time
elapsed in this node and its children until the last row was
returned, why does it say "actual time=4.63..4.63" instead of
"actual time=4.63..4767.62"? Would it say that if there had
been 1 row returned instead of none?

The meaning of the times is (IIRC) derived from the numbers used in the
planning. The first number is "time to first result", the second number
is "time to last result". So if you're doing a "LIMIT 1" query, only
the first number is relevent.

The purpose of the explain output is to determine where the bottlenecks
are and as such each node only counts time spent in it and all its
subnodes. So for example a Sort node has a really high start time
(because all subnodes must complete before sorting can complete) but
the end time is shortly after because it only needs to pump out tuples.

The complication comes because nodes can be executed in their entirety
repeatedly, especially with nested joins, the inner loop is repeatedly
executed with different parameters. I was one of the major contributers
of this feature originally and there was discussion about how to
represent this. I think the rationale is that the figures should not
appear radically different just because a Node is reexecuted a lot, so
you get an extra result "loops" and the numbers look like a single
index scan. If you look at the numbers the planner uses, it follows the
same pattern.

In general, the EXPLAIN ANALYZE output follows the planner output as
close as possible. If you look at the original query posted, it showed
an Index Scan costing 4.63..4.63 which means the index scan is taking
(on average) 4.63ms to return 1 row! If it displayed as 4000 or
something it would be a lot less clear what was going on.

Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

On Wednesday February 9 2005 3:13, Martijn van Oosterhout wrote:

In general, the EXPLAIN ANALYZE output follows the planner
output as close as possible. If you look at the original query
posted, it showed an Index Scan costing 4.63..4.63 which means
the index scan is taking (on average) 4.63ms to return 1 row!
If it displayed as 4000 or something it would be a lot less
clear what was going on.

Hope this helps,

Both replies help very much, thanks. Regarding 4.63ms to return
a row, I know I/O speeds vary widely depending on conditions and
hardware, but what would you say is a "red flag" value for the
actual time to retrieve a row. I see that for most of the other
times in this example, 0.01ms to 0.10ms is not unusual.

Ed

On Wed, Feb 09, 2005 at 03:38:32PM -0700, Ed L. wrote:

On Wednesday February 9 2005 3:13, Martijn van Oosterhout wrote:

In general, the EXPLAIN ANALYZE output follows the planner
output as close as possible. If you look at the original query
posted, it showed an Index Scan costing 4.63..4.63 which means
the index scan is taking (on average) 4.63ms to return 1 row!
If it displayed as 4000 or something it would be a lot less
clear what was going on.

Hope this helps,

Both replies help very much, thanks. Regarding 4.63ms to return
a row, I know I/O speeds vary widely depending on conditions and
hardware, but what would you say is a "red flag" value for the
actual time to retrieve a row. I see that for most of the other
times in this example, 0.01ms to 0.10ms is not unusual.

That number 4.63ms is way out. Especially considering this is an
*average* over 1000+ iterations which tells you something it very wrong
with that step. Note, Index Scan can take a long time, it completely
depends on how many rows it returns. Also, if there is an additional
filter on the index (someotherfield = 'x') it may take a while to
return a single value.

But for unique indexes on primary keys (which is what this appears to
be) the times should hopefully be <1ms *average* (caching and load are
imprtant factors).

Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/

Thinking about how to make this analysis faster and less labor-
intensive ...

I know of no other way to get the detailed performance data provided
via EXPLAIN ANALYZE without just painfully disassembling a query.
It seems it would be pretty useful w/r/t performance monitoring to
be able to retrieve such performance numbers as those in EXPLAIN
ANALYZE in a rowset via query. That would seem to enable automated
identification of things like single rows taking 4.63ms to retrieve.
I can think of a number of application queries for which I would
like to do this sort of analysis routinely across a bunch of
database clusters. I guess one could just parse the explain output
in the meantime but, dreaming a bit here, for example,

SELECT node_id, op, parent_node_id, index, relation,
cost_first, cost_last, cost_rows, cost_width,
actual_first, actual_last, actual_rows, actual_loops,
index_condition
FROM pg_explain_analyze('SELECT * FROM foo');

with output similar to

node_id | op | parent_node_id ... actual_last | actual_rows | actual_loops ...
---------+-------------+----------------...--------------+-------------+--------------...
21 | Nested Loop | 20 ... 72.80 | 1014 | 1
22 | Nested Loop | 21 ... 46.51 | 1014 | 1
...
34 | Index Scan | 21 ... 4.63 | 0 | 1014
...

Then, as a routine measure, catch those cases like this one,

SELECT sql, op, index, relation, actual_first
FROM pg_explain_analyze('SELECT * FROM foo')
WHERE op = 'Index Scan'
AND actual_first > 1.0;

Thankfully, I'm sure there are a lot of skilled postgresql'ers
just sitting around right now wishing they had something to do.

Ed

On Wed, Feb 09, 2005 at 04:34:30PM -0700, Ed L. wrote:

Thinking about how to make this analysis faster and less labor-
intensive ...

I know of no other way to get the detailed performance data provided
via EXPLAIN ANALYZE without just painfully disassembling a query.
It seems it would be pretty useful w/r/t performance monitoring to
be able to retrieve such performance numbers as those in EXPLAIN
ANALYZE in a rowset via query. That would seem to enable automated
identification of things like single rows taking 4.63ms to retrieve.
I can think of a number of application queries for which I would
like to do this sort of analysis routinely across a bunch of
database clusters. I guess one could just parse the explain output
in the meantime but, dreaming a bit here, for example,

SELECT node_id, op, parent_node_id, index, relation,
cost_first, cost_last, cost_rows, cost_width,
actual_first, actual_last, actual_rows, actual_loops,
index_condition
FROM pg_explain_analyze('SELECT * FROM foo');

with output similar to

node_id | op | parent_node_id ... actual_last | actual_rows | actual_loops ...
---------+-------------+----------------...--------------+-------------+--------------...
21 | Nested Loop | 20 ... 72.80 | 1014 | 1
22 | Nested Loop | 21 ... 46.51 | 1014 | 1
...
34 | Index Scan | 21 ... 4.63 | 0 | 1014
...

Then, as a routine measure, catch those cases like this one,

SELECT sql, op, index, relation, actual_first
FROM pg_explain_analyze('SELECT * FROM foo')
WHERE op = 'Index Scan'
AND actual_first > 1.0;

Thankfully, I'm sure there are a lot of skilled postgresql'ers
just sitting around right now wishing they had something to do.

Well, I'm a little bored; I've got tomorrow off, and this seems like
it might be doable in the kind of high-level PL/Foo's with which I'm
familiar. What would the returning rowtype for
pg_explain_analyze(TEXT) be?

Cheers,
D
--
David Fetter david@fetter.org http://fetter.org/
phone: +1 510 893 6100 mobile: +1 415 235 3778

Remember to vote!

David Fetter wrote:

On Wed, Feb 09, 2005 at 04:34:30PM -0700, Ed L. wrote:

Thinking about how to make this analysis faster and less labor-
intensive ...

I know of no other way to get the detailed performance data provided
via EXPLAIN ANALYZE without just painfully disassembling a query.
It seems it would be pretty useful w/r/t performance monitoring to
be able to retrieve such performance numbers as those in EXPLAIN
ANALYZE in a rowset via query. That would seem to enable automated
identification of things like single rows taking 4.63ms to retrieve.
I can think of a number of application queries for which I would
like to do this sort of analysis routinely across a bunch of
database clusters. I guess one could just parse the explain output
in the meantime but, dreaming a bit here, for example,

SELECT node_id, op, parent_node_id, index, relation,
cost_first, cost_last, cost_rows, cost_width,
actual_first, actual_last, actual_rows, actual_loops,
index_condition
FROM pg_explain_analyze('SELECT * FROM foo');

with output similar to

node_id | op | parent_node_id ... actual_last | actual_rows | actual_loops ...
---------+-------------+----------------...--------------+-------------+--------------...
21 | Nested Loop | 20 ... 72.80 | 1014 | 1
22 | Nested Loop | 21 ... 46.51 | 1014 | 1
...
34 | Index Scan | 21 ... 4.63 | 0 | 1014
...

Then, as a routine measure, catch those cases like this one,

SELECT sql, op, index, relation, actual_first
FROM pg_explain_analyze('SELECT * FROM foo')
WHERE op = 'Index Scan'
AND actual_first > 1.0;

Thankfully, I'm sure there are a lot of skilled postgresql'ers
just sitting around right now wishing they had something to do.

Well, I'm a little bored; I've got tomorrow off, and this seems like
it might be doable in the kind of high-level PL/Foo's with which I'm
familiar. What would the returning rowtype for
pg_explain_analyze(TEXT) be?

You could return it as formatted text. if you want to make it simple.

J

Cheers,
D

-- 
Command Prompt, Inc., home of Mammoth PostgreSQL - S/ODBC and S/JDBC
Postgresql support, programming shared hosting and dedicated hosting.
+1-503-667-4564 - jd@commandprompt.com - http://www.commandprompt.com
PostgreSQL Replicator -- production quality replication for PostgreSQL

On Wednesday February 9 2005 7:31, David Fetter wrote:

On Wed, Feb 09, 2005 at 04:34:30PM -0700, Ed L. wrote:

Thinking about how to make this analysis faster and less
labor- intensive ...

SELECT node_id, op, parent_node_id, index, relation,
cost_first, cost_last, cost_rows, cost_width,
actual_first, actual_last, actual_rows,
actual_loops, index_condition
FROM pg_explain_analyze('SELECT * FROM foo');

Thankfully, I'm sure there are a lot of skilled
postgresql'ers just sitting around right now wishing they
had something to do.

Well, I'm a little bored; I've got tomorrow off, and this
seems like it might be doable in the kind of high-level
PL/Foo's with which I'm familiar. What would the returning
rowtype for
pg_explain_analyze(TEXT) be?

LOL. If you're serious, I was thinking of something like this:

node_id integer not null unique
op varchar: "Index Scan"|"Hash Join"|"Seq Scan"|...
parent_node_id integer: node_id of parent node
index varchar: name of index for scan (oid better?)
relation varchar: name of relation for scan (oid better?)
cost_first float: first cost number
cost_last float: second cost number
cost_rows bigint
cost_width integer
actual_first float: time to first row
actual_last float: time to last row
actual_rows bigint
actual_loops bigint
condition varchar: what comes after "Index Cond:"|"Hash Cond:"|...
total_time float: total query time

How's that?

That might be a start. This is half-baked and you may be
the new head chef, so feel free.

Ed

Hi,

I am trying to keep database access encapsulated in functions from an insert
and update point of view so as all of the applications writing to the
database are using the same functions/statements.

My problem is I was creating functions to do inserts/updates and now I have
a table with more than 32 columns and the functions seem to only want to
have 32 parameters?

Is there any way around this?

I have used stored procedures in this way with Oracle/SQL server before.Or
is there another strategy I could use?

I am using Windows 2000 Postgres 8.0.1 if it makes a difference

Thanks in advance,
Oisin

On Wednesday February 9 2005 8:07, Ed L. wrote:

Well, I'm a little bored; I've got tomorrow off, and this
seems like it might be doable in the kind of high-level
PL/Foo's with which I'm familiar. What would the returning
rowtype for
pg_explain_analyze(TEXT) be?

LOL. If you're serious, I was thinking of something like
this:

node_id integer not null unique
op varchar: "Index Scan"|"Hash Join"|"Seq Scan"|...
parent_node_id integer: node_id of parent node
index varchar: name of index for scan (oid better?)
relation varchar: name of relation for scan (oid better?)
cost_first float: first cost number
cost_last float: second cost number
cost_rows bigint
cost_width integer
actual_first float: time to first row
actual_last float: time to last row
actual_rows bigint
actual_loops bigint
condition varchar: what comes after "Index Cond:"|"Hash
Cond:"|... total_time float: total query time

You might drive the rowtype by what you (alias I) hope to get out
of it: 1) easy discovery of the slowest parts of the query, 2)
really slow avg row retrieval times (like the 4.63ms/row
discussed earlier in this thread), and I don't know what else.
Part 2 seems straight forward with this scheme, less sure about
part 1.

Ed

On Wed, Feb 09, 2005 at 06:31:11PM -0800, David Fetter wrote:

On Wed, Feb 09, 2005 at 04:34:30PM -0700, Ed L. wrote:

SELECT sql, op, index, relation, actual_first
FROM pg_explain_analyze('SELECT * FROM foo')
WHERE op = 'Index Scan'
AND actual_first > 1.0;

Thankfully, I'm sure there are a lot of skilled postgresql'ers
just sitting around right now wishing they had something to do.

Well, I'm a little bored; I've got tomorrow off, and this seems like
it might be doable in the kind of high-level PL/Foo's with which I'm
familiar. What would the returning rowtype for
pg_explain_analyze(TEXT) be?

I started looking at this earlier. Is it even possible to get
EXPLAIN output via SPI (and thus the PLs' interfaces to SPI)? Or
would the function have to make a new connection to the database
and issue the EXPLAIN as an ordinary client? I suppose a proper
implementation would be written in C and would call the internal
functions that generate the output, but I was thinking about how
to do something simple in a higher-level PL.

As for the return type, I was going to look at explain_outNode()
in src/backend/commands/explain.c and get some ideas from there.

--
Michael Fuhr
http://www.fuhr.org/~mfuhr/

"Ed L." <pgsql@bluepolka.net> writes:

and I don't know what else.

How about being able to search for queries where expected rows and actual rows
are far apart.

--
greg

Any advice for an opensource newbie running on Windows 2000? How hard is it
to rebuild for windows? Any instructions? What compiler?

Oisin

----- Original Message -----
From: "Bradley D. Snobar" <bradsnobar@netscape.net>
To: ""Oisin Glynn"" <me@oisinglynn.com>
Sent: Wednesday, February 09, 2005 10:40 PM
Subject: RE: [GENERAL] Functions with more than 32 parameters