Re: I/O hangs after resuming from suspend-to-ram

Oleksandr Natalenko
2017-08-29T15:52:49Z

Hello.

Re-tested with v4.13-rc7 + proposed patch and got the same result.

Let me know if any additional testing is needed.

===
[ 82.638148] INFO: task md0_raid10:193 blocked for more than 20 seconds.
[ 82.642804] Not tainted 4.13.0-pf1 #1
[ 82.646998] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 82.649007] md0_raid10 D 0 193 2 0x00000000
[ 82.650799] Call Trace:
[ 82.652118] __schedule+0x239/0x890
[ 82.653469] schedule+0x3d/0x90
[ 82.654649] md_super_wait+0x6e/0xa0 [md_mod]
[ 82.656186] ? wait_woken+0x80/0x80
[ 82.657333] md_update_sb.part.59+0x3df/0x840 [md_mod]
[ 82.659084] ? percpu_ref_switch_to_percpu+0x36/0x40
[ 82.660477] md_check_recovery+0x453/0x520 [md_mod]
[ 82.662125] raid10d+0x62/0x1420 [raid10]
[ 82.663457] ? __schedule+0x241/0x890
[ 82.664766] ? schedule+0x3d/0x90
[ 82.665816] ? schedule_timeout+0x208/0x390
[ 82.666785] md_thread+0x120/0x160 [md_mod]
[ 82.668117] ? md_thread+0x120/0x160 [md_mod]
[ 82.669487] ? wait_woken+0x80/0x80
[ 82.670531] kthread+0x125/0x140
[ 82.671602] ? find_pers+0x70/0x70 [md_mod]
[ 82.672452] ? kthread_create_on_node+0x70/0x70
[ 82.673844] ret_from_fork+0x25/0x30
[ 82.674991] INFO: task dmcrypt_write:226 blocked for more than 20 seconds.
[ 82.678246] Not tainted 4.13.0-pf1 #1
[ 82.679336] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 82.681175] dmcrypt_write D 0 226 2 0x00000000
[ 82.682522] Call Trace:
[ 82.683104] __schedule+0x239/0x890
[ 82.684099] schedule+0x3d/0x90
[ 82.684754] md_write_start+0xe3/0x270 [md_mod]
[ 82.685599] ? wait_woken+0x80/0x80
[ 82.686273] raid10_make_request+0x3f/0x140 [raid10]
[ 82.687258] md_make_request+0xa2/0x290 [md_mod]
[ 82.688132] ? _raw_spin_unlock_irq+0x10/0x30
[ 82.689660] ? finish_task_switch+0x75/0x200
[ 82.690624] generic_make_request+0x125/0x320
[ 82.691722] dmcrypt_write+0x22d/0x250 [dm_crypt]
[ 82.693120] ? dmcrypt_write+0x22d/0x250 [dm_crypt]
[ 82.694760] ? wake_up_q+0x80/0x80
[ 82.695752] kthread+0x125/0x140
[ 82.696831] ? kthread+0x125/0x140
[ 82.697964] ? crypt_iv_essiv_dtr+0x70/0x70 [dm_crypt]
[ 82.699340] ? kthread_create_on_node+0x70/0x70
[ 82.700728] ret_from_fork+0x25/0x30
[ 82.702378] INFO: task NetworkManager:432 blocked for more than 20 seconds.
[ 82.704022] Not tainted 4.13.0-pf1 #1
[ 82.705264] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 82.709068] NetworkManager D 0 432 1 0x00000000
[ 82.710189] Call Trace:
[ 82.711041] __schedule+0x239/0x890
[ 82.712162] schedule+0x3d/0x90
[ 82.713223] io_schedule+0x16/0x40
[ 82.714324] wait_on_page_bit_common+0xe7/0x170
[ 82.715644] ? page_cache_tree_insert+0xc0/0xc0
[ 82.717008] __filemap_fdatawait_range+0x10d/0x170
[ 82.718562] ? __filemap_fdatawrite_range+0xc1/0x100
[ 82.720103] ? __filemap_fdatawrite_range+0xcd/0x100
[ 82.721561] file_write_and_wait_range+0x78/0xa0
[ 82.722839] xfs_file_fsync+0x5f/0x210 [xfs]
[ 82.724085] vfs_fsync_range+0x4b/0xb0
[ 82.725152] do_fsync+0x3d/0x70
[ 82.726535] SyS_fsync+0x10/0x20
[ 82.727953] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 82.729196] RIP: 0033:0x7fcd816f6c8d
[ 82.730336] RSP: 002b:00007ffd4650d4d0 EFLAGS: 00000293 ORIG_RAX:
000000000000004a
[ 82.732192] RAX: ffffffffffffffda RBX: 0000000000000013 RCX:
00007fcd816f6c8d
[ 82.733922] RDX: 00007ffd4650d4f0 RSI: 00007ffd4650d4f0 RDI:
0000000000000013
[ 82.735313] RBP: 000056436710ff00 R08: 0000000000000000 R09:
00000000313d26e9
[ 82.738973] R10: 000000000000003d R11: 0000000000000293 R12:
00007ffd4650d638
[ 82.740531] R13: 0000000000000001 R14: 0000000000000002 R15:
00005643670eb1c0
[ 82.741869] INFO: task sync:676 blocked for more than 20 seconds.
[ 82.743116] Not tainted 4.13.0-pf1 #1
[ 82.744286] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 82.745935] sync D 0 676 542 0x00000000
[ 82.747338] Call Trace:
[ 82.748281] __schedule+0x239/0x890
[ 82.749421] schedule+0x3d/0x90
[ 82.750458] io_schedule+0x16/0x40
[ 82.751420] wait_on_page_bit_common+0xe7/0x170
[ 82.752668] ? page_cache_tree_insert+0xc0/0xc0
[ 82.753873] __filemap_fdatawait_range+0x10d/0x170
[ 82.755153] ? finish_wait+0x56/0x70
[ 82.756226] filemap_fdatawait_keep_errors+0x27/0x50
[ 82.757568] sync_inodes_sb+0x204/0x2a0
[ 82.758788] ? SyS_tee+0x3d0/0x3d0
[ 82.759926] sync_inodes_one_sb+0x16/0x20
[ 82.761152] iterate_supers+0x94/0x100
[ 82.762419] sys_sync+0x44/0xb0
[ 82.763499] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 82.764495] RIP: 0033:0x7fd85d7941d7
[ 82.765736] RSP: 002b:00007ffe648d4f48 EFLAGS: 00000206 ORIG_RAX:
00000000000000a2
[ 82.769068] RAX: ffffffffffffffda RBX: 0000000000000006 RCX:
00007fd85d7941d7
[ 82.770663] RDX: 00007fd85da50e01 RSI: 0000000000000000 RDI:
00007fd85d8197d3
[ 82.772211] RBP: 0000000000002710 R08: 0000000000000000 R09:
0000000000000000
[ 82.774138] R10: 000000000000082c R11: 0000000000000206 R12:
00007fd85da4ead8
[ 82.776430] R13: 0000000000000030 R14: 0000000000c6cfd0 R15:
00007fd85da4ea80
===

On úterý 29. srpna 2017 2:24:25 CEST Ming Lei wrote:
> On Mon, Aug 28, 2017 at 08:22:26PM +0200, Oleksandr Natalenko wrote:
> > Hi.
> >
> > On pondělí 28. srpna 2017 14:58:28 CEST Ming Lei wrote:
> > > Could you verify if the following patch fixes your issue?
> > > …SNIP…
> >
> > I've applied it to v4.12.9 and rechecked — the issue is still there,
> > unfortunately. Stacktrace is the same as before.
> >
> > Were you able to reproduce it in a VM?
>
> Yes, I can.
>
> > Should I re-check it with v4.13-rc7?
> >
> > Any other suggestions?
>
> Please test it with v4.13-rc7 first.