Eric Ridge <ebr@tcdi.com> writes:
> I should have included the entire explain output:
> stub AM:
> Index Scan using idxa_stub on test2 (cost=0.00..2.68 rows=1 width=5)
> (actual time=0.002..0.002 rows=0 loops=1)
> Index Cond: (a ==> '1'::text)
> Total runtime: 0.247 ms
> builtin btree AM:
> Index Scan using idxa_btree on test2 (cost=0.00..4.68 rows=1 width=5)
> (actual time=0.024..0.026 rows=1 loops=1)
> Index Cond: (a = '1'::text)
> Total runtime: 0.060 ms
> If the "actual time" numbers are really a measure of the amount of time
> spent in (at least) the index, it seems the stub should report a
> smaller "total runtime", but alas, it doesn't.
The difference between "total runtime" and the top plan node's runtime
has to represent plan startup/shutdown time. I'm suspicious that your
stubs are somehow not initializing something, though on first glance I
do not see what.
Theory B would be that there's some huge overhead in calling non-built-in
functions on your platform. We do know that looking up a "C" function is
significantly more expensive than looking up a "builtin" function, but
there should only be half a dozen such calls involved in this test case;
it's hard to credit that that takes 200 msec. Does the time drop at all
on second and subsequent repetitions in a single backend run?
regards, tom lane
