Re: Small performance regression in 9.2 has a big impact

Scott Marlowe <scott(dot)marlowe(at)gmail(dot)com> writes:
> OK so there's a simple set of tree functions we use at work. They're
> quite fast in 8.4 and they've gotten about 40% slower in 9.2. They're
> a simple mix of sql and plpgsql functions which are at
> http://pastebin.com/SXTnNhd5 and which I've attached.

> Here's a test query:

> select tree_ancestor_keys('000000000000000100000001');

> According to explain analyze on both 8.4 and 9.2 they have the same
> plan. However, on the same machine the query is about 40% slower on
> 9.2. Note we're not hitting the disks, or even buffers here. It's pure
> in memory plpsql and sql that we're running.

> explain analyze select tree_ancestor_keys('000000000000000100000001')
> from generate_series(1,1000);

Hmm, I don't like the trend here. For the repeat-1000x query, I get
these reported execution times:

8.4 360 ms
9.0 365 ms
9.1 440 ms
9.2 510 ms
9.3 550 ms
9.4 570 ms
head 570 ms

(This is in assert-enabled builds, I'm too lazy to rebuild all the
branches without that.)

oprofile isn't showing any smoking gun AFAICS; it seems like things
are just generally slower. Still, we've not seen similar reports
elsewhere, so somehow this usage style is getting penalized in newer
branches compared to other cases. If it were all on 9.2's head
I'd be suspicious of the plancache mechanism, but evidently that's
not it, or at least not the whole story.

HEAD profile entries above 1%:

samples % image name symbol name
7573 7.2448 postgres AllocSetAlloc
6059 5.7964 postgres SearchCatCache
3533 3.3799 postgres AllocSetCheck
3420 3.2718 postgres base_yyparse
2104 2.0128 postgres AllocSetFree
1613 1.5431 postgres palloc
1523 1.4570 postgres ExecMakeFunctionResultNoSets
1313 1.2561 postgres check_list_invariants
1241 1.1872 postgres palloc0
1213 1.1604 postgres pfree
1157 1.1069 postgres SPI_plan_get_cached_plan
1136 1.0868 postgres GetPrivateRefCountEntry
1098 1.0504 postgres sentinel_ok
1085 1.0380 postgres hash_any
1057 1.0112 postgres core_yylex
1053 1.0074 postgres expression_tree_walker
1046 1.0007 postgres hash_search_with_hash_value

8.4 profile entries above 1%:

samples % image name symbol name
11782 10.3680 postgres AllocSetAlloc
7369 6.4846 postgres AllocSetCheck
5623 4.9482 postgres base_yyparse
4166 3.6660 postgres SearchCatCache
2671 2.3504 postgres ExecMakeFunctionResultNoSets
2060 1.8128 postgres MemoryContextAllocZeroAligned
2030 1.7864 postgres MemoryContextAlloc
1679 1.4775 postgres ExecEvalParam
1607 1.4141 postgres base_yylex
1389 1.2223 postgres check_list_invariants
1348 1.1862 postgres RevalidateCachedPlan
1341 1.1801 postgres AcquireExecutorLocks
1266 1.1141 postgres MemoryContextCreate
1256 1.1053 postgres hash_any
1255 1.1044 postgres expression_tree_walker
1202 1.0577 postgres expression_tree_mutator
1191 1.0481 postgres AllocSetReset

regards, tom lane