Обсуждение: 9.3 regression with dbt2

<div class="WordSection1"><p class="MsoPlainText">Hi,<p class="MsoPlainText"> <p class="MsoPlainText">We recently
observed~15% performance regression with dbt2 from PG 9.3.<p class="MsoPlainText">We narrowed down on testing master
between9.2 cut and 9.3 cut.<p class="MsoPlainText">It seems that 0ac5ad5134f2769ccbaefec73844f8504c4d6182 is the
culpritcommit.<p class="MsoPlainText">We did several runs and perf profiling comparing it against its parent
(f925c79b9f36c54b67053ade5ad225a75b8dc803).<pclass="MsoPlainText">Also tested a 12/16 commit on the master
(3b97e6823b949624afdc3ce4c92b29a80429715f)once, it performed similarly as 0ac..<p class="MsoPlainText"> <p
class="MsoPlainText">Regards,<pclass="MsoPlainText">Dong<p class="MsoPlainText"> <p class="MsoPlainText"> <p
class="MsoPlainText">Results:<pclass="MsoPlainText">f92: 53k-56k'ish notpm<p class="MsoPlainText">0ac: 47k-48k'ish
notpm<pclass="MsoPlainText"> <p class="MsoPlainText">Server SUT:<p class="MsoPlainText">HP ML350 G6<p
class="MsoPlainText">Two Xeon E5520 (4c/p, 8 cores total, hyper-threading disabled)<p class="MsoPlainText">12GB DRAM<p
class="MsoPlainText">HPP410i RAID controller (256MB battery-backed cache)<p class="MsoPlainText">- three 10k-rpm SAS:
/<pclass="MsoPlainText">- three 10k-rpm SAS: /pgdata<p class="MsoPlainText">- one 15k-rpm SAS: /pgxlog<p
class="MsoPlainText">-ext4 (rw,relatime,data=ordered) on all mounts. <p class="MsoPlainText"> <p
class="MsoPlainText">Fedora19 (3.11.10-200.fc19.x86_64)<p class="MsoPlainText"> <p
class="MsoPlainText">max_connections=100<pclass="MsoPlainText">shared_buffers=8192MB<p
class="MsoPlainText">effective_cache_size=10GB<pclass="MsoPlainText">temp_buffers=8186kB<p
class="MsoPlainText">work_mem=4093kB<pclass="MsoPlainText">maintenance_work_mem=399MB<p
class="MsoPlainText">wal_buffers=-1<pclass="MsoPlainText">checkpoint_segments=300<p
class="MsoPlainText">checkpoint_completion_target=0.9<pclass="MsoPlainText">logging_collector=on<p
class="MsoPlainText">log_timezone=UTC<pclass="MsoPlainText">datestyle='iso, mdy'<p class="MsoPlainText">lc_messages=C<p
class="MsoPlainText">lc_monetary=C<pclass="MsoPlainText">lc_numeric=C<p class="MsoPlainText">lc_time=C<p
class="MsoPlainText">default_text_search_config='pg_catalog.english'<pclass="MsoPlainText">listen_addresses='*'<p
class="MsoPlainText">log_destination=csvlog<pclass="MsoPlainText">log_directory=pg_log<p
class="MsoPlainText">log_filename='pg-%a'<pclass="MsoPlainText">log_rotation_age=1440<p
class="MsoPlainText">log_truncate_on_rotation=on<pclass="MsoPlainText"> <p class="MsoPlainText">Client and workload:<p
class="MsoPlainText">Dell390. Two core. Direct connect with the Server SUT.<p class="MsoPlainText">dbt2 (ToT)<p
class="MsoPlainText">40warehouse<p class="MsoPlainText">8 terminals, 8 connections<p class="MsoPlainText">zero
think/keytime<p class="MsoPlainText">12-min run<p class="MsoPlainText"> <p class="MsoPlainText">Flat perf profiles of
twosuch runs look like:<p class="MsoPlainText">f92:<p class="MsoPlainText">Samples: 608K of event 'cycles', Event count
(approx.):6679607097416                                                 <p class="MsoPlainText">+   4.04%      
postgres postgres                  [.] heap_hot_search_buffer                                        <p
class="MsoPlainText">+  3.63%       postgres  postgres                  [.]
AllocSetAlloc                                                <p class="MsoPlainText">+   3.37%       postgres 
postgres                 [.] hash_search_with_hash_value                                   <p class="MsoPlainText">+  
2.85%      postgres  postgres                  [.] _bt_compare                                                   <p
class="MsoPlainText">+  2.67%       postgres  postgres                  [.]
SearchCatCache                                               <p class="MsoPlainText">+   2.46%       postgres 
postgres                 [.] LWLockAcquire                                                 <p class="MsoPlainText">+  
2.16%      postgres  postgres                  [.] XLogInsert                                                    <p
class="MsoPlainText">+  2.08%       postgres  postgres                  [.]
PinBuffer                                                    <p class="MsoPlainText">+   1.32%       postgres 
postgres                 [.] ExecInitExpr                                                  <p class="MsoPlainText">+  
1.31%      postgres  libc-2.17.so              [.] _int_malloc                                                   <p
class="MsoPlainText">+  1.29%        swapper  [kernel.kallsyms]         [k]
intel_idle                                                   <p class="MsoPlainText">+   1.23%       postgres 
postgres                 [.] MemoryContextAllocZeroAligned                                 <p class="MsoPlainText">+  
1.13%      postgres  postgres                  [.] heap_page_prune_opt                                           <p
class="MsoPlainText">+  1.06%       postgres  libc-2.17.so              [.]
__memcpy_ssse3_back                                          <p class="MsoPlainText">+   1.02%       postgres 
postgres                 [.] LWLockRelease                                                 <p class="MsoPlainText">+  
0.94%      postgres  postgres                  [.] copyObject                                                    <p
class="MsoPlainText">+  0.89%       postgres  postgres                  [.]
fmgr_info_cxt_security                                       <p class="MsoPlainText">+   0.82%       postgres 
postgres                 [.] _bt_checkkeys                                                 <p class="MsoPlainText">+  
0.81%      postgres  postgres                  [.] hash_any                                                      <p
class="MsoPlainText">+  0.73%       postgres  postgres                  [.]
FunctionCall2Coll                                            <p class="MsoPlainText">+   0.69%       postgres 
libc-2.17.so             [.] __strncpy_sse2_unaligned                                      <p class="MsoPlainText">+  
0.67%      postgres  postgres                  [.] HeapTupleSatisfiesMVCC                                        <p
class="MsoPlainText">+  0.66%       postgres  postgres                  [.]
MemoryContextAlloc                                           <p class="MsoPlainText">+   0.65%       postgres 
postgres                 [.] expression_tree_walker                                        <p class="MsoPlainText">+  
0.59%      postgres  postgres                  [.] check_stack_depth                                             <p
class="MsoPlainText">+  0.57%       postgres  libc-2.17.so              [.]
__printf_fp                                                  <p class="MsoPlainText">+   0.56%       postgres 
libc-2.17.so             [.] _int_free                                                     <p class="MsoPlainText">+  
0.52%      postgres  postgres                  [.] base_yyparse<p class="MsoPlainText"> <p class="MsoPlainText">0ac:<p
class="MsoPlainText">Samples:706K of event 'cycles', Event count (approx.):
6690377376522                                                <p class="MsoPlainText">+   3.82%         postgres 
postgres                 [.] GetMultiXactIdMembers                                       <p class="MsoPlainText">+  
3.43%        postgres  postgres                  [.] LWLockAcquire                                               <p
class="MsoPlainText">+  3.31%         postgres  postgres                  [.]
hash_search_with_hash_value                                <p class="MsoPlainText">+   3.09%         postgres 
postgres                 [.] heap_hot_search_buffer                                      <p class="MsoPlainText">+  
3.00%        postgres  postgres                  [.] AllocSetAlloc                                               <p
class="MsoPlainText">+  2.56%         postgres  postgres                  [.]
_bt_compare                                                <p class="MsoPlainText">+   2.19%         postgres 
postgres                 [.] PinBuffer                                                   <p class="MsoPlainText">+  
2.13%        postgres  postgres                  [.] SearchCatCache                                              <p
class="MsoPlainText">+  1.99%         postgres  postgres                  [.] XLogInsert   
                                              <pclass="MsoPlainText">+   1.53%         postgres 
postgres                 [.] LWLockRelease                                               <p class="MsoPlainText">+  
1.32%        postgres  postgres                  [.] HeapTupleSatisfiesMVCC                                      <p
class="MsoPlainText">+  1.31%          swapper  [kernel.kallsyms]         [k]
intel_idle                                                 <p class="MsoPlainText">+   1.25%         postgres 
postgres                 [.] ExecInitExpr                                                <p class="MsoPlainText">+  
1.21%        postgres  postgres                  [.] heap_page_prune_opt<p class="MsoPlainText">+   1.03%        
postgres libc-2.17.so              [.] _int_malloc<p class="MsoPlainText">+   0.99%         postgres 
postgres                 [.] MemoryContextAllocZeroAligned<p class="MsoPlainText">+   0.97%         postgres 
libc-2.17.so             [.] __memcpy_ssse3_back<p class="MsoPlainText">+   0.89%         postgres 
postgres                 [.] heapgetpage<p class="MsoPlainText">+   0.76%         postgres  postgres                 
[.]hash_any<p class="MsoPlainText">+   0.69%         postgres  postgres                  [.] fmgr_info_cxt_security<p
class="MsoPlainText">+  0.69%         postgres  postgres                  [.] _bt_checkkeys<p class="MsoPlainText">+  
0.65%        postgres  postgres                  [.] copyObject<p class="MsoPlainText">+   0.63%         postgres 
postgres                 [.] FunctionCall2Coll<p class="MsoPlainText">+   0.58%         postgres 
postgres                 [.] MemoryContextAlloc<p class="MsoPlainText">+   0.56%         postgres 
libc-2.17.so             [.] __strncpy_sse2_unaligned<p class="MsoPlainText">+   0.53%         postgres 
postgres                 [.] XidInMVCCSnapshot<p class="MsoPlainText">+   0.52%         postgres 
[kernel.kallsyms]        [k] copy_user_generic_string<p class="MsoPlainText">+   0.51%         postgres 
libc-2.17.so             [.] __printf_fp<p class="MsoPlainText">+   0.50%         postgres  libc-2.17.so             
[.]vfprintf<p class="MsoPlainText"> <p class="MsoPlainText"> <p class="MsoPlainText">P.S.<p class="MsoPlainText">The
regressionwas found when testing vPostgres performance.<p class="MsoPlainText">During the narrow-down, we found the
commit005f583ba4e6d4d19b62959ef8e70a3da4d188a5 (on REL9_2_STABLE) improves performance (versus its parent commit) by
5-10%.Perhaps serve an extra data point for the patch.<p class="MsoPlainText"> <p class="MsoNormal"> </div> 

Hello,

On 2013-12-18 10:24:56 -0800, Dong Ye wrote:
> It seems that 0ac5ad5134f2769ccbaefec73844f8504c4d6182 is the culprit
> commit.

How long does a run take to verify the problem? Could you retry with the
patch attached to
http://www.postgresql.org/message-id/20131201114514.GG18793@alap2.anarazel.de
? Based on the theory that it creates many superflous multixacts.

> Flat perf profiles of two such runs look like:

Those aren't really flat profiles tho ;)

> 0ac:
> 
> Samples: 706K of event 'cycles', Event count (approx.): 6690377376522
> 
> 
> +   3.82%         postgres  postgres                  [.]
> GetMultiXactIdMembers                                       

Could you expland that one some levels, so we see the callers?

Greetings,

Andres Freund

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services

Hi,

On 2013-12-18 14:59:45 -0500, Dong Ye wrote:
> ~20 minutes each run with binary.
> Try your patch now..
> You are right I used -g in perf record. But what I reported was flat (meant
> as a start).
> 
> Expand GetMultiXactIdMembers:
> 
>      3.82%         postgres  postgres                  [.]
> GetMultiXactIdMembers

That looks like a postgres compiled without
-fno-omit-frame-pointer. Without that hierarchical profiles are
meaningless. Very new perfs can also do it using dwarf, but it's unusabl
slow...

Greetings,

Andres Freund

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services

<div dir="ltr">HI<br /><div class="gmail_extra"><br /><div class="gmail_quote">On Wed, Dec 18, 2013 at 3:03 PM, Andres
Freund<span dir="ltr"><<a href="mailto:andres@2ndquadrant.com" target="_blank">andres@2ndquadrant.com</a>></span>
wrote:<blockquoteclass="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> That looks
likea postgres compiled without<br /> -fno-omit-frame-pointer. Without that hierarchical profiles are<br />
meaningless.Very new perfs can also do it using dwarf, but it's unusabl<br /> slow...<br /><div class="HOEnZb"><div
class="h5"><br/></div></div></blockquote><div style="style">Let me complete current test without the flag (to serve as
acheckpoint as well). I will do a run with the flag after.</div><div style="style"><br /></div><div
style="style">Thanks,</div><divstyle="style">Dong</div></div></div></div>