Re: dbt2 performance regresses from 9.1.6 to 9.2.1

Hi there,

I work for VMware with our Postgres performance team. We recently came across a dbt2 performance regression from 9.1.6 to 9.2.1. We have done some profiling and don't see anything obvious. Would like to get some suggestions from the community where to investigate further.

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).

Specs:

HP ML360 G6:
2x Xeon E5520 (4-core/processor, Hyperthreading disabled)
12GB DRAM
HP P410i RAID controller (256MB battery-backed cache)
- One 10k-rpm SAS: to mount /
- One SSD: to mount pgdata and wal

SUSE Linux Enterprise Server 11 SP1 64-bit (kernel version: 2.6.32.59-0.7-default)

postgresql.conf:
max_connections = 100
shared_buffers = 5600MB
temp_buffers = 8193kB
work_mem = 4096kB
maintenance_work_mem = 400MB
wal_buffers = -1
checkpoint_segments = 300
logging_collector = on
datestyle = 'iso, mdy'
lc_messages = 'C'
lc_monetary = 'C'
lc_numeric = 'C'
lc_time = 'C'
default_text_search_config = 'pg_catalog.english'
log_destination = 'csvlog'
log_directory = 'pg_log'
log_filename = 'postgresql-%a'
log_rotation_age = 1440
log_truncate_on_rotation = on

dbt2-0.40 was used:
40 warehouse
20 db connections
use no thinktime
use prepared statement
buffer warmup before measurement run (warmup is done through disabling sequential scan and count(*) all tables and indexes).
measurement run lasts 20 minutes

We used postgresql91-9.1.6 and postgresql92-9.2.1 openSUSE builds:
http://download.opensuse.org/repositories/server:/database:/postgresql/openSUSE_12.1/x86_64/

Thanks,
Dong

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

> 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.

Without prepare statement, we got 48837.33 avg notpm with 9.1.6 and 43264.54 avg notpm with 9.2.1.
notps over time shows the slowdown of 9.2.1 is evident during the entire course of the run.
Their profiles are posted on http://pgsql.privatepaste.com/b770f72967 (9.1.6) and http://pgsql.privatepaste.com/6fa8b7f174 (9.2.1).

Thanks,
Dong

On Sun, Nov 4, 2012 at 7:23 PM, Dong Ye <yed(at)vmware(dot)com> wrote:
>> 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.
>
> Without prepare statement, we got 48837.33 avg notpm with 9.1.6 and 43264.54 avg notpm with 9.2.1.
> notps over time shows the slowdown of 9.2.1 is evident during the entire course of the run.
> Their profiles are posted on http://pgsql.privatepaste.com/b770f72967 (9.1.6) and http://pgsql.privatepaste.com/6fa8b7f174 (9.2.1).

You know... it does look as if 9.2.1 is generating a lot more pressure
into the memory allocator (AllocSetAlloc notably higher).

On 05.11.2012 16:32, Claudio Freire wrote:
> On Sun, Nov 4, 2012 at 7:23 PM, Dong Ye<yed(at)vmware(dot)com> wrote:
>>> 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.
>>
>> Without prepare statement, we got 48837.33 avg notpm with 9.1.6 and 43264.54 avg notpm with 9.2.1.
>> notps over time shows the slowdown of 9.2.1 is evident during the entire course of the run.
>> Their profiles are posted on http://pgsql.privatepaste.com/b770f72967 (9.1.6) and http://pgsql.privatepaste.com/6fa8b7f174 (9.2.1).
>
> You know... it does look as if 9.2.1 is generating a lot more pressure
> into the memory allocator (AllocSetAlloc notably higher).

Did you check the access plans of the queries? 9.2 planner might choose
a slightly worse plan. Or perhaps index-only scans are hurting
performance with the DBT-2 queries.

- Heikki