Re: another query optimization question

David Teran <david.teran@cluster9.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