Well, I feel like a fool, because I failed to notice that the total runtime shown in that profile wasn't anywhere close to the actual wall clock time. gprof is indeed simply not counting the time spent in dynamically-linked code. With tsearch2 statically linked into the backend, a more believable picture emerges: % cumulative self self total time seconds seconds calls Ks/call Ks/call name 98.96 1495.93 1495.93 33035195 0.00 0.00 hemdistsign 0.27 1500.01 4.08 10030581 0.00 0.00 makesign 0.11 1501.74 1.73 588976 0.00 0.00 gistchoose 0.10 1503.32 1.58 683471 0.00 0.00 XLogInsert 0.05 1504.15 0.83 246579 0.00 0.00 sizebitvec 0.05 1504.93 0.78 446399 0.00 0.00 gtsvector_union 0.03 1505.45 0.52 3576475 0.00 0.00 LWLockRelease 0.03 1505.92 0.47 1649 0.00 0.00 gtsvector_picksplit 0.03 1506.38 0.47 3572572 0.00 0.00 LWLockAcquire 0.02 1506.74 0.36 444817 0.00 0.00 gtsvector_same 0.02 1507.09 0.35 4077089 0.00 0.00 AllocSetAlloc 0.02 1507.37 0.28 236984 0.00 0.00 gistdoinsert 0.02 1507.63 0.26 874195 0.00 0.00 hash_search 0.02 1507.89 0.26 9762101 0.00 0.00 gtsvector_penalty 0.01 1508.08 0.19 236984 0.00 0.00 gistmakedeal 0.01 1508.27 0.19 841754 0.00 0.00 UnpinBuffer 0.01 1508.45 0.18 22985469 0.00 0.00 hemdistcache 0.01 1508.63 0.18 3998572 0.00 0.00 LockBuffer 0.01 1508.81 0.18 686681 0.00 0.00 gtsvector_compress 0.01 1508.98 0.17 11514275 0.00 0.00 gistdentryinit So we gotta fix hemdistsign ... regards, tom lane
