Bug 35662

Summary:	softlockup with kernel 2.6.39
Product:	IO/Storage	Reporter:	Hussam Al-Tayeb (ht990332)
Component:	Other	Assignee:	io_other
Status:	RESOLVED INSUFFICIENT_DATA
Severity:	normal	CC:	akpm, alan, bugzilla-kernel, florian, maciej.rutecki, rjw
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	2.6.39	Subsystem:
Regression:	Yes	Bisected commit-id:
Bug Depends on:
Bug Blocks:	32012

Description Hussam Al-Tayeb 2011-05-23 08:13:28 UTC

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.

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.

Comment 1 Hussam Al-Tayeb 2011-05-23 17:36:09 UTC

I forgot to mention. all paritions apart from swap and /boot and encrypted with LuKs.

Comment 2 Andrew Morton 2011-05-23 23:23:18 UTC

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

On Mon, 23 May 2011 08:13:30 GMT
bugzilla-daemon@bugzilla.kernel.org 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: io_other@kernel-bugs.osdl.org
>         ReportedBy: ht990332@gmail.com
>         Regression: No

I'll mark this as a regression.

> 
> 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.
> 
> 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,

> 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...

Comment 3 Anonymous Emailer 2011-05-23 23:42:23 UTC

Reply-To: ht990332@gmail.com

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.

Comment 4 Andrew Morton 2011-05-23 23:49:00 UTC

On Tue, 24 May 2011 02:41:51 +0300
Hussam Al-Tayeb <ht990332@gmail.com> 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".

Comment 5 Anonymous Emailer 2011-05-24 07:02:22 UTC

Reply-To: ht990332@gmail.com

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.

Comment 6 Anonymous Emailer 2011-05-26 05:03:52 UTC

Reply-To: ht990332@gmail.com

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

Comment 7 Anonymous Emailer 2011-05-26 16:34:46 UTC

Reply-To: ht990332@gmail.com

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

Comment 8 Alan 2012-06-27 13:51:06 UTC

Is this still seen with modern kernels ?