This guide shows how to fix hung_task_timeout_secs and blocked for more than 120 seconds problem in Linux.
A panic may occur as a result of a hardware failure or a software bug in the operating system.
My server became unresponsive today (around 15:38hrs)
I’ve collected following logs that shows Memory and CPU usage and narrowed down /var/log/messages
.
After doing a hard reboot, it came back online but I was unable to access it via VNC
or SSH
.
VNC
connection showed an error (many errors but all contained /proc/sys/kernel/hung_task_timeout_secs
“)
INFO: task jbd2/vda3-8:250 blocked for more than 120 seconds. Not tainted 2.6.32-431.11.2.el6.x86_64 #1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Following log shows server memory usage
someuser@servercore [/var/log]# sar -r15:00:01 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit15:20:01 476604 1396772 74.56 110140 707116 1201652 30.6415:30:02 526240 1347136 71.91 110412 710536 1165148 29.7115:55:53 LINUX RESTART16:00:01 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit16:10:01 517168 1356208 72.39 136040 588964 1196724 30.5216:20:01 510580 1362796 72.75 137488 596560 1191664 30.39
As you can see, it’s not that high and I had plenty of free Memory.
Following log shows CPU usage.
someuser@servercore [/var/log]# sar -u15:00:01 CPU %user %nice %system %iowait %steal %idle15:20:01 all 6.01 0.04 1.74 1.59 0.14 90.4815:30:02 all 4.97 0.04 1.54 7.87 0.15 85.44Average: all 7.20 0.06 2.19 2.69 0.26 87.6015:55:53 LINUX RESTART16:00:01 CPU %user %nice %system %iowait %steal %idle16:10:01 all 9.13 0.04 2.78 6.98 0.31 80.7616:20:01 all 4.21 0.04 1.39 3.49 0.15 90.73
Again, CPU wasn’t at 100%. This is now getting annoying that I can’t explain why I am getting into s**tstorm for nothing.
Let’s check //var/log/messages
to find all the error logs related this this kernel panic
Now I am getting somewhere …
someuser@servercore [/var/log]# grep 'Aug 22 15' messages | grep -v Firewall | grep -v blackmore | grep -v operational | grep -v ec2Aug 22 15:38:05 servercore kernel: INFO: task jbd2/vda3-8:250 blocked for more than 120 seconds.Aug 22 15:38:05 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:05 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:05 servercore kernel: jbd2/vda3-8 D 0000000000000000 0 250 2 0x00000000Aug 22 15:38:06 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:06 servercore kernel: Call Trace:Aug 22 15:38:06 servercore kernel: INFO: task rs:main Q:Reg:1035 blocked for more than 120 seconds.Aug 22 15:38:06 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:06 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:06 servercore kernel: rs:main Q:Reg D 0000000000000000 0 1035 1 0x00000080Aug 22 15:38:06 servercore kernel: Call Trace:Aug 22 15:38:06 servercore kernel: INFO: task queueprocd - qu:1793 blocked for more than 120 seconds.Aug 22 15:38:06 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:06 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:06 servercore kernel: queueprocd - D 0000000000000000 0 1793 1 0x00000080Aug 22 15:38:06 servercore kernel: Call Trace:Aug 22 15:38:06 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:06 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:06 servercore kernel: Call Trace:Aug 22 15:38:06 servercore kernel: INFO: task httpd:30439 blocked for more than 120 seconds.Aug 22 15:38:06 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:07 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:07 servercore kernel: httpd D 0000000000000000 0 30439 2223 0x00000080Aug 22 15:38:07 servercore kernel: Call Trace:Aug 22 15:38:11 servercore kernel: INFO: task httpd:30482 blocked for more than 120 seconds.Aug 22 15:38:11 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:38:11 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:38:11 servercore kernel: httpd D 0000000000000000 0 30482 2223 0x00000080Aug 22 15:38:11 servercore kernel: Call Trace:Aug 22 15:39:54 servercore kernel: INFO: task jbd2/vda3-8:250 blocked for more than 120 seconds.Aug 22 15:39:54 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:39:54 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:39:54 servercore kernel: jbd2/vda3-8 D 0000000000000000 0 250 2 0x00000000Aug 22 15:39:54 servercore kernel: Call Trace:Aug 22 15:39:54 servercore kernel: INFO: task flush-253:0:263 blocked for more than 120 seconds.Aug 22 15:39:54 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:39:54 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:39:54 servercore kernel: flush-253:0 D 0000000000000000 0 263 2 0x00000000Aug 22 15:39:54 servercore kernel: Call Trace:Aug 22 15:39:56 servercore kernel: INFO: task rs:main Q:Reg:1035 blocked for more than 120 seconds.Aug 22 15:39:56 servercore kernel: Not tainted 2.6.32-431.11.2.el6.x86_64 #1Aug 22 15:39:56 servercore kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.Aug 22 15:39:56 servercore kernel: rs:main Q:Reg D 0000000000000000 0 1035 1 0x00000080Aug 22 15:39:56 servercore kernel: Call Trace:Aug 22 15:42:11 servercore kernel: Clocksource tsc unstable (delta = -8589964877 ns)15:55:53 LINUX RESTART
As you can see all the errors contained “echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
” and “blocked for more than 120 seconds
” somewhere.
Now let’s fix this problem once and for all..
By default Linux uses up to 40% of the available memory for file system caching. After this mark has been reached the file system flushes all outstanding data to disk causing all following IOs going synchronous. For flushing out this data to disk this there is a time limit of 120 seconds by default. In the case here the IO subsystem is not fast enough to flush the data withing 120 seconds. As IO subsystem responds slowly and more requests are served, System Memory gets filled up resulting in the above error, thus serving HTTP requests.
I tested this theory with the following:
Change vm.dirty_ratio
and vm.dirty_backgroud_ratio
someuser@servercore [/home/someuser]$ sudo sysctl -w vm.dirty_ratio=10someuser@servercore [/home/someuser]$ sudo sysctl -w vm.dirty_background_ratio=5
Commit Change
someuser@servercore [/home/someuser]# sudo sysctl -p
When the server seemed more stable and no Kernel/Swap/Memory Panic for a week, I edited /etc/sysctl.conf
file to make these permanent after reboot.
someuser@servercore [/home/someuser]$ sudo vi /etc/sysctl.conf
ADD 2 lines at the bottom
vm.dirty_background_ratio = 5vm.dirty_ratio = 10
Save and exit.
someuser@servercore [/home/someuser]$ sudo reboot
That’s it. I never had this issue .. ever again..
Hope someone find this info useful.
Ronny Egners Blog – INFO: task blocked for more than 120 seconds.
联系客服