Thread: dbt2 performance regresses from 9.1.6 to 9.2.1

dbt2 performance regresses from 9.1.6 to 9.2.1

From
Dong Ye
Date:
Hi there,

I work for VMware with our Postgres performance team. We recently came across a dbt2 performance regression from 9.1.6
to9.2.1. We have done some profiling and don't see anything obvious. Would like to get some suggestions from the
communitywhere 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
jumpedout 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



Re: dbt2 performance regresses from 9.1.6 to 9.2.1

From
Ants Aasma
Date:
On Thu, Nov 1, 2012 at 12:51 AM, Dong Ye <yed@vmware.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
nothingjumped 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


Re: dbt2 performance regresses from 9.1.6 to 9.2.1

From
Dong Ye
Date:
> 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


Re: dbt2 performance regresses from 9.1.6 to 9.2.1

From
Claudio Freire
Date:
On Sun, Nov 4, 2012 at 7:23 PM, Dong Ye <yed@vmware.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).


Re: dbt2 performance regresses from 9.1.6 to 9.2.1

From
Heikki Linnakangas
Date:
On 05.11.2012 16:32, Claudio Freire wrote:
> On Sun, Nov 4, 2012 at 7:23 PM, Dong Ye<yed@vmware.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