Re: Where does the time go?

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> Tom Lane <tgl@sss.pgh.pa.us> wrote: 
>> You didn't show us the explain analyze results,

> The below is cut & paste directly from a psql run without editing.

OK, so the two plans do indeed have much different node execution
counts.  The EXPLAIN ANALYZE instrumentation overhead is basically
proportional to (rows+1)*loops summed over all the nodes in the plan,
so I count about 102112 node executions in the NOT IN plan versus
1145 in the NOT EXISTS plan --- in other words, 100x more overhead for
the former.

> The run time of the NOT IN query, as measured by elapsed time between
> SELECT CURRENT_TIMESTAMP executions, increased by 31 ms.

Works out to about 30 microsec per node execution, which seems a bit
high for modern machines ... and the coarse quantization of the
CURRENT_TIMESTAMP results is odd too.  What platform is this on exactly?

> That leaves an unaccounted difference between the time
> reported by EXPLAIN ANALYZE and the timestamp elapsed time of (on
> average) 9 ms for the NOT IN form of the query, and 41 ms for the NOT
> EXISTS for of the query.  (In the run shown above, it's higher.)  I'm
> guessing that this is the time spent in parsing and planning the query. 

Parse/plan time is one component, and another is the time spent by
EXPLAIN preparing its output display, which is not an area we've spent
any time at all optimizing --- I wouldn't be surprised if it's kinda
slow.  However, these plans are relatively similar in terms of the
complexity of the display, so it is odd that there'd be so much
difference.

> What is the best way to see where this time is going?

Profiling with gprof or some such tool might be educational.
        regards, tom lane