Re: not exactly a bug report, but surprising behaviour

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> writes:

> Greg Stark <gsstark(at)mit(dot)edu> writes:
> > Neil Conway <neilc(at)samurai(dot)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