Jeff Frost <jeff@frostconsultingllc.com> writes:
> Got my oprofile man page reading done. Here's the general opreport:
> ...
> And the postgres one:
> samples % symbol name
> 3894022 12.6488 LWLockAcquire
> 3535497 11.4842 slot_deform_tuple
> 3030280 9.8431 LWLockRelease
> 2279699 7.4050 HeapTupleSatisfiesSnapshot
> 1782097 5.7887 ExecMakeFunctionResultNoSets
> 1209262 3.9280 ExecEvalScalarVar
> 1128461 3.6655 heap_release_fetch
> 916447 2.9768 LockBuffer
> 898437 2.9183 _bt_checkkeys
> 887904 2.8841 btgettuple
> 728377 2.3660 slot_getattr
> 648121 2.1053 hash_search
> 608352 1.9761 _bt_restscan
> 574699 1.8668 index_getnext
> 570999 1.8547 _bt_step
> 517225 1.6801 FunctionCall2
> 501845 1.6301 _bt_next
> 452142 1.4687 IndexNext
> 426455 1.3852 PinBuffer
It seems to basically be spending its time scanning tuples and applying
some function or other (probably a WHERE clause). The btree references
suggest that the scan is an indexscan and not a brute-force seqscan, but
still I wonder if the problem isn't that the planner has switched to some
plan much less efficient than the one it was using before. oprofile is
too low-level to give us much info about that, unfortunately.
Probably your next step should be to investigate the plans being used
for the queries in the slow functions. See the archives for hints, eg
http://archives.postgresql.org/pgsql-performance/2006-06/msg00301.php
regards, tom lane