Re: CentOS upgrade to 6.8 resulting in high load for PostgreSQL 9.4.6 server

"Hazuka (CTR), Brad" <brad.hazuka.ctr@xxxxxxxx> · Thu, 9 Jun 2016 15:04:47 -0500

I verified the HugePages and IOScheduler with the SA settings and they are the same.

Bradley J. Hazuka
Database Administrator
Innovate!, Inc.
Contractor to the U.S. Geological Survey (USGS)
Earth Resources Observation and Science (EROS) Center
47914 252nd Street
Sioux Falls, SD 57198
Tel: (605) 594-2667
Fax: (605) 594-2828
E-mail: brad.hazuka.ctr@xxxxxxxx <<<NEW E-MAIL ADDRESS

NOTICE: This email may contain confidential, proprietary, or competition sensitive bid or proposal procurement information. Unauthorized disclosure of this information may carry criminal penalties as set forth in the Procurement Integrity Act, 41 U.S.C. 423, as amended. Further, the unauthorized disclosure of certain commercial information by civil servants may result in fines or imprisonment under the Trade Secrets Act (18 U.S.C. 1905). If you have received this information in error, please delete it, including all copies, and notify the sender of the error immediately. 

On Thu, Jun 9, 2016 at 12:38 PM, Scott Mead <scottm@xxxxxxxxxxx> wrote:

On Thu, Jun 9, 2016 at 8:27 AM, Hazuka (CTR), Brad <brad.hazuka.ctr@xxxxxxxx> wrote:
I am hoping someone can help me out. I have a production server running CentOS 6.8 and PostgreSQL community edition 9.4.6.  The application hitting the database is highly concurrent. When the database was running on the latest 6.7 CentOS OS I had no problems, we were seeing great throughput and my bottleneck was IO as I expected it to be. From the sar data my CPU overhead was ~10% and my disk usage was 99%. Memory was not using swap. After the SA upgraded the machine to 6.8 the profile changed. Now I am seeing a high CPU bound load on the system caused by postgres. disk usage is at ~50% and our application throughput has dropped dynamically. I was able to pull some vmstat and perf metrics which can be seen below. Any insight someone can offer would be great to return the system performance. Unfortunately rolling back to 6.7 is not an option because of security policy.

Any chance that you had tuned the IOScheduler or HugePages and now you've lost those settings with an OS upgrade?

--Scott 

OS Info:

CentOS 6.8 Linux 2.6.32-642.1.1.el6.x86_64 #1 SMP Tue May 31 21:57:07 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

DB Info:

PostgreSQL 9.4.6

HW Info:

Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                16
On-line CPU(s) list:   0-15
Thread(s) per core:    2
Core(s) per socket:    4
Socket(s):             2
NUMA node(s):          2
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 44
Model name:            Intel(R) Xeon(R) CPU           X5687  @ 3.60GHz
Stepping:              2
CPU MHz:               3600.000
BogoMIPS:              7199.83
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              12288K
NUMA node0 CPU(s):     0,2,4,6,8,10,12,14
NUMA node1 CPU(s):     1,3,5,7,9,11,13,15

             total       used       free     shared    buffers     cached
Mem:      99052244   98472232     580012    8620496      47452   95264812
-/+ buffers/cache:    3159968   95892276
Swap:      4194300      11060    4183240

Top information
=================
top - 10:22:07 up 1 day,  1:13,  3 users,  load average: 15.64, 17.16, 17.39
Tasks: 546 total,  18 running, 528 sleeping,   0 stopped,   0 zombie
Cpu(s): 91.7%us,  3.8%sy,  0.0%ni,  3.8%id,  0.6%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:  99052244k total, 98744272k used,   307972k free,    47208k buffers
Swap:  4194300k total,    11064k used,  4183236k free, 95472720k cached

  PID  PPID    TIME+  %CPU %MEM  PR  NI S  VIRT SWAP  RES  UID COMMAND                                                                                                                                                                        
21968  8814 995:06.03 86.6  1.1  20   0 R 8640m  272 1.1g  600 postgres: SELECT                                                                                                                            
21972  8814 994:41.35 85.9  1.1  20   0 R 8640m  272 1.1g  600 postgres: SELECT                                                                                                                            
20923  8814 994:53.56 85.0  1.8  20   0 R 8641m  296 1.7g  600 postgres: SELECT                                                                                                                            
 7607  8814  16:39.25 80.1  8.0  20   0 R 8631m  268 7.6g  600 postgres: SELECT                                                                                                                            
21058  8814 956:59.78 79.1  3.1  20   0 R 8641m  296 2.9g  600 postgres: SELECT                                                                                                                            
 7667  8814  17:22.53 77.1  0.9  20   0 R 8621m  288 855m  600 postgres: SELECT                                                                                                                            
20899  8814 995:15.39 76.5  4.4  20   0 R 8641m  292 4.2g  600 postgres: SELECT                                                                                                                            
 7381  8814  28:59.06 75.8  0.9  20   0 R 8621m  288 865m  600 postgres: SELECT                                                                                                                            
21966  8814 995:13.87 74.5  4.4  20   0 R 8641m  272 4.2g  600 postgres: SELECT                                                                                                                            
 7848  8814  10:22.82 73.2  0.9  20   0 R 8621m  288 840m  600 postgres: SELECT                                                                                                                            
 7806  8814  13:50.43 71.9  0.9  20   0 S 8621m  288 849m  600 postgres: idle                                                                                                                              
 7645  8814  18:08.60 70.9  0.9  20   0 R 8621m  288 852m  600 postgres: SELECT                                                                                                                            
 7619  8814  19:34.71 70.3  0.9  20   0 R 8621m  288 856m  600 postgres: SELECT                                                                                                                            
 7665  8814  17:40.34 69.6  0.9  20   0 S 8621m  288 855m  600 postgres: COMMIT                                                                                                                            
 7843  8814  13:35.96 68.6  0.9  20   0 R 8621m  288 849m  600 postgres: SELECT                                                                                                                            
 7264  8814  31:09.93 67.3  1.5  20   0 R 8633m  268 1.5g  600 postgres: SELECT                                                                                                                            
 7675  8814  15:00.69 66.7  0.9  20   0 R 8621m  288 849m  600 postgres: SELECT                                                                                                                            
 7574  8814  23:30.92 64.4  0.9  20   0 D 8621m  288 857m  600 postgres: SELECT                                                                                                                            
 6977  8814  34:06.98 64.1  2.8  20   0 R 9106m  268 2.7g  600 postgres: SELECT                                                                                                                            
21973  8814   5:39.97  1.3  1.1  20   0 S 8640m  272 1.1g  600 postgres: idle                                                                                                                                                                                        
 9212     1  13:13.12  1.0  0.0  20   0 S 44120  540 1140  600 /opt/pgbouncer/bin/pgbouncer -d /etc/pgbouncer/pgbouncer.ini                                                                                                                   

VMStat Information
================= procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
20  0  11072 749604  47000 95163200    0    0    75   230   18   26 82  0 15  2  0	
15  0  11072 723244  47016 95176920    0    0    38   887 86610 33495 84  6 10  0  0	
21  0  11072 708256  47024 95190704    0    0    28  3856 86047 23593 85  5  9  1  0	
20  0  11072 702536  47040 95196160    0    0     1  3890 82383 10971 89  4  6  1  0	
19  1  11072 696464  47048 95201504    0    0    17   522 84030 11061 90  4  5  0  0	
21  0  11072 688740  47064 95206920    0    0    31  2238 84497 27806 87  5  8  0  0

perf top info
=================
Overhead  Shared Object          Symbol 
  12.83%  postgres               [.] heap_hot_search_buffer
   6.82%  postgres               [.] ExecScanHashBucket 
   6.67%  postgres               [.] slot_deform_tuple
   4.74%  postgres               [.] LWLockAcquire
   3.81%  postgres               [.] pg_next_dst_boundary 
   3.43%  postgres               [.] texteq  
   2.97%  postgres               [.] _bt_checkkeys 
   2.79%  postgres               [.] j2date 
   2.76%  postgres               [.] LWLockRelease  
   2.69%  postgres               [.] slot_getattr 
   2.66%  postgres               [.] ExecMakeFunctionResultNoSets  
   2.48%  postgres               [.] DetermineTimeZoneOffsetInternal  
   2.25%  postgres               [.] hash_search_with_hash_value 
   2.04%  postgres               [.] tm2timestamp   
   2.04%  postgres               [.] ExecEvalParamExtern  
   1.99%  postgres               [.] dt2time    
   1.67%  postgres               [.] date2j          
   1.54%  postgres               [.] pgstat_end_function_usage    
   1.54%  postgres               [.] FunctionCall2Coll 
   1.52%  postgres               [.] ExecQual         
   1.48%  postgres               [.] timestamp2tm 
   1.43%  postgres               [.] index_fetch_heap  
   1.33%  postgres               [.] index_getnext_tid
   1.22%  postgres               [.] _bt_next   
   1.18%  postgres               [.] ExecEvalNullTest      
   1.15%  postgres               [.] ExecScan      
   1.14%  postgres               [.] btgettuple
   0.99%  postgres               [.] IndexNext 
   0.95%  postgres               [.] timestamp2timestamptz 
   0.94%  postgres               [.] ReleaseAndReadBuffer 
   0.93%  postgres               [.] PinBuffer   
   0.92%  postgres               [.] ExecEvalScalarVarFast    
   0.87%  postgres               [.] ExecStoreTuple   
   0.85%  postgres               [.] LockBuffer          
   0.82%  postgres               [.] heap_page_prune_opt      
   0.78%  libc-2.12.so           [.] __memcmp_sse4_1      
   0.74%  postgres               [.] toast_raw_datum_size   
   0.74%  postgres               [.] pg_detoast_datum_packed     
   0.72%  postgres               [.] ExecEvalRelabelType  
   0.68%  postgres               [.] CheckForSerializableConflictOut   
   0.68%  postgres               [.] HeapTupleSatisfiesMVCC      
   0.57%  postgres               [.] index_getnext      
   0.53%  postgres               [.] ReadBuffer_common    
   0.51%  postgres               [.] pgstat_init_function_usage

IO information
=====================

Tme            DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
08:00:01     dev253-5     59.13      1.89   1564.72     26.50      2.57     43.43      5.90     34.90
08:10:01     dev253-5     58.47      2.19   1555.84     26.65      2.20     37.59      6.05     35.38
08:20:01     dev253-5     60.72     36.18   1598.49     26.92      2.34     38.53      5.92     35.94
08:30:01     dev253-5     60.21     12.68   1562.41     26.16      2.18     36.21      5.97     35.97
08:40:01     dev253-5     60.77    367.49   2624.93     49.25      2.94     48.33      6.09     36.98
08:50:01     dev253-5     63.26    217.68   2644.81     45.25      5.41     85.45      5.82     36.80
09:00:01     dev253-5     60.33      1.41   1612.09     26.75      2.16     35.80      5.93     35.77
09:10:01     dev253-5     58.45      2.96   1586.15     27.19      3.29     56.23      6.12     35.77
09:20:01     dev253-5     89.26   1139.63   3323.51     50.00      3.78     42.35      4.51     40.28
09:30:01     dev253-5     92.84   1320.94   4093.75     58.32      4.21     45.30      4.15     38.57
09:40:01     dev253-5     82.81    998.29   4179.65     62.53      5.09     61.35      4.69     38.85
09:50:01     dev253-5     58.08     22.32   5549.46     95.93      5.22     89.88      6.14     35.67
10:00:01     dev253-5     60.98     50.19  10181.89    167.78      8.34    136.79      6.04     36.81
10:10:01     dev253-5     61.11    256.26   2992.49     53.16      3.12     51.10      5.61     34.29
Average:     dev253-5     83.02   4394.40   2225.11     79.73      3.18     38.35      4.69     38.93

Bradley J. Hazuka
Database Administrator
Innovate!, Inc. 

-- 
--
Scott Mead
Sr. Architect
OpenSCG
http://openscg.com