zfsonlinux/zfs — Issue #557: CPU stall / hung - only able to clear via hard power cycle
Author: machtech
Created: 2012-02-03 14:02:20+00:00
State: open

G'day ZFS on Linux community.

Running ZFS rc6 from PPA on Ubuntu 11.10 x64. Really hoping this can be solved when rc7 is achieved please. Any debugging or assistance we can provide to the devs/project with our 8x SANs will be provided freely.........

When moderate activity placed on file services presented via ZFS, will cause a "rcu_sched_state detected stall on CPU" error to be logged by the kernel, and / or the error logged being "hung_task_timeout_secs". See bottom of this post for relevant logging extracts, where despite all the great work being done by the devs/project - the issue has remained outstanding for the past 2+months. Issue routinely experienced across a diverse range of physical hardware from $2k through to $100k kit.

The net effect is continually escalating high load average will occur, climbing up to as high as 1000 load average value seen if left to run for hours. If entering "reboot" command the server will never actually reboot - the only action to clear the condition is to hard power cycle.

We have been able to reduce the frequency of these attacks from a few times a day to a few times a month, by limiting the size of "zfs_arc_max" to 1/4 of available RAM.

This is a very serious issue for us - as it is a deal-breaking stability issue that is preventing more wide scale and more serious production rollout.

I will take a moment to celebrate the ZFS on Linux's ability to maintain data integrity in the face of this issue - there are very few SAN systems that can routinely have the power literally hard cycled as much as we have done, and NEVER lose a single file or corrupt a single file. Utterly impressive :-)

Very much looking forward to solving this stability issue as after months of trying every possible suggestion in the newsgroups, we have had not found a viable workaround.

Cheers

Paul

----------
root@gsan1-coy:~# cat /var/log/syslog | grep -e hung
Nov 24 17:15:23 gsan1-coy kernel: [232737.512137] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 17:17:24 gsan1-coy kernel: [232857.504204] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 17:19:24 gsan1-coy kernel: [232977.495599] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 17:21:24 gsan1-coy kernel: [233097.487354] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 17:27:24 gsan1-coy kernel: [233457.413291] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 17:43:22 gsan1-coy kernel: [ 361.018833] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 18:08:18 gsan1-coy kernel: [ 361.024042] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 18:08:18 gsan1-coy kernel: [ 361.051342] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 18:42:29 gsan1-coy kernel: [ 241.052531] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 18:44:29 gsan1-coy kernel: [ 361.045481] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 18:56:33 gsan1-coy kernel: [ 1077.001800] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 18:58:28 gsan1-coy kernel: [ 1196.981191] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 18:58:28 gsan1-coy kernel: [ 1196.996135] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 19:00:25 gsan1-coy kernel: [ 1316.976739] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 19:00:26 gsan1-coy kernel: [ 1316.994442] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 19:02:25 gsan1-coy kernel: [ 1436.982179] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 19:16:25 gsan1-coy kernel: [ 2276.771722] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 24 19:29:28 gsan1-coy kernel: [ 3059.941819] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

root@gsan1-coy:~# cat /var/log/syslog | grep stall
Nov 24 18:54:25 gsan1-coy kernel: [ 432.316135] INFO: rcu_sched_state detected stall on CPU 2 (t=15000 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 432.324129] INFO: rcu_sched_state detected stalls on CPUs/tasks: { 2} (detected by 7, t=15002 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 575.229472] INFO: rcu_sched_state detected stall on CPU 6 (t=15000 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 575.229476] INFO: rcu_sched_state detected stall on CPU 2 (t=15000 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 575.229480] INFO: rcu_sched_state detected stall on CPU 7 (t=15000 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 575.229485] INFO: rcu_sched_state detected stall on CPU 5 (t=15000 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 575.229489] INFO: rcu_sched_state detected stall on CPU 1 (t=15000 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 575.229494] INFO: rcu_sched_state detected stall on CPU 4 (t=15000 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 575.229497] INFO: rcu_sched_state detected stall on CPU 3 (t=15000 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 755.300583] INFO: rcu_sched_state detected stall on CPU 6 (t=60030 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 755.300589] INFO: rcu_sched_state detected stall on CPU 5 (t=60030 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 755.300593] INFO: rcu_sched_state detected stall on CPU 7 (t=60030 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 755.300597] INFO: rcu_sched_state detected stall on CPU 3 (t=60030 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 755.300601] INFO: rcu_sched_state detected stall on CPU 2 (t=60030 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 755.300604] INFO: rcu_sched_state detected stall on CPU 1 (t=60030 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 755.300609] INFO: rcu_sched_state detected stall on CPU 4 (t=60030 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 935.371591] INFO: rcu_sched_state detected stall on CPU 5 (t=105060 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 935.371596] INFO: rcu_sched_state detected stall on CPU 6 (t=105060 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 935.371601] INFO: rcu_sched_state detected stall on CPU 7 (t=105060 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 935.371605] INFO: rcu_sched_state detected stall on CPU 1 (t=105060 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 935.371608] INFO: rcu_sched_state detected stall on CPU 2 (t=105060 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 935.371612] INFO: rcu_sched_state detected stall on CPU 3 (t=105060 jiffies)
Nov 24 18:54:25 gsan1-coy kernel: [ 935.371616] INFO: rcu_sched_state detected stall on CPU 4 (t=105060 jiffies)
Nov 24 19:25:28 gsan1-coy kernel: [ 2562.893218] INFO: rcu_sched_state detected stall on CPU 6 (t=15000 jiffies)
Nov 24 19:25:28 gsan1-coy kernel: [ 2562.901208] INFO: rcu_sched_state detected stalls on CPUs/tasks: { 6} (detected by 5, t=15002 jiffies)
Nov 24 19:25:28 gsan1-coy kernel: [ 2742.970645] INFO: rcu_sched_state detected stall on CPU 6 (t=60032 jiffies)
Nov 24 19:25:28 gsan1-coy kernel: [ 2742.978638] INFO: rcu_sched_state detected stalls on CPUs/tasks: { 6} (detected by 5, t=60034 jiffies)
Nov 24 19:38:48 gsan1-coy kernel: [ 3196.369340] INFO: rcu_sched_state detected stall on CPU 7 (t=15000 jiffies)
Nov 24 19:38:48 gsan1-coy kernel: [ 3196.369345] INFO: rcu_sched_state detected stall on CPU 5 (t=15000 jiffies)
Nov 24 19:38:48 gsan1-coy kernel: [ 3196.369349] INFO: rcu_sched_state detected stall on CPU 6 (t=15000 jiffies)
Nov 24 19:38:48 gsan1-coy kernel: [ 3196.369353] INFO: rcu_sched_state detected stall on CPU 1 (t=15000 jiffies)
Nov 24 19:38:48 gsan1-coy kernel: [ 3196.369357] INFO: rcu_sched_state detected stall on CPU 2 (t=15000 jiffies)
Nov 24 19:38:48 gsan1-coy kernel: [ 3196.369362] INFO: rcu_sched_state detected stall on CPU 4 (t=15000 jiffies)
Nov 24 19:38:48 gsan1-coy kernel: [ 3196.369365] INFO: rcu_sched_state detected stall on CPU 3 (t=15000 jiffies)
Nov 24 19:38:48 gsan1-coy kernel: [ 3196.369368] INFO: rcu_sched_state detected stall on CPU 0 (t=15000 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3376.440249] INFO: rcu_sched_state detected stall on CPU 6 (t=60030 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3376.440255] INFO: rcu_sched_state detected stall on CPU 7 (t=60030 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3376.440259] INFO: rcu_sched_state detected stall on CPU 5 (t=60030 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3376.440263] INFO: rcu_sched_state detected stall on CPU 1 (t=60030 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3376.440268] INFO: rcu_sched_state detected stall on CPU 4 (t=60030 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3376.440271] INFO: rcu_sched_state detected stall on CPU 3 (t=60030 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3376.440275] INFO: rcu_sched_state detected stall on CPU 2 (t=60030 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3376.440278] INFO: rcu_sched_state detected stall on CPU 0 (t=60030 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3556.510874] INFO: rcu_sched_state detected stall on CPU 7 (t=105060 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3556.510879] INFO: rcu_sched_state detected stall on CPU 6 (t=105060 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3556.510884] INFO: rcu_sched_state detected stall on CPU 5 (t=105060 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3556.510888] INFO: rcu_sched_state detected stall on CPU 3 (t=105060 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3556.510892] INFO: rcu_sched_state detected stall on CPU 1 (t=105060 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3556.510896] INFO: rcu_sched_state detected stall on CPU 4 (t=105060 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3556.510899] INFO: rcu_sched_state detected stall on CPU 2 (t=105060 jiffies)
Nov 24 19:39:04 gsan1-coy kernel: [ 3556.510903] INFO: rcu_sched_state detected stall on CPU 0 (t=105060 jiffies)
Nov 24 20:21:30 gsan1-coy kernel: [ 5914.420208] INFO: rcu_sched_state detected stall on CPU 1 (t=15000 jiffies)
Nov 24 20:21:30 gsan1-coy kernel: [ 6094.494578] INFO: rcu_sched_state detected stall on CPU 1 (t=60031 jiffies)
Nov 24 22:13:27 gsan1-coy kernel: [12757.532111] INFO: rcu_sched_state detected stall on CPU 2 (t=15000 jiffies)
Nov 24 22:13:27 gsan1-coy kernel: [12757.540104] INFO: rcu_sched_state detected stalls on CPUs/tasks: { 2} (detected by 7, t=15002 jiffies)
Nov 24 22:47:10 gsan1-coy kernel: [14827.405601] INFO: rcu_sched_state detected stall on CPU 7 (t=15000 jiffies)
Nov 24 22:47:10 gsan1-coy kernel: [14827.405606] INFO: rcu_sched_state detected stall on CPU 6 (t=15000 jiffies)
Nov 24 22:47:10 gsan1-coy kernel: [14827.405611] INFO: rcu_sched_state detected stall on CPU 5 (t=15000 jiffies)
Nov 24 22:47:10 gsan1-coy kernel: [14827.405614] INFO: rcu_sched_state detected stall on CPU 1 (t=15000 jiffies)
Nov 24 22:47:10 gsan1-coy kernel: [14827.405618] INFO: rcu_sched_state detected stall on CPU 2 (t=15000 jiffies)
Nov 24 22:47:10 gsan1-coy kernel: [14827.405622] INFO: rcu_sched_state detected stall on CPU 3 (t=15000 jiffies)
Nov 24 22:47:10 gsan1-coy kernel: [14827.405625] INFO: rcu_sched_state detected stall on CPU 0 (t=15000 jiffies)
Nov 24 22:47:10 gsan1-coy kernel: [14827.405629] INFO: rcu_sched_state detected stall on CPU 4 (t=15000 jiffies)
Nov 25 00:19:28 gsan1-coy kernel: [20240.935394] INFO: rcu_sched_state detected stall on CPU 5 (t=15000 jiffies)
Nov 25 00:19:28 gsan1-coy kernel: [20421.005987] INFO: rcu_sched_state detected stall on CPU 5 (t=60030 jiffies)
Nov 25 00:26:41 gsan1-coy kernel: [20888.081850] INFO: rcu_sched_state detected stall on CPU 5 (t=15000 jiffies)
Nov 25 00:26:41 gsan1-coy kernel: [20888.081855] INFO: rcu_sched_state detected stall on CPU 6 (t=15000 jiffies)
Nov 25 00:26:41 gsan1-coy kernel: [20888.081860] INFO: rcu_sched_state detected stall on CPU 7 (t=15000 jiffies)
Nov 25 00:26:41 gsan1-coy kernel: [20888.081864] INFO: rcu_sched_state detected stall on CPU 2 (t=15000 jiffies)
Nov 25 00:26:41 gsan1-coy kernel: [20888.081868] INFO: rcu_sched_state detected stall on CPU 3 (t=15000 jiffies)
Nov 25 00:26:41 gsan1-coy kernel: [20888.081872] INFO: rcu_sched_state detected stall on CPU 4 (t=15000 jiffies)
Nov 25 00:26:41 gsan1-coy kernel: [20888.081875] INFO: rcu_sched_state detected stall on CPU 1 (t=15000 jiffies)
Nov 25 00:29:42 gsan1-coy kernel: [21068.152456] INFO: rcu_sched_state detected stall on CPU 6 (t=60030 jiffies)
Nov 25 00:29:42 gsan1-coy kernel: [21068.152461] INFO: rcu_sched_state detected stall on CPU 5 (t=60030 jiffies)
Nov 25 00:29:42 gsan1-coy kernel: [21068.152466] INFO: rcu_sched_state detected stall on CPU 7 (t=60030 jiffies)
Nov 25 00:29:42 gsan1-coy kernel: [21068.152470] INFO: rcu_sched_state detected stall on CPU 4 (t=60030 jiffies)
Nov 25 00:29:42 gsan1-coy kernel: [21068.152474] INFO: rcu_sched_state detected stall on CPU 2 (t=60030 jiffies)
Nov 25 00:29:42 gsan1-coy kernel: [21068.152477] INFO: rcu_sched_state detected stall on CPU 1 (t=60030 jiffies)
Nov 25 00:29:42 gsan1-coy kernel: [21068.152481] INFO: rcu_sched_state detected stall on CPU 3 (t=60030 jiffies)