Re: another query optimization question

David Teran <david(dot)teran(at)cluster9(dot)com> writes:
> [ query plan ]

I got a little distracted by the bizarre actual-time values shown for
some of the query steps:

> -> Merge Join (cost=2451266.53..2655338.83 rows=13604393 width=8)
> (actual time=82899.466..-2371037.726 rows=2091599 loops=1)

> -> Sort (cost=2451169.10..2483246.47 rows=12830947 width=8)
> (actual time=82891.076..-529619.213 rows=4187378 loops=1)

> -> Hash IN Join (cost=507.32..439065.37 rows=12830947
> width=8) (actual time=61.943..1874640.807 rows=4187378 loops=1)

The hash-join total time is obviously wrong seeing that the total
runtime is only about 100000 msec, and the negative values for the other
two are even more obviously wrong.

I recall that we saw similar symptoms once before, and I thought we'd
fixed it, but I didn't find any relevant mentions in the CVS logs.

What version are you running, exactly? Could you repeat the EXPLAIN
with client_min_messages set to 'debug2', and see if you see any
messages about InstrStartTimer or InstrStopNode?

regards, tom lane