Re: not exactly a bug report, but surprising behaviour

Tom Lane <tgl@sss.pgh.pa.us> writes:

> Greg Stark <gsstark@mit.edu> writes:
> > Neil Conway <neilc@samurai.com> writes:
> >> On Wed, 2003-02-05 at 15:49, Greg Stark wrote:
> > %   cumulative   self              self     total
> > time   seconds   seconds    calls   s/call   s/call  name
> > 16.59     97.88    97.88 69608411     0.00     0.00  ExecMakeFunctionResult
> > 7.08    139.65    41.77 79472258     0.00     0.00  comparetup_heap
> > 4.50    166.17    26.52 192211935     0.00     0.00  ExecEvalExpr
> >>
> >> Annoyingly enough, I get similarly strange gprof output (all zeros in
> >> the two right hand columns) on Debian --
>
> > Well this is Debian also, but I don't think that's related.
>
> Right.  Zeroes in the per-call columns are not unexpected.  If you get
> zeroes in the "self seconds" or "calls" fields then you have a
> measurement issue ... but what we're seeing here is just ye olde death
> of a thousand cuts, viz a lot of calls on routines that don't take very
> long in any one call.

Though it looks from the legend as if these columns really ought to be
"ms/call" not "s/call". Even so they would still be 0.00. It looks like
ExecMakeFunctionResult is taking about 1.6us/call.

> It is annoying that ExecMakeFunctionResult seems to be chewing so much
> CPU time, since it's nothing more than an interface routine.  But
> offhand I have no ideas on how to improve the situation.

Does ExecMakeFunctionResult have to do with pgpsql functions? Or internal
functions? I have a normal function that's being used in the query. It in turn
calls sqrt, pow, and cos. Should I inline my function manually? Should I do
... * ... instead of pow(..., 2) to calculate the square?

But I think this result is deceptive. It's still only 17% of the time. There
doesn't seem to be a way to get the linux gprof to display the total time per
function including children. That would indicate the place where algorithmic
changes would have the biggest impact.

--
greg