Re: Problems with pg_locks explosion - Mailing list pgsql-performance

From Armand du Plessis
Subject Re: Problems with pg_locks explosion
Date
Msg-id CANf99sX4YREA61NGuSQ=AqS4yFmk4kUJEhGERaNVm0ON9_zFfQ@mail.gmail.com
Whole thread Raw
In response to Re: Problems with pg_locks explosion  (Armand du Plessis <adp@bank.io>)
List pgsql-performance
It's now running as expected, I made a few other tweaks to get it to an operational state again. So just for closure on this dark period below some notes. 

There was two triggers that caused the almost instant backlog of locks. As suspected the one was scheduler that caused endless problems whenever it started migrating tasks. This would lock up the database (and server) for a second or more after which a few thousand locks existed. 

Setting the kernel.sched_migration_cost to 5ms didn't have the desired effect. The scheduler would still stop the world and break down for a few seconds. After much anguish and research (this is a pretty good explanation of the scheduler tunables http://events.linuxfoundation.org/slides/2011/linuxcon/lcna2011_rajan.pdf) I adjusted :

sysctl -w kernel.sched_min_granularity_ns=9000000
sysctl -w kernel.sched_wakeup_granularity_ns=12000000

Since then I haven't had an interruption from migration. 

I also switched hugepage to not be as aggressive, it was also intrusive and my Postgres not configured to use it. "echo madvise > /sys/kernel/mm/transparent_hugepage/defrag"

After these changes things started smoothing out and running like it should. I also found that if you are running on striped EBS volumes you should really try and get them busy to get consistent performance. I checked with Amazon and the usage I see on the individual modules were correct. (Not the RAID figure but the numbers on the individual volumes, they were idling)

Thanks again for all the help and suggestions. 

Armand


On Tue, Apr 2, 2013 at 11:55 AM, Armand du Plessis <adp@bank.io> wrote:
Jumped the gun a bit. the problem still exists like before. But it's definitely on the right track, below is the output from top in the seconds before the cluster locks up. For some reason still insisting on moving tasks around despite bumping the sched_migration_cost cost up to 100ms. 

77 root      RT   0     0    0    0 S 32.3  0.0  13:55.20 [migration/24]                                                                                                                                                                                                     
26512 postgres  20   0 8601m 7388 4992 R 32.3  0.0   0:02.17 postgres: other_user xxxx(52944) INSERT                                                                                                                                                 
   38 root      RT   0     0    0    0 S 31.3  0.0  17:26.15 [migration/11]                                                                                                                                                                                                        65 root      RT   0     0    0    0 S 30.0  0.0  13:18.66 [migration/20]                                                                                                                                                                                                     
   62 root      RT   0     0    0    0 S 29.7  0.0  12:58.81 [migration/19]                                                                                                                                                                                                     
   47 root      RT   0     0    0    0 S 29.0  0.0  18:16.43 [migration/14]                                                                                                                                                                                                     
   29 root      RT   0     0    0    0 S 28.7  0.0  25:21.47 [migration/8]                                                                                                                                                                                                      
   71 root      RT   0     0    0    0 S 28.4  0.0  13:20.31 [migration/22]                                                                                                                                                                                                     
   95 root      RT   0     0    0    0 S 23.8  0.0  13:37.31 [migration/30]                                                                                                                                                                                                     
26518 postgres  20   0 8601m 9684 5228 S 21.2  0.0   0:01.89 postgres: other_user xxxxx(52954) INSERT                                                                                                                                                 
    6 root      RT   0     0    0    0 S 20.5  0.0  39:17.72 [migration/0]                                                                                                                                                                                                      
   41 root      RT   0     0    0    0 S 19.6  0.0  18:21.36 [migration/12]                                                                                                                                                                                                     
   68 root      RT   0     0    0    0 S 19.6  0.0  13:04.62 [migration/21]                                                                                                                                                                                                     
   74 root      RT   0     0    0    0 S 18.9  0.0  13:39.41 [migration/23]                                                                                                                                                                                                     
  305 root      20   0     0    0    0 S 18.3  0.0  11:34.52 [kworker/27:1]                                                                                                                                                                                                     
   44 root      RT   0     0    0    0 S 17.0  0.0  18:30.71 [migration/13]                                                                                                                                                                                                     
   89 root      RT   0     0    0    0 S 16.0  0.0  12:13.42 [migration/28]                                                                                                                                                                                                     
    7 root      RT   0     0    0    0 S 15.3  0.0  21:58.56 [migration/1]                                                                                                                                                                                                      
   35 root      RT   0     0    0    0 S 15.3  0.0  20:02.05 [migration/10]                                                                                                                                                                                                     
   53 root      RT   0     0    0    0 S 14.0  0.0  12:51.46 [migration/16]                                                                                                                                                                                                     
11254 root       0 -20 21848 7532 2788 S 11.7  0.0  22:35.66 atop 1                                                                                                                                                                                                             
   14 root      RT   0     0    0    0 S 10.8  0.0  19:36.56 [migration/3]                                                                                                                                                                                                      
26463 postgres  20   0 8601m 7492 5100 R 10.8  0.0   0:00.33 postgres: other_user xxxxx(32835) INSERT                                                                                                                                                   
   32 root      RT   0     0    0    0 S 10.1  0.0  20:46.18 [migration/9]                                                                                                                                                                                                      
16793 root      20   0     0    0    0 S  6.5  0.0   1:12.72 [kworker/25:0]                                                                                                                                                                                                     
   20 root      RT   0     0    0    0 S  5.5  0.0  18:51.81 [migration/5]                                                                                                                                                                                                      
   48 root      20   0     0    0    0 S  5.5  0.0   3:52.93 [kworker/14:0]   


On Tue, Apr 2, 2013 at 10:16 AM, Armand du Plessis <adp@bank.io> wrote:
Touch wood but I think I found the problem thanks to these pointers. I checked the vm.zone_reclaim_mode and mine was set to 0. However just before the locking starts I can see many of my CPUs flashing red and jump to high percentage sys usage. When I look at top it's the migration kernel tasks that seem to trigger it. 

So it seems it was a bit trigger happy with task migrations, setting the kernel.sched_migration_cost to 5000000 (5ms) seemed to have resolved my woes. I'm yet to see locks climb and it's been running stable for a bit. This post was invaluable in explaining the cause -> http://www.postgresql.org/message-id/50E4AAB1.9040902@optionshouse.com

# Postgres Kernel Tweaks
kernel.sched_migration_cost = 5000000
# kernel.sched_autogroup_enabled = 0

The second recommended setting 'sched_autogroup_enabled' is not available on the kernel I'm running but it doesn't seem to be a problem. 

Again, thanks again for the help. It was seriously appreciated. Long night was long. 

If things change and the problem pops up again I'll update you guys. 

Cheers,

Armand


On Tue, Apr 2, 2013 at 8:43 AM, Mark Kirkwood <mark.kirkwood@catalyst.net.nz> wrote:
Also it is worth checking what your sysctl vm.zone_reclaim_mode is set to - if 1 then override to 0. As Jeff mentioned, this gotcha for larger cpu number machines has been discussed at length on this list - but still traps us now and again!

Cheers

Mark

pgsql-performance by date:

Previous
From: Tom Lane
Date:
Subject: Re: Re: Join between 2 tables always executes a sequential scan on the larger table
Next
From: AI Rumman
Date:
Subject: Planner is getting wrong row count