New: softlockup with kernel 2.6.39

Bugme-new Andrew Morton 2 participants 6 messages May 23, 2011 – May 26, 2011 1 message not in the archive Memory management

lore

Share & tools

lore

A message that is not in the archive (sent off-list or not yet received): [email protected]/

Andrew Morton

author maintainer

2011-05-23 23:23 UTC #1 lore raw

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

Quoted 15 lines · On Mon, 23 May 2011 08:13:30 GMT [email protected] wrote:

https://bugzilla.kernel.org/show_bug.cgi?id=35662

           Summary: softlockup with kernel 2.6.39
           Product: IO/Storage
           Version: 2.5
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: Other
        AssignedTo: [email protected]
        ReportedBy: [email protected]
        Regression: No

I'll mark this as a regression.

Quoted 37 lines

After upgrading to kernel 2.6.39, I started having soft lockups due to disk activity. anything more that low disk activity would cause a problem in an application A.
dmesg would spit out something like [ 1920.307498] INFO: task java:25665 blocked for more than 120 seconds.
[ 1920.307499] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 1920.307500] java D f036df98 0 25665 25393 0x00000000
[ 1920.307503] f036dee0 00000086 c15899c8 f036df98 e1c09590 00000001 00cbde28
00000170
[ 1920.307507] f036de98 00000064 f036de60 f036de60 f036de68 f036de68 e1c09590
c14e1440
[ 1920.307511] 081c6000 c14e1440 f5506440 e1c09590 e1c08450 00000000 ffffffff
c15899c8
[ 1920.307515] Call Trace:
[ 1920.307518] [<c1073c8d>] ? get_futex_key+0x6d/0x1d0
[ 1920.307520] [<c10742c5>] ? futex_wake+0xe5/0x100
[ 1920.307522] [<c132fd65>] rwsem_down_failed_common+0x95/0xe0
[ 1920.307525] [<c1027640>] ? vmalloc_sync_all+0x120/0x120
[ 1920.307527] [<c132fde2>] rwsem_down_read_failed+0x12/0x14
[ 1920.307529] [<c132fe1f>] call_rwsem_down_read_failed+0x7/0xc
[ 1920.307531] [<c132f69d>] ? down_read+0xd/0x10
[ 1920.307534] [<c1027787>] do_page_fault+0x147/0x420
[ 1920.307536] [<c10760e4>] ? sys_futex+0xc4/0x130
[ 1920.307538] [<c1027640>] ? vmalloc_sync_all+0x120/0x120
[ 1920.307540] [<c1330c4b>] error_code+0x67/0x6c
Application A would then stop being able to read/write from disk. Other running applications would still be able to read/write fine to the disk.
I could even copy the data application A to another folder or delete it. This isn't a hard lockup and I could still continue to use the computer but then it'll hang at shutdown.
At first I thought the disk (which I bought 12 days ago) is bad so I ran badblocks -vs and didn't find a single bad block. I ran smartctl long test and the disk is fine. It started to feel like some ext4 regression.

Quoted 6 lines

I downgraded to kernel 2.6.38.6 and performed a disk intensive action which was recompiling libreoffice. This worked without a problem.
I also tried the application A which was giving problems earlier but I couldn't see a problem again. So I compiled libreoffice again to check and didn't have lockups.

It appears that we forgot to release mmap_sem.

Also,

Quoted 1 line

all paritions apart from swap and /boot and encrypted with LuKs.

This involves dm-crypt, correct?

I see quite a lot of dm-crypt related bug reports float past. But there have been very few changes in dm-crypt recently, and something broke in 2.6.39...

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Fight unfair telecom internet charges in Canada: sign http://stopthemeter.ca/
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Hussam Al-Tayeb

2011-05-23 23:42 UTC #2 lore raw

YEs,
lsmod | grep dm_crypt

dm_crypt               12887  2 
dm_mod                 55464  5 dm_crypt

Still no lockups since downgrading to 2.6.38.6 which was a few hours before I filed the bug report.
I could reinstall 2.6.39 if there is anything you would like me to test.

Andrew Morton

author maintainer

2011-05-23 23:49 UTC #3 lore raw

Quoted 8 lines · On Tue, 24 May 2011 02:41:51 +0300 Hussam Al-Tayeb <[email protected]> wrote:

YEs,
lsmod | grep dm_crypt
dm_crypt               12887  2 
dm_mod                 55464  5 dm_crypt
Still no lockups since downgrading to 2.6.38.6 which was a few hours before I filed the bug report.
I could reinstall 2.6.39 if there is anything you would like me to test.

Thanks.

CONFIG_PROVE_LOCKING=y would be useful, if you didn't already have it set.

Also after the kernel has failed, kill everything off and do a `ps aux' and look for any other tasks which are stuck in "D" state. Backtraces for any such processes can be obtained with "echo w > /proc/sysrq-trigger".

Hussam Al-Tayeb

2011-05-24 07:01 UTC #4 lore raw

Actually it was definitely more than a few hours before filing the bug report. I did recompile libreoffice twice as a 'stress test' under kernel 2.6.38.6

I'm using kernel 2.6.39 now and waiting for the lockup to happen again.

Hussam Al-Tayeb

2011-05-26 05:03 UTC #5 lore raw

It happened again. also while doing a test build of libreoffice (very disk intensive stuff).
The build process seems frozen. I did cat /var/log/kernel.log and run /bin/dmesg but didn't find any error.

so I typed init s then
echo w > /proc/sysrq-trigger

and then I typed ps aux | grep D

root        23  0.0  0.0      0     0 ?        DN   May25   0:06 [khugepaged]
root      8673  0.0  0.0   4412   832 pts/2    S+   08:02   0:00 grep D

then I typed exit and I found the following in my kernel.log

11/05/26 07:54:00 udevd[7360] starting version 170
11/05/26 07:54:01 leds_ss4200 no LED devices found
11/05/26 07:54:01 intel_rng Firmware space is locked read-only. If you can't
or
11/05/26 07:54:01 intel_rng don't want to disable this in firmware setup, and
if
11/05/26 07:54:01 intel_rng you are certain that your system has a
functional
11/05/26 07:54:01 intel_rng RNG, try using the 'no_fwh_detect' option.
11/05/26 07:54:32 SysRq Show Blocked State
11/05/26 07:54:32 task PC stack pid father
11/05/26 07:54:32 khugepaged D f4393ca4 0 23 2 0x00000000
11/05/26 07:54:32 f4393cb4 00000046 00000002 f4393ca4 f4044dcc 00000000
c0a8204e 000033ba
11/05/26 07:54:32 00000000 e20eba00 f4393c5c c10026ce 00000000 0098c500
00000001 c14e1440
11/05/26 07:54:32 f4393c64 c14e1440 f5506440 f4044da0 f4042f70 e20eba00
f4393d0c 00000286
11/05/26 07:54:32 Call Trace
11/05/26 07:54:32 [<c10026ce>] ? __switch_to+0xce/0x180
11/05/26 07:54:32 [<c1052076>] ? lock_timer_base.isra.31+0x26/0x50
11/05/26 07:54:32 [<c1052106>] ? try_to_del_timer_sync+0x66/0x100
11/05/26 07:54:32 [<c1052076>] ? lock_timer_base.isra.31+0x26/0x50
11/05/26 07:54:32 [<c132e3ca>] schedule_timeout+0x12a/0x2e0
11/05/26 07:54:32 [<c1051630>] ? init_timer_deferrable_key+0x20/0x20
11/05/26 07:54:32 [<c132e231>] io_schedule_timeout+0x81/0xd0
11/05/26 07:54:32 [<c10d7ea2>] congestion_wait+0x52/0xe0
11/05/26 07:54:32 [<c1061750>] ? abort_exclusive_wait+0x80/0x80
11/05/26 07:54:32 [<c10f2501>] compact_zone+0x721/0x750
11/05/26 07:54:32 [<c10f25a9>] compact_zone_order+0x79/0xa0
11/05/26 07:54:32 [<c10f266d>] try_to_compact_pages+0x9d/0xd0
11/05/26 07:54:32 [<c10c6eee>] __alloc_pages_direct_compact+0x7e/0x160
11/05/26 07:54:32 [<c10c73ad>] __alloc_pages_nodemask+0x3dd/0x7b0
11/05/26 07:54:32 [<c10e5f7c>] ? page_add_new_anon_rmap+0x8c/0xa0
11/05/26 07:54:32 [<c10faea8>] khugepaged+0x418/0xe10
11/05/26 07:54:32 [<c1061750>] ? abort_exclusive_wait+0x80/0x80
11/05/26 07:54:32 [<c10faa90>] ? khugepaged_defrag_store+0x50/0x50
11/05/26 07:54:32 [<c1061098>] kthread+0x68/0x70
11/05/26 07:54:32 [<c1061030>] ? kthread_worker_fn+0x150/0x150
11/05/26 07:54:32 [<c133147e>] kernel_thread_helper+0x6/0xd
11/05/26 07:54:32 Sched Debug Version v0.10, 2.6.39-ARCH #1
11/05/26 07:54:32 ktime : 56907897.973146
11/05/26 07:54:32 sched_clk : 56892856.276187
11/05/26 07:54:32 cpu_clk : 56907897.973092
11/05/26 07:54:32 jiffies : 16982371
11/05/26 07:54:32 sched_clock_stable : 0
11/05/26 07:54:32
11/05/26 07:54:32 sysctl_sched
11/05/26 07:54:32 .sysctl_sched_latency : 12.000000
11/05/26 07:54:32 .sysctl_sched_min_granularity : 1.500000
11/05/26 07:54:32 .sysctl_sched_wakeup_granularity : 2.000000
11/05/26 07:54:32 .sysctl_sched_child_runs_first : 0
11/05/26 07:54:32 .sysctl_sched_features : 7279
11/05/26 07:54:32 .sysctl_sched_tunable_scaling : 1 (logaritmic)
11/05/26 07:54:32
11/05/26 07:54:32 cpu#0, 2933.889 MHz
11/05/26 07:54:32 .nr_running : 1
11/05/26 07:54:32 .load : 1024
11/05/26 07:54:32 .nr_switches : 66131673
11/05/26 07:54:32 .nr_load_updates : 4725405
11/05/26 07:54:32 .nr_uninterruptible : 0
11/05/26 07:54:32 .next_balance : 16.982350
11/05/26 07:54:32 .curr->pid : 7949
11/05/26 07:54:32 .clock : 56907897.673964
11/05/26 07:54:32 .cpu_load[0] : 0
11/05/26 07:54:32 .cpu_load[1] : 0
11/05/26 07:54:32 .cpu_load[2] : 0
11/05/26 07:54:32 .cpu_load[3] : 0
11/05/26 07:54:32 .cpu_load[4] : 0
11/05/26 07:54:32
11/05/26 07:54:32 cfs_rq[0] autogroup-105
11/05/26 07:54:32 .exec_clock : 0.000000
11/05/26 07:54:32 .MIN_vruntime : 0.000001
11/05/26 07:54:32 .min_vruntime : 19.599979
11/05/26 07:54:32 .max_vruntime : 0.000001
11/05/26 07:54:32 .spread : 0.000000
11/05/26 07:54:32 .spread0 : -13633115.574964
11/05/26 07:54:32 .nr_spread_over : 0
11/05/26 07:54:32 .nr_running : 1
11/05/26 07:54:32 .load : 1024
11/05/26 07:54:32 .load_avg : 0.000000
11/05/26 07:54:32 .load_period : 9.999999
11/05/26 07:54:32 .load_contrib : 0
11/05/26 07:54:32 .load_tg : 0
11/05/26 07:54:32 .se->exec_start : 56907897.673964
11/05/26 07:54:32 .se->vruntime : 13633135.174943
11/05/26 07:54:32 .se->sum_exec_runtime : 19.279330
11/05/26 07:54:32 .se->load.weight : 1024
11/05/26 07:54:32
11/05/26 07:54:32 cfs_rq[0]
11/05/26 07:54:32 .exec_clock : 0.000000
11/05/26 07:54:32 .MIN_vruntime : 0.000001
11/05/26 07:54:32 .min_vruntime : 13633135.174943
11/05/26 07:54:32 .max_vruntime : 0.000001
11/05/26 07:54:32 .spread : 0.000000
11/05/26 07:54:32 .spread0 : 0.000000
11/05/26 07:54:32 .nr_spread_over : 0
11/05/26 07:54:32 .nr_running : 1
11/05/26 07:54:32 .load : 1024
11/05/26 07:54:32 .load_avg : 0.000000
11/05/26 07:54:32 .load_period : 0.000000
11/05/26 07:54:32 .load_contrib : 0
11/05/26 07:54:32 .load_tg : 0
11/05/26 07:54:32
11/05/26 07:54:32 runnable tasks
11/05/26 07:54:32 task PID tree-key switches prio exec-runtime sum-exec
sum-sleep
11/05/26 07:54:32
----------------------------------------------------------------------------------------------------------
11/05/26 07:54:32 R bash 7949 19.599979 63 120 0 0 0.000000 0.000000
0.000000 /autogroup-105
11/05/26 07:54:32
11/05/26 07:54:32 cpu#1, 2933.889 MHz
11/05/26 07:54:32 .nr_running : 0
11/05/26 07:54:32 .load : 0
11/05/26 07:54:32 .nr_switches : 66462726
11/05/26 07:54:32 .nr_load_updates : 4571341
11/05/26 07:54:32 .nr_uninterruptible : 1
11/05/26 07:54:32 .next_balance : 16.982370
11/05/26 07:54:32 .curr->pid : 0
11/05/26 07:54:32 .clock : 56907897.675594
11/05/26 07:54:32 .cpu_load[0] : 0
11/05/26 07:54:32 .cpu_load[1] : 0
11/05/26 07:54:32 .cpu_load[2] : 0
11/05/26 07:54:32 .cpu_load[3] : 0
11/05/26 07:54:32 .cpu_load[4] : 5
11/05/26 07:54:32
11/05/26 07:54:32 cfs_rq[1]
11/05/26 07:54:32 .exec_clock : 0.000000
11/05/26 07:54:32 .MIN_vruntime : 0.000001
11/05/26 07:54:32 .min_vruntime : 13650531.404239
11/05/26 07:54:32 .max_vruntime : 0.000001
11/05/26 07:54:32 .spread : 0.000000
11/05/26 07:54:32 .spread0 : 17396.229296
11/05/26 07:54:32 .nr_spread_over : 0
11/05/26 07:54:32 .nr_running : 0
11/05/26 07:54:32 .load : 0
11/05/26 07:54:32 .load_avg : 0.000000
11/05/26 07:54:32 .load_period : 0.000000
11/05/26 07:54:32 .load_contrib : 0
11/05/26 07:54:32 .load_tg : 0
11/05/26 07:54:32
11/05/26 07:54:32 runnable tasks
11/05/26 07:54:32 task PID tree-key switches prio exec-runtime sum-exec
sum-sleep
11/05/26 07:54:32
----------------------------------------------------------------------------------------------------------
11/05/26 07:54:32
11/05/26 07:55:01 usb 3-2 USB disconnect, device number 2
11/05/26 07:55:02 ppp0 Features changed: 0x00006800 -> 0x00006000
11/05/26 07:55:02 usb 3-2 new low speed USB device number 3 using uhci_hcd
11/05/26 07:55:03 input PIXART USB OPTICAL MOUSE as
/devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2:1.0/input/input9
11/05/26 07:55:03 generic-usb 0003 93A:2510.0002: input,hidraw0: USB HID
v1.11 Mouse [PIXART USB OPTICAL MOUSE] on usb-0000:00:1d.1-2/input0
11/05/26 07:55:05 0000 2:05.0: tulip_stop_rxtx() failed (CSR5 0xfc664010
CSR6 0xff972113)
11/05/26 07:55:05 net eth0 Setting full-duplex based on MII#1 link partner
capability of 45e1
11/05/26 07:55:05 w83627ehf Found W83627DHG chip at 0x290
11/05/26 07:55:12 eth0 no IPv6 routers present
11/05/26 07:55:19 EXT4-fs (dm-0) re-mounted. Opts: user_xattr,commit=0
11/05/26 07:55:19 EXT4-fs (sda1) re-mounted. Opts: user_xattr,commit=0
11/05/26 07:55:20 EXT4-fs (dm-1) re-mounted. Opts: user_xattr,commit=0

Hussam Al-Tayeb

2011-05-26 16:34 UTC #6 lore raw

In reply to Hussam Al-Tayeb

Another time.

[ 8520.275830] INFO: task khugepaged:26 blocked for more than 120 seconds.
[ 8520.275834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables 
this message.
[ 8520.275837] khugepaged      D c1455200     0    26      2 0x00000000
[ 8520.275843]  f3f9fedc 00000046 f59af000 c1455200 00000400 c1455200 c1455580 
f3c451f0
[ 8520.275850]  0000000a f3f9fe88 c10c5078 c1455c80 00000003 f5506380 c14c4380 
f3c451f0
[ 8520.275857]  f3c453b4 33c86581 0000069a c14c4380 f5506380 f3c451f0 c4525640 
f3f9fee8
[ 8520.275864] Call Trace:
[ 8520.275874]  [<c10c5078>] ? __alloc_pages_direct_compact+0xe8/0x160
[ 8520.275880]  [<c10ff3f8>] ? __mem_cgroup_try_charge+0x2d8/0x4e0
[ 8520.275885]  [<c10fd138>] ? memcg_check_events+0x28/0x160
[ 8520.275891]  [<c131b885>] rwsem_down_failed_common+0x95/0xe0
[ 8520.275895]  [<c131b8e2>] rwsem_down_write_failed+0x12/0x20
[ 8520.275900]  [<c131b94a>] call_rwsem_down_write_failed+0x6/0x8
[ 8520.275904]  [<c131b0f5>] ? down_write+0x15/0x17
[ 8520.275908]  [<c10f8c72>] khugepaged+0x552/0xdf0
[ 8520.275913]  [<c10613a0>] ? autoremove_wake_function+0x0/0x40
[ 8520.275922]  [<c10f8720>] ? khugepaged+0x0/0xdf0
[ 8520.275924]  [<c1060d08>] kthread+0x68/0x70
[ 8520.275926]  [<c1060ca0>] ? kthread+0x0/0x70
[ 8520.275929]  [<c1003d7e>] kernel_thread_helper+0x6/0x18