Re: having difficulty with explain analyze output

David Rysdam <drysdam(at)ll(dot)mit(dot)edu> writes:
> On Tue, 26 Nov 2013 14:51:22 -0500, Martijn van Oosterhout <kleptog(at)svana(dot)org> wrote:
>> The Seq Scan took 674ms and was run once (loops=1)
>>
>> The Materialise was run 94951 times and took, on average, 0.011ms to
>> return the first row and 16ms to complete.
>>
>> 16.145 * 94951 = 1532983.895

> OK, this is helpful. But why would Materialize run 94k times? I thought
> the whole point of Materialize was to make a "virtual table" that could
> speed up "parent" queries. If it has to recreate the subquery, why would
> the planner choose to Materialize?

It *does* create a virtual table, or tuplestore --- what you are seeing
here is just the cost of pulling tuples out of that tuplestore. There
were 48139 * (94951 - 1) = 4570798050 tuples returned out of the
tuplestore rather than by directly querying the underlying seqscan, and
the time spent doing that was 16.145 * 94951 - 674.201 = 1532309.694 msec,
so on your machine it takes about a third of a microsecond to pull a tuple
from the in-memory tuplestore, which sounds about right allowing for
EXPLAIN ANALYZE's instrumentation overhead. Without the Materialize
node it'd have had to rescan the "sigs" table for each outer row, and
you'd probably still be waiting :-(

BTW, it's possible for a tuplestore to spill to disk, negating some of the
benefit, if the storage required exceeds work_mem. If you have a small
work_mem setting, does it go any faster if you increase work_mem?

regards, tom lane