0

We have an web app that runs in AWS Elastic Beanstalk and uses Java as backend. Intermittently, one app server behind the load balancer crashes due to the CPU being used 100%. After some analysis, I have reasons to believe the underlying OS might play a role in this problem.

Here's a snippet from the /var/log/messages file with the point where the kernel catches the error:

Jan  3 22:50:11 ip-10-220-46-44 kernel: [22649903.665305] ------------[ cut here ]------------
Jan  3 22:50:11 ip-10-220-46-44 kernel: [22649903.676120] WARNING: CPU: 0 PID: 12578 at fs/dcache.c:361 d_shrink_del+0x71/0x80()
Jan  3 22:50:11 ip-10-220-46-44 kernel: [22649903.680845] Modules linked in: ipv6 binfmt_misc evbug evdev psmouse i2c_piix4 ixgbevf i2c_core button ext4 crc16 jbd2 mbcache dm_mirror dm_region_hash dm_log dm_mod
Jan  3 22:50:11 ip-10-220-46-44 kernel: [22649903.691804] CPU: 0 PID: 12578 Comm: lsof Not tainted 3.14.48-33.39.amzn1.x86_64 #1
Jan  3 22:50:11 ip-10-220-46-44 kernel: [22649903.696742] Hardware name: Xen HVM domU, BIOS 4.2.amazon 08/24/2006
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.700879]  0000000000000009 ffff880037dc1c90 ffffffff81487535 0000000000000000
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.706058]  ffff880037dc1cc8 ffffffff8105d39d ffff8800147b33c0 ffff880037dc1d48
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.711346]  ffff8800147b3418 ffff8800147b33c0 ffff8800147b33c0 ffff880037dc1cd8
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.716450] Call Trace:
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.718151]  [<ffffffff81487535>] dump_stack+0x45/0x56
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.721634]  [<ffffffff8105d39d>] warn_slowpath_common+0x7d/0xa0
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.725658]  [<ffffffff8105d47a>] warn_slowpath_null+0x1a/0x20
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.729562]  [<ffffffff811bc601>] d_shrink_del+0x71/0x80
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.732957]  [<ffffffff811bda24>] shrink_dentry_list+0x64/0xe0
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.736748]  [<ffffffff811be868>] shrink_dcache_parent+0x28/0x70
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.740689]  [<ffffffff8120fdf6>] proc_flush_task+0xa6/0x190
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.744318]  [<ffffffff8105e190>] release_task+0x30/0x450
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.748305]  [<ffffffff810946e1>] ? thread_group_cputime_adjusted+0x41/0x50
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.752971]  [<ffffffff8105ee7b>] wait_consider_task+0x8cb/0xb00
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.757236]  [<ffffffff8105f1b0>] do_wait+0x100/0x240
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.760681]  [<ffffffff810602e4>] SyS_wait4+0x64/0xe0
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.764026]  [<ffffffff8105def0>] ? task_stopped_code+0x60/0x60
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.768138]  [<ffffffff81496fc9>] system_call_fastpath+0x16/0x1b
Jan  3 22:50:12 ip-10-220-46-44 kernel: [22649903.772147] ---[ end trace e3b4a7d896ae3cba ]---
Jan  3 22:51:11 ip-10-220-46-44 kernel: [22649962.676054] INFO: rcu_sched self-detected stall on CPU
Jan  3 22:51:11 ip-10-220-46-44 kernel: [22649962.676054]       0: (14747 ticks this GP) idle=f7d/140000000000001/0 softirq=400397332/400397344
Jan  3 22:51:11 ip-10-220-46-44 kernel: [22649962.676054]        (t=14750 jiffies g=44792585 c=44792584 q=188767)

Some hours later the OOM-killer steps in:

Jan  4 00:30:55 ip-10-220-46-44 kernel: [22655946.486183] Out of memory: Kill process 2776 (java) score 654 or sacrifice child

As you can see, the OOM-killer selects the Java process and kills it. At that moment it consumes aprox. 1.5 Gb of RAM. This is below the 2Gb of heap allocated via the -Xmx flag. Shortly after that, our web app restarts several times until the CPU reaches 100%. The kernel version of the OS is 3.14.48-33.39.amzn1.x86_64.

My question is: Based on the above info do you think this problem is caused by the OS? I'm seeing the log line CPU: 0 PID: 12578 Comm: lsof Not tainted 3.14.48-33.39.amzn1.x86_64 #1 and I think it might be a problem with the lsof utilitary from our current distribution.

Any help will be highly appreciated.

  • I think something related to your filesystem of underneath storage. Check your filesystem events on that day. WARNING: CPU: 0 PID: 12578 at fs/dcache.c:361 d_shrink_del+0x71/0x80() – asktyagi Apr 28 at 13:30

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.