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

Oleksandr Natalenko
2017-08-22T11:45:51Z

Hi.

v4.12.8 kernel hangs in I/O path after resuming from suspend-to-ram. I have
blk-mq enabled, tried both BFQ and mq-deadline schedulers with the same
result. Soft lockup happens showing stacktraces I'm pasting below.

Stacktrace shows that I/O hangs in md_super_wait(), and it means it waits for
"all superblock writes that were scheduled to complete". Since there is
"scheduled" word, should I also try "none" scheduler with blk-mq enabled?

While I'm trying to reproduce it on a VM without much luck (it happens on my
laptop rarely, like 1 out of 10 suspend-resume cycles), and also re-checking
it with blk-mq disabled, by any chance is this something already known?

Ideally, I'd like to reprduce it in a VM and capture vmcore.

Any suggestions are welcome. Thanks.

===
[ 9460.165958] INFO: task md0_raid10:225 blocked for more than 120 seconds.
[ 9460.165983] Not tainted 4.12.0-pf7 #1
[ 9460.165989] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.165996] md0_raid10 D 0 225 2 0x00000000
[ 9460.166005] Call Trace:
[ 9460.166027] __schedule+0x6e7/0xcd0
[ 9460.166043] schedule+0x3d/0xd0
[ 9460.166067] md_super_wait+0x6e/0xa0 [md_mod]
[ 9460.166130] ? wake_bit_function+0x60/0x60
[ 9460.166143] write_page+0x185/0x310 [md_mod]
[ 9460.166156] bitmap_update_sb+0x12f/0x140 [md_mod]
[ 9460.166167] md_update_sb.part.60+0x354/0x840 [md_mod]
[ 9460.166179] ? percpu_ref_switch_to_percpu+0x36/0x40
[ 9460.166190] md_check_recovery+0x214/0x4b0 [md_mod]
[ 9460.166201] raid10d+0x62/0x13c0 [raid10]
[ 9460.166213] ? lock_timer_base+0x81/0xa0
[ 9460.166222] ? try_to_del_timer_sync+0x53/0x80
[ 9460.166232] ? del_timer_sync+0x39/0x40
[ 9460.166246] ? schedule_timeout+0x19b/0x330
[ 9460.166261] ? call_timer_fn+0x160/0x160
[ 9460.166279] md_thread+0x120/0x160 [md_mod]
[ 9460.166290] ? md_thread+0x120/0x160 [md_mod]
[ 9460.166298] ? wake_bit_function+0x60/0x60
[ 9460.166309] kthread+0x124/0x140
[ 9460.166319] ? find_pers+0x70/0x70 [md_mod]
[ 9460.166353] ? kthread_create_on_node+0x70/0x70
[ 9460.166360] ret_from_fork+0x25/0x30
[ 9460.166371] INFO: task dmcrypt_write:254 blocked for more than 120 seconds.
[ 9460.166376] Not tainted 4.12.0-pf7 #1
[ 9460.166381] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.166386] dmcrypt_write D 0 254 2 0x00000000
[ 9460.166492] Call Trace:
[ 9460.166501] __schedule+0x6e7/0xcd0
[ 9460.166511] schedule+0x3d/0xd0
[ 9460.166522] md_write_start+0xe3/0x270 [md_mod]
[ 9460.166529] ? wake_bit_function+0x60/0x60
[ 9460.166538] raid10_make_request+0x3f/0x140 [raid10]
[ 9460.166549] md_make_request+0xa9/0x2a0 [md_mod]
[ 9460.166557] ? __schedule+0x6ef/0xcd0
[ 9460.166567] generic_make_request+0x11e/0x2f0
[ 9460.166578] dmcrypt_write+0x22d/0x250 [dm_crypt]
[ 9460.166586] ? dmcrypt_write+0x22d/0x250 [dm_crypt]
[ 9460.166596] ? wake_up_q+0x80/0x80
[ 9460.166605] kthread+0x124/0x140
[ 9460.166613] ? kthread+0x124/0x140
[ 9460.166621] ? crypt_iv_essiv_dtr+0x70/0x70 [dm_crypt]
[ 9460.166628] ? kthread_create_on_node+0x70/0x70
[ 9460.166635] ret_from_fork+0x25/0x30
[ 9460.166677] INFO: task konversation:7110 blocked for more than 120 seconds.
[ 9460.166683] Not tainted 4.12.0-pf7 #1
[ 9460.166687] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.166693] konversation D 0 7110 6972 0x00000000
[ 9460.166700] Call Trace:
[ 9460.166709] __schedule+0x6e7/0xcd0
[ 9460.166719] schedule+0x3d/0xd0
[ 9460.166824] io_schedule+0x16/0x40
[ 9460.166833] wait_on_page_bit+0xeb/0x130
[ 9460.166841] ? page_cache_tree_insert+0xc0/0xc0
[ 9460.166882] prepare_pages+0x1b5/0x1d0 [btrfs]
[ 9460.166915] __btrfs_buffered_write+0x267/0x6d0 [btrfs]
[ 9460.166948] btrfs_file_write_iter+0x1c1/0x500 [btrfs]
[ 9460.166956] ? cp_new_stat+0x152/0x180
[ 9460.166966] __vfs_write+0xe4/0x140
[ 9460.166975] vfs_write+0xb1/0x1a0
[ 9460.166984] SyS_write+0x55/0xc0
[ 9460.166994] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 9460.167001] RIP: 0033:0x7fd020f09c0d
[ 9460.167006] RSP: 002b:00007ffe27e70360 EFLAGS: 00000293 ORIG_RAX:
0000000000000001
[ 9460.167013] RAX: ffffffffffffffda RBX: 0000000003178840 RCX:
00007fd020f09c0d
[ 9460.167019] RDX: 000000000000007d RSI: 0000000003241598 RDI:
000000000000002b
[ 9460.167024] RBP: 00007fd0211c72a0 R08: 00007fd021a55010 R09:
0000000000000030
[ 9460.167029] R10: 00007fd0211caad8 R11: 0000000000000293 R12:
0000000000000000
[ 9460.167034] R13: 00000000013b4cef R14: 0000000000000400 R15:
0000000000000001
[ 9460.167075] INFO: task akonadi_imap_re:7363 blocked for more than 120
seconds.
[ 9460.167080] Not tainted 4.12.0-pf7 #1
[ 9460.167084] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.167089] akonadi_imap_re D 0 7363 7107 0x00000000
[ 9460.167096] Call Trace:
[ 9460.167105] __schedule+0x6e7/0xcd0
[ 9460.167114] schedule+0x3d/0xd0
[ 9460.167149] wait_for_writer+0xb1/0xe0 [btrfs]
[ 9460.167157] ? wake_bit_function+0x60/0x60
[ 9460.167190] btrfs_sync_log+0xe2/0xad0 [btrfs]
[ 9460.167201] ? dput.part.24+0x51/0x1d0
[ 9460.167210] ? dput+0x13/0x20
[ 9460.167242] ? btrfs_log_dentry_safe+0x6a/0x80 [btrfs]
[ 9460.167275] btrfs_sync_file+0x2f4/0x3f0 [btrfs]
[ 9460.167302] ? btrfs_sync_file+0x2f4/0x3f0 [btrfs]
[ 9460.167313] vfs_fsync_range+0x4b/0xb0
[ 9460.167320] do_fsync+0x3d/0x70
[ 9460.167327] SyS_fdatasync+0x13/0x20
[ 9460.167336] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 9460.167342] RIP: 0033:0x7fcdf0d7522d
[ 9460.167348] RSP: 002b:00007ffdcb64e9a0 EFLAGS: 00000293 ORIG_RAX:
000000000000004b
[ 9460.167355] RAX: ffffffffffffffda RBX: 0000007b8c7c9f80 RCX:
00007fcdf0d7522d
[ 9460.167361] RDX: 0000000000000023 RSI: 0000007b8c7ca228 RDI:
0000000000000010
[ 9460.167366] RBP: 0000000000000001 R08: 0000007b8c7c9270 R09:
000000000000002f
[ 9460.167371] R10: 0000007b8c7c9830 R11: 0000000000000293 R12:
0000007b8c7b88f0
[ 9460.167376] R13: 0000000000000000 R14: 0000000000000010 R15:
0000007b8c7b66b0
[ 9460.167387] INFO: task akonadi_maildis:7366 blocked for more than 120
seconds.
[ 9460.167492] Not tainted 4.12.0-pf7 #1
[ 9460.167496] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.167501] akonadi_maildis D 0 7366 7107 0x00000000
[ 9460.167507] Call Trace:
[ 9460.167516] __schedule+0x6e7/0xcd0
[ 9460.167525] schedule+0x3d/0xd0
[ 9460.167557] wait_log_commit+0xd6/0x100 [btrfs]
[ 9460.167564] ? wake_bit_function+0x60/0x60
[ 9460.167593] btrfs_sync_log+0x13e/0xad0 [btrfs]
[ 9460.167603] ? dput.part.24+0x51/0x1d0
[ 9460.167611] ? dput+0x13/0x20
[ 9460.167640] ? btrfs_log_dentry_safe+0x6a/0x80 [btrfs]
[ 9460.167670] btrfs_sync_file+0x2f4/0x3f0 [btrfs]
[ 9460.167696] ? btrfs_sync_file+0x2f4/0x3f0 [btrfs]
[ 9460.167705] vfs_fsync_range+0x4b/0xb0
[ 9460.167712] do_fsync+0x3d/0x70
[ 9460.167718] SyS_fdatasync+0x13/0x20
[ 9460.167727] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 9460.167733] RIP: 0033:0x7ff91da0822d
[ 9460.167737] RSP: 002b:00007ffdbded6fb0 EFLAGS: 00000293 ORIG_RAX:
000000000000004b
[ 9460.167744] RAX: ffffffffffffffda RBX: 000000841e8cc480 RCX:
00007ff91da0822d
[ 9460.167749] RDX: 0000000000000028 RSI: 000000841e902608 RDI:
000000000000000f
[ 9460.167754] RBP: 0000000000000001 R08: 000000841e8aff00 R09:
000000000000002f
[ 9460.167760] R10: 000000841e91a1d0 R11: 0000000000000293 R12:
000000841e910cc0
[ 9460.167764] R13: 0000000000000000 R14: 000000000000000f R15:
000000841e9165c0
[ 9460.167786] INFO: task chromium:7600 blocked for more than 120 seconds.
[ 9460.167791] Not tainted 4.12.0-pf7 #1
[ 9460.167796] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.167800] chromium D 0 7600 7020 0x00000000
[ 9460.167807] Call Trace:
[ 9460.167815] __schedule+0x6e7/0xcd0
[ 9460.167824] schedule+0x3d/0xd0
[ 9460.167831] io_schedule+0x16/0x40
[ 9460.167838] wait_on_page_bit+0xeb/0x130
[ 9460.167847] ? page_cache_tree_insert+0xc0/0xc0
[ 9460.167879] btrfs_page_mkwrite+0x1bf/0x400 [btrfs]
[ 9460.167889] do_page_mkwrite+0x31/0x90
[ 9460.167896] ? current_time+0x38/0x70
[ 9460.167905] do_wp_page+0x200/0x4b0
[ 9460.167911] ? file_update_time+0x60/0x110
[ 9460.167920] __handle_mm_fault+0x832/0xd50
[ 9460.167930] handle_mm_fault+0xde/0x220
[ 9460.167938] __do_page_fault+0x24d/0x510
[ 9460.167946] do_page_fault+0x22/0x30
[ 9460.167954] page_fault+0x28/0x30
[ 9460.167959] RIP: 0033:0x64de23cd9c
[ 9460.167964] RSP: 002b:00007ffdfd4ad4c0 EFLAGS: 00010202
[ 9460.167970] RAX: 00007f80a51b9d58 RBX: 0000398cef048700 RCX:
0000398ce8da6510
[ 9460.167982] RDX: 0000000000000006 RSI: 0000000000000000 RDI:
0000398cef048700
[ 9460.167988] RBP: 0000000000000005 R08: 0000000000000000 R09:
0000000000000000
[ 9460.167993] R10: 00007ffdfd4acdc0 R11: 0000000000000000 R12:
0000000000000001
[ 9460.168000] R13: 0000000000000005 R14: 00007ffdfd4ad908 R15:
0000000000000000
[ 9460.168014] INFO: task BrowserBlocking:7639 blocked for more than 120
seconds.
[ 9460.168019] Not tainted 4.12.0-pf7 #1
[ 9460.168024] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.168028] BrowserBlocking D 0 7639 7020 0x00000000
[ 9460.168035] Call Trace:
[ 9460.168044] __schedule+0x6e7/0xcd0
[ 9460.168054] schedule+0x3d/0xd0
[ 9460.168061] io_schedule+0x16/0x40
[ 9460.168068] wait_on_page_bit_common+0xe3/0x180
[ 9460.168076] ? page_cache_tree_insert+0xc0/0xc0
[ 9460.168083] __filemap_fdatawait_range+0x12a/0x1a0
[ 9460.168093] filemap_fdatawait_range+0x14/0x30
[ 9460.168128] btrfs_wait_ordered_range+0x6b/0x110 [btrfs]
[ 9460.168157] ? btrfs_fdatawrite_range+0x20/0x50 [btrfs]
[ 9460.168186] btrfs_sync_file+0x17c/0x3f0 [btrfs]
[ 9460.168195] vfs_fsync_range+0x4b/0xb0
[ 9460.168202] do_fsync+0x3d/0x70
[ 9460.168209] SyS_fdatasync+0x13/0x20
[ 9460.168218] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 9460.168223] RIP: 0033:0x7f80b8fcd22d
[ 9460.168228] RSP: 002b:00007f808c8b7680 EFLAGS: 00000293 ORIG_RAX:
000000000000004b
[ 9460.168235] RAX: ffffffffffffffda RBX: 00007f808c8b7670 RCX:
00007f80b8fcd22d
[ 9460.168240] RDX: 00000000000019bc RSI: 0000398cef877800 RDI:
0000000000000119
[ 9460.168246] RBP: 0000000000000119 R08: 0000000000000037 R09:
0000398ce88693c0
[ 9460.168251] R10: 0000000000000000 R11: 0000000000000293 R12:
00007f808c8b77d8
[ 9460.168257] R13: 0000398ceb6cf820 R14: 00000000000019bc R15:
0000398cef877800
[ 9460.168267] INFO: task Chrome_SyncThre:7867 blocked for more than 120
seconds.
[ 9460.168272] Not tainted 4.12.0-pf7 #1
[ 9460.168277] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.168282] Chrome_SyncThre D 0 7867 7020 0x00000000
[ 9460.168289] Call Trace:
[ 9460.168297] __schedule+0x6e7/0xcd0
[ 9460.168306] schedule+0x3d/0xd0
[ 9460.168338] wait_ordered_extents.isra.22.constprop.26+0x354/0x3d0 [btrfs]
[ 9460.168348] ? wake_bit_function+0x60/0x60
[ 9460.168377] btrfs_log_changed_extents+0x28a/0x620 [btrfs]
[ 9460.168412] ? release_extent_buffer+0x98/0xb0 [btrfs]
[ 9460.168444] btrfs_log_inode+0x97e/0x1140 [btrfs]
[ 9460.168668] btrfs_log_inode_parent+0x277/0xa30 [btrfs]
[ 9460.168676] ? touch_atime+0xc1/0xd0
[ 9460.168686] ? refcount_inc+0x9/0x30
[ 9460.168719] ? join_transaction+0x122/0x450 [btrfs]
[ 9460.168750] btrfs_log_dentry_safe+0x60/0x80 [btrfs]
[ 9460.168779] btrfs_sync_file+0x2b3/0x3f0 [btrfs]
[ 9460.168787] vfs_fsync_range+0x4b/0xb0
[ 9460.168794] do_fsync+0x3d/0x70
[ 9460.168801] SyS_fdatasync+0x13/0x20
[ 9460.168810] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 9460.168815] RIP: 0033:0x7f80b8fcd22d
[ 9460.168819] RSP: 002b:00007f80804e1720 EFLAGS: 00000293 ORIG_RAX:
000000000000004b
[ 9460.168826] RAX: ffffffffffffffda RBX: 0000000000008000 RCX:
00007f80b8fcd22d
[ 9460.168830] RDX: 0000000000000001 RSI: 0000000000000002 RDI:
00000000000000fb
[ 9460.168835] RBP: 0000398ce9e33000 R08: 0000398ced562800 R09:
0000000000000001
[ 9460.168840] R10: 0000000000018400 R11: 0000000000000293 R12:
00000000004b0000
[ 9460.168845] R13: 0000398ceac2ac78 R14: 0000398ce9e3b038 R15:
0000398ceb9a1048
[ 9460.168854] INFO: task BrowserBlocking:8011 blocked for more than 120
seconds.
[ 9460.168858] Not tainted 4.12.0-pf7 #1
[ 9460.168863] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.168867] BrowserBlocking D 0 8011 7020 0x00000000
[ 9460.168873] Call Trace:
[ 9460.168882] __schedule+0x6e7/0xcd0
[ 9460.168892] schedule+0x3d/0xd0
[ 9460.168898] io_schedule+0x16/0x40
[ 9460.168905] wait_on_page_bit_common+0xe3/0x180
[ 9460.168912] ? page_cache_tree_insert+0xc0/0xc0
[ 9460.168919] __filemap_fdatawait_range+0x12a/0x1a0
[ 9460.168929] filemap_fdatawait_range+0x14/0x30
[ 9460.168961] btrfs_wait_ordered_range+0x6b/0x110 [btrfs]
[ 9460.168989] ? btrfs_fdatawrite_range+0x20/0x50 [btrfs]
[ 9460.169015] btrfs_sync_file+0x17c/0x3f0 [btrfs]
[ 9460.169025] vfs_fsync_range+0x4b/0xb0
[ 9460.169033] do_fsync+0x3d/0x70
[ 9460.169040] SyS_fdatasync+0x13/0x20
[ 9460.169050] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 9460.169055] RIP: 0033:0x7f80b8fcd22d
[ 9460.169060] RSP: 002b:00007f807d5f1680 EFLAGS: 00000293 ORIG_RAX:
000000000000004b
[ 9460.169066] RAX: ffffffffffffffda RBX: 00007f807d5f1670 RCX:
00007f80b8fcd22d
[ 9460.169073] RDX: 000000000001f95c RSI: 0000398cece75000 RDI:
000000000000011d
[ 9460.169078] RBP: 000000000000011d R08: 000000000000003f R09:
0000398ce8870200
[ 9460.169083] R10: 0000000000000000 R11: 0000000000000293 R12:
00007f807d5f17d8
[ 9460.169088] R13: 0000398ceafb9160 R14: 000000000001f95c R15:
0000398cece75000
[ 9460.169098] INFO: task TaskSchedulerBa:9603 blocked for more than 120
seconds.
[ 9460.169103] Not tainted 4.12.0-pf7 #1
[ 9460.169108] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 9460.169113] TaskSchedulerBa D 0 9603 7020 0x00000000
[ 9460.169120] Call Trace:
[ 9460.169128] __schedule+0x6e7/0xcd0
[ 9460.169138] schedule+0x3d/0xd0
[ 9460.169166] wait_ordered_extents.isra.22.constprop.26+0x354/0x3d0 [btrfs]
[ 9460.169175] ? wake_bit_function+0x60/0x60
[ 9460.169204] btrfs_log_changed_extents+0x28a/0x620 [btrfs]
[ 9460.169237] ? release_extent_buffer+0x98/0xb0 [btrfs]
[ 9460.169265] btrfs_log_inode+0x97e/0x1140 [btrfs]
[ 9460.169278] ? __set_page_dirty_nobuffers+0x117/0x150
[ 9460.169310] ? btree_set_page_dirty+0xe/0x10 [btrfs]
[ 9460.169346] ? set_extent_buffer_dirty+0x7b/0xb0 [btrfs]
[ 9460.169378] btrfs_log_inode_parent+0x277/0xa30 [btrfs]
[ 9460.169386] ? touch_atime+0xc1/0xd0
[ 9460.169395] ? refcount_inc+0x9/0x30
[ 9460.169427] ? join_transaction+0x122/0x450 [btrfs]
[ 9460.169457] btrfs_log_dentry_safe+0x60/0x80 [btrfs]
[ 9460.169490] btrfs_sync_file+0x2b3/0x3f0 [btrfs]
[ 9460.169498] vfs_fsync_range+0x4b/0xb0
[ 9460.169505] do_fsync+0x3d/0x70
[ 9460.169512] SyS_fdatasync+0x13/0x20
[ 9460.169522] entry_SYSCALL_64_fastpath+0x1a/0xa5
[ 9460.169527] RIP: 0033:0x7f80b8fcd22d
[ 9460.169532] RSP: 002b:00007f80777ea2c0 EFLAGS: 00000293 ORIG_RAX:
000000000000004b
[ 9460.169541] RAX: ffffffffffffffda RBX: 0000398ce9546d90 RCX:
00007f80b8fcd22d
[ 9460.169546] RDX: 0000000000000001 RSI: 0000000000000002 RDI:
0000000000000117
[ 9460.169552] RBP: 0000000000000200 R08: 0000398ced6459c0 R09:
0000000000000001
[ 9460.169557] R10: 000000000000e400 R11: 0000000000000293 R12:
0000000000000001
[ 9460.169562] R13: 0000000000000015 R14: 0000000000000200 R15:
0000398ce9b50d80
===