Re: Small performance regression in 9.2 has a big impact - Mailing list pgsql-performance

Scott Marlowe <scott.marlowe@gmail.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