Обсуждение: 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 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
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
> 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@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).
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