Re: dbt2 performance regresses from 9.1.6 to 9.2.1

On Thu, Nov 1, 2012 at 12:51 AM, Dong Ye <yed(at)vmware(dot)com> wrote:
> The average notpm is 61384.24 with 9.1.6 and 57381.43 with 9.2.1.
> Plotting notps over time shows that the slowdown of 9.2.1 is evident across the entire run period.
> Since we also observed sustained 80+% CPU utilization during both runs, we suspected this is a CPU bottleneck issue.
> So we run oprofile hoping that the profiles may suggest one is using CPU less productively than the other; but nothing jumped out to that explanation.
> The profiling results are posted on http://pgsql.privatepaste.com/3fa3ae0627 (9.1.6 run) and http://pgsql.privatepaste.com/930bb51374 (9.2.1 run).

You are using prepared statements, this makes me think that this
regression might be due to support for parameter specific plans for
prepared statements. [1] Can you run the test on both versions without
prepared statements and see if the regressions remains.

I compared the profile results, I'll reproduce the results here incase
they ring any other bells for someone. Here are top 20 functions that
take more time under 9.2:

Function Diff v9.2% v9.1%
postgres.copyObject 3.48 1.2436 0.3569
postgres.check_stack_depth 1.92 0.7244 0.3774
postgres.eval_const_expressions_mutator 1.87 0.3473 0.1853
jbd./jbd 1.82 0.4127 0.2271
libc-2.14.1.so._int_malloc 1.75 1.4938 0.8540
libc-2.14.1.so.__strlen_sse42 1.72 0.7098 0.4124
vmlinux-2.6.32.59-0.7-default.copy_user_generic_string 1.70 0.5130 0.3017
postgres.MemoryContextCreate 1.68 0.3206 0.1914
postgres.MemoryContextAllocZeroAligned 1.64 1.5443 0.9443
libc-2.14.1.so._int_free 1.60 0.7182 0.4476
postgres.expression_tree_walker 1.60 0.8350 0.5235
postgres.XLogInsert 1.58 2.7251 1.7210
ext3./ext3 1.55 0.2065 0.1335
libc-2.14.1.so.__strcpy_ssse3 1.50 0.3061 0.2046
postgres.expression_tree_mutator 1.41 0.3461 0.2447
libc-2.14.1.so.__memcpy_ssse3_back 1.40 1.2379 0.8830
postgres.AllocSetAlloc 1.39 4.6567 3.3467
postgres.LockAcquireExtended 1.39 0.2799 0.2015
postgres.MemoryContextAlloc 1.38 1.0151 0.7373
postgres.AllocSetDelete 1.33 0.2130 0.1600

And top 10 functions present under 9.2 but not present with 9.1:
Function
postgres._copyList.isra.15 0.341
postgres._SPI_execute_plan.isra.4 0.224
postgres.grouping_planner 0.220
postgres.IndexOnlyNext 0.213
postgres.GetCachedPlan 0.189
postgres.MemoryContextStrdup 0.171
postgres.list_copy 0.165
postgres.index_getnext_tid 0.155
postgres.MemoryContextSetParent 0.128
postgres.cost_qual_eval_walker 0.127

I have no idea why is XLogInsert taking so much longer on 9.2.

[1] http://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=e6faf910

Ants Aasma
--
Cybertec Schönig & Schönig GmbH
Gröhrmühlgasse 26
A-2700 Wiener Neustadt
Web: http://www.postgresql-support.de