On 13.11.2019 15:25, Oleksandr Natalenko wrote:
I didn't try to switch schedulers, but what I see now is once the
system is able to boot with BFQ, the I/O can still hang on I/O burst
(which for me happens to happen during VM reboot).
This may also not hang forever, but just slow down considerably. I've
noticed this inside a KVM VM, not on a real HW.
Possible call traces:
[ 179.107123] sysrq: Show Blocked State
[ 179.107127] task PC stack pid father
[ 179.107157] systemd-journal D 0 268 1 0x00000120
[ 179.107163] Call Trace:
[ 179.107177] ? __schedule+0x637/0x2af0
[ 179.107184] ? get_page_from_freelist+0x123d/0x2530
[ 179.107560] schedule+0x3e/0x140
[ 179.107568] schedule_timeout+0x354/0x4c0
[ 179.107576] __down+0x8a/0xe0
[ 179.107583] ? preempt_count_add+0x68/0xa0
[ 179.107702] ? xfs_buf_find.isra.0+0x447/0x730 [xfs]
[ 179.107709] down+0x3b/0x50
[ 179.107795] xfs_buf_lock+0x33/0x110 [xfs]
[ 179.107885] xfs_buf_find.isra.0+0x447/0x730 [xfs]
[ 179.108035] xfs_buf_get_map+0x4b/0x4d0 [xfs]
[ 179.108115] xfs_buf_read_map+0x28/0x180 [xfs]
[ 179.108205] xfs_trans_read_buf_map+0xaa/0x390 [xfs]
[ 179.108274] xfs_da_read_buf+0xf0/0x130 [xfs]
[ 179.108345] xfs_dir3_block_read+0x35/0x70 [xfs]
[ 179.108423] xfs_dir2_block_getdents+0xa7/0x280 [xfs]
[ 179.108503] xfs_readdir+0x113/0x1b0 [xfs]
[ 179.108512] iterate_dir+0x143/0x1a0
[ 179.108517] ksys_getdents64+0x9c/0x130
[ 179.108522] ? compat_filldir+0x180/0x180
[ 179.108527] __x64_sys_getdents64+0x16/0x20
[ 179.108533] do_syscall_64+0x4e/0x110
[ 179.108540] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 179.108546] RIP: 0033:0x7f3311baee3b
[ 179.108581] Code: Bad RIP value.
[ 179.108584] RSP: 002b:00007ffc60a3d6d8 EFLAGS: 00000293 ORIG_RAX:
00000000000000d9
[ 179.108588] RAX: ffffffffffffffda RBX: 000056021e9df880 RCX:
00007f3311baee3b
[ 179.108590] RDX: 0000000000008000 RSI: 000056021e9df8b0 RDI:
000000000000001a
[ 179.108592] RBP: 000056021e9df8b0 R08: 0000000000000030 R09:
00007f3311ca80e0
[ 179.108594] R10: 0000000000000000 R11: 0000000000000293 R12:
ffffffffffffff80
[ 179.108596] R13: 000056021e9df884 R14: 0000000000000000 R15:
00007ffc60a3e3f0
[ 179.108611] mkinitcpio D 0 375 374 0x00000084
[ 179.108616] Call Trace:
[ 179.108624] ? __schedule+0x637/0x2af0
[ 179.108643] schedule+0x3e/0x140
[ 179.108648] schedule_timeout+0x354/0x4c0
[ 179.108655] __down+0x8a/0xe0
[ 179.108661] ? preempt_count_add+0x68/0xa0
[ 179.108737] ? xfs_buf_find.isra.0+0x447/0x730 [xfs]
[ 179.108743] down+0x3b/0x50
[ 179.108820] xfs_buf_lock+0x33/0x110 [xfs]
[ 179.108913] xfs_buf_find.isra.0+0x447/0x730 [xfs]
[ 179.108992] xfs_buf_get_map+0x4b/0x4d0 [xfs]
[ 179.109000] ? get_page_from_freelist+0x123d/0x2530
[ 179.109077] xfs_buf_read_map+0x28/0x180 [xfs]
[ 179.109166] xfs_trans_read_buf_map+0xaa/0x390 [xfs]
[ 179.109239] xfs_iread+0xaf/0x220 [xfs]
[ 179.109322] xfs_iget+0x2f1/0xb80 [xfs]
[ 179.109391] ? xfs_dir_lookup+0x1bb/0x210 [xfs]
[ 179.109472] xfs_lookup+0x104/0x140 [xfs]
[ 179.109554] xfs_vn_lookup+0x82/0xc0 [xfs]
[ 179.109561] __lookup_slow+0x90/0x190
[ 179.109569] path_lookupat.isra.0+0x322/0x610
[ 179.109576] filename_lookup+0xc2/0x1d0
[ 179.109584] __se_sys_newstat+0x6c/0x100
[ 179.109593] do_syscall_64+0x4e/0x110
[ 179.109600] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 179.109604] RIP: 0033:0x7f8730e5b8da
[ 179.109610] Code: Bad RIP value.
[ 179.109612] RSP: 002b:00007ffe0505c378 EFLAGS: 00000246 ORIG_RAX:
0000000000000004
[ 179.109616] RAX: ffffffffffffffda RBX: 000055e2f87bd900 RCX:
00007f8730e5b8da
[ 179.109618] RDX: 00007ffe0505c3a0 RSI: 00007ffe0505c3a0 RDI:
000055e2f8800cc0
[ 179.109620] RBP: 0000000000000000 R08: 0000000000000001 R09:
0000000000000004
[ 179.109622] R10: 000055e2f8794f30 R11: 0000000000000246 R12:
0000000000000000
[ 179.109623] R13: 000055e2f8800cc0 R14: 000055e2f71c57f4 R15:
000055e2f88123e0
[ 87.069140] sysrq: Show Blocked State
[ 87.071749] task PC stack pid father
[ 87.073827] kworker/u2:3 D 0 220 2 0x80004000
[ 87.076330] Workqueue: writeback wb_workfn (flush-8:0)
[ 87.078086] Call Trace:
[ 87.079758] ? __schedule+0x637/0x2af0
[ 87.083061] schedule+0x3e/0x140
[ 87.084784] io_schedule+0x41/0x70
[ 87.086349] blk_mq_get_tag+0x119/0x250
[ 87.087503] ? bfq_timeout_sync_show+0x30/0x30
[ 87.090520] ? wait_woken+0x70/0x70
[ 87.093294] blk_mq_get_request+0x30a/0x410
[ 87.098519] blk_mq_make_request+0x15d/0x6f0
[ 87.101566] generic_make_request+0xf2/0x370
[ 87.103148] submit_bio+0x5f/0x180
[ 87.104538] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 87.106010] xfs_vm_writepages+0x73/0xa0 [xfs]
[ 87.107256] do_writepages+0x41/0x100
[ 87.108514] ? __switch_to_asm+0x34/0x70
[ 87.110591] ? __switch_to_asm+0x40/0x70
[ 87.112706] ? __switch_to_asm+0x34/0x70
[ 87.114931] ? __switch_to_asm+0x40/0x70
[ 87.117285] ? kvm_sched_clock_read+0x14/0x40
[ 87.120036] __writeback_single_inode+0x3d/0x3d0
[ 87.122671] ? psi_task_change+0x123/0x430
[ 87.124950] writeback_sb_inodes+0x20b/0x4a0
[ 87.127536] __writeback_inodes_wb+0x4c/0x140
[ 87.131212] wb_writeback+0x35c/0x410
[ 87.133642] ? set_worker_desc+0xc2/0xd0
[ 87.136088] ? soft_cursor+0x1a1/0x230
[ 87.138433] wb_workfn+0x46a/0x560
[ 87.140383] process_one_work+0x1e2/0x3b0
[ 87.142659] worker_thread+0x5c/0x480
[ 87.145952] kthread+0x131/0x170
[ 87.149337] ? rescuer_thread+0x4d0/0x4d0
[ 87.152348] ? kthread_park+0x80/0x80
[ 87.155309] ret_from_fork+0x35/0x40
[ 87.158352] kworker/u2:4 D 0 223 2 0x80004000
[ 87.164537] Workqueue: writeback wb_workfn (flush-8:0)
[ 87.168819] Call Trace:
[ 87.171101] ? __schedule+0x637/0x2af0
[ 87.174254] ? ktime_get+0x3c/0x90
[ 87.177114] ? _raw_spin_unlock_irq+0x1d/0x30
[ 87.180847] ? bfq_insert_requests+0x6a/0x11a0
[ 87.183894] ? preempt_count_add+0x30/0xa0
[ 87.187213] schedule+0x3e/0x140
[ 87.190310] io_schedule+0x41/0x70
[ 87.193559] blk_mq_get_tag+0x119/0x250
[ 87.197036] ? wait_woken+0x70/0x70
[ 87.200099] blk_mq_get_request+0x30a/0x410
[ 87.203252] blk_mq_make_request+0x15d/0x6f0
[ 87.206302] generic_make_request+0xf2/0x370
[ 87.209355] ? __test_set_page_writeback+0xfe/0x310
[ 87.213038] submit_bio+0x5f/0x180
[ 87.215431] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 87.219264] xfs_do_writepage+0x1c0/0x4f0 [xfs]
[ 87.223744] write_cache_pages+0x189/0x440
[ 87.227220] ? xfs_map_blocks+0x4c0/0x4c0 [xfs]
[ 87.230743] xfs_vm_writepages+0x62/0xa0 [xfs]
[ 87.233752] do_writepages+0x41/0x100
[ 87.236396] ? sched_clock_cpu+0x12/0x160
[ 87.239905] ? psi_task_change+0x123/0x430
[ 87.242949] __writeback_single_inode+0x3d/0x3d0
[ 87.245812] ? psi_task_change+0x123/0x430
[ 87.248885] writeback_sb_inodes+0x20b/0x4a0
[ 87.253396] __writeback_inodes_wb+0x4c/0x140
[ 87.256836] wb_writeback+0x35c/0x410
[ 87.259635] ? set_worker_desc+0xc2/0xd0
[ 87.262496] wb_workfn+0x46a/0x560
[ 87.265226] process_one_work+0x1e2/0x3b0
[ 87.268241] worker_thread+0x5c/0x480
[ 87.270966] kthread+0x131/0x170
[ 87.273225] ? rescuer_thread+0x4d0/0x4d0
[ 87.276163] ? kthread_park+0x80/0x80
[ 87.279137] ret_from_fork+0x35/0x40
[ 87.282813] kworker/u2:5 D 0 224 2 0x80004000
[ 87.286817] Workqueue: writeback wb_workfn (flush-8:0)
[ 87.290770] Call Trace:
[ 87.292773] ? __schedule+0x637/0x2af0
[ 87.295432] schedule+0x3e/0x140
[ 87.298187] io_schedule+0x41/0x70
[ 87.300723] blk_mq_get_tag+0x119/0x250
[ 87.303627] ? wait_woken+0x70/0x70
[ 87.306270] blk_mq_get_request+0x30a/0x410
[ 87.309216] blk_mq_make_request+0x15d/0x6f0
[ 87.313271] generic_make_request+0xf2/0x370
[ 87.317023] submit_bio+0x5f/0x180
[ 87.319899] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 87.323501] xfs_vm_writepages+0x73/0xa0 [xfs]
[ 87.326520] do_writepages+0x41/0x100
[ 87.329696] ? sched_clock_cpu+0x12/0x160
[ 87.332555] ? psi_task_change+0x123/0x430
[ 87.335264] __writeback_single_inode+0x3d/0x3d0
[ 87.338447] ? psi_task_change+0x123/0x430
[ 87.341905] writeback_sb_inodes+0x20b/0x4a0
[ 87.345393] __writeback_inodes_wb+0x4c/0x140
[ 87.348837] wb_writeback+0x35c/0x410
[ 87.351496] ? set_worker_desc+0xc2/0xd0
[ 87.354137] wb_workfn+0x46a/0x560
[ 87.355742] process_one_work+0x1e2/0x3b0
[ 87.357278] worker_thread+0x5c/0x480
[ 87.359015] kthread+0x131/0x170
[ 87.360477] ? rescuer_thread+0x4d0/0x4d0
[ 87.362015] ? kthread_park+0x80/0x80
[ 87.363473] ret_from_fork+0x35/0x40
[ 127.931979] sysrq: Show Blocked State
[ 127.943816] task PC stack pid father
[ 127.949588] kworker/u2:3 D 0 220 2 0x80004000
[ 127.954562] Workqueue: writeback wb_workfn (flush-8:0)
[ 127.971556] Call Trace:
[ 127.973746] ? __schedule+0x637/0x2af0
[ 127.975441] schedule+0x3e/0x140
[ 127.977002] io_schedule+0x41/0x70
[ 127.978949] blk_mq_get_tag+0x119/0x250
[ 127.981525] ? bfq_timeout_sync_show+0x30/0x30
[ 127.983861] ? wait_woken+0x70/0x70
[ 127.985772] blk_mq_get_request+0x30a/0x410
[ 127.990451] blk_mq_make_request+0x15d/0x6f0
[ 127.994248] generic_make_request+0xf2/0x370
[ 127.997879] submit_bio+0x5f/0x180
[ 128.000832] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 128.004644] xfs_vm_writepages+0x73/0xa0 [xfs]
[ 128.008598] do_writepages+0x41/0x100
[ 128.011564] ? __switch_to_asm+0x34/0x70
[ 128.014527] ? __switch_to_asm+0x40/0x70
[ 128.017547] ? __switch_to_asm+0x34/0x70
[ 128.022455] ? __switch_to_asm+0x40/0x70
[ 128.025836] ? kvm_sched_clock_read+0x14/0x40
[ 128.029223] __writeback_single_inode+0x3d/0x3d0
[ 128.032533] ? psi_task_change+0x123/0x430
[ 128.036069] writeback_sb_inodes+0x20b/0x4a0
[ 128.039544] __writeback_inodes_wb+0x4c/0x140
[ 128.042947] wb_writeback+0x35c/0x410
[ 128.046167] ? set_worker_desc+0xc2/0xd0
[ 128.049393] ? soft_cursor+0x1a1/0x230
[ 128.053427] wb_workfn+0x46a/0x560
[ 128.056444] process_one_work+0x1e2/0x3b0
[ 128.059854] worker_thread+0x5c/0x480
[ 128.062617] kthread+0x131/0x170
[ 128.065320] ? rescuer_thread+0x4d0/0x4d0
[ 128.068475] ? kthread_park+0x80/0x80
[ 128.071626] ret_from_fork+0x35/0x40
[ 128.074413] kworker/u2:4 D 0 223 2 0x80004000
[ 128.078421] Workqueue: writeback wb_workfn (flush-8:0)
[ 128.083873] Call Trace:
[ 128.086442] ? __schedule+0x637/0x2af0
[ 128.089844] ? ktime_get+0x3c/0x90
[ 128.092390] ? _raw_spin_unlock_irq+0x1d/0x30
[ 128.095769] ? bfq_insert_requests+0x6a/0x11a0
[ 128.099566] ? preempt_count_add+0x30/0xa0
[ 128.102368] schedule+0x3e/0x140
[ 128.104985] io_schedule+0x41/0x70
[ 128.107840] blk_mq_get_tag+0x119/0x250
[ 128.111122] ? wait_woken+0x70/0x70
[ 128.115268] blk_mq_get_request+0x30a/0x410
[ 128.118827] blk_mq_make_request+0x15d/0x6f0
[ 128.122513] generic_make_request+0xf2/0x370
[ 128.125688] ? __test_set_page_writeback+0xfe/0x310
[ 128.129481] submit_bio+0x5f/0x180
[ 128.132227] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 128.135979] xfs_do_writepage+0x1c0/0x4f0 [xfs]
[ 128.139147] write_cache_pages+0x189/0x440
[ 128.143406] ? xfs_map_blocks+0x4c0/0x4c0 [xfs]
[ 128.149176] xfs_vm_writepages+0x62/0xa0 [xfs]
[ 128.152721] do_writepages+0x41/0x100
[ 128.155683] ? sched_clock_cpu+0x12/0x160
[ 128.159142] ? psi_task_change+0x123/0x430
[ 128.162682] __writeback_single_inode+0x3d/0x3d0
[ 128.166272] ? psi_task_change+0x123/0x430
[ 128.169611] writeback_sb_inodes+0x20b/0x4a0
[ 128.174680] __writeback_inodes_wb+0x4c/0x140
[ 128.178400] wb_writeback+0x35c/0x410
[ 128.181249] ? set_worker_desc+0xc2/0xd0
[ 128.182963] wb_workfn+0x46a/0x560
[ 128.184508] process_one_work+0x1e2/0x3b0
[ 128.187977] worker_thread+0x5c/0x480
[ 128.191032] kthread+0x131/0x170
[ 128.194041] ? rescuer_thread+0x4d0/0x4d0
[ 128.197508] ? kthread_park+0x80/0x80
[ 128.200633] ret_from_fork+0x35/0x40
[ 128.204789] kworker/u2:5 D 0 224 2 0x80004000
[ 128.209060] Workqueue: writeback wb_workfn (flush-8:0)
[ 128.213110] Call Trace:
[ 128.215323] ? __schedule+0x637/0x2af0
[ 128.219244] schedule+0x3e/0x140
[ 128.223320] io_schedule+0x41/0x70
[ 128.231005] blk_mq_get_tag+0x119/0x250
[ 128.237796] ? wait_woken+0x70/0x70
[ 128.241028] blk_mq_get_request+0x30a/0x410
[ 128.244530] blk_mq_make_request+0x15d/0x6f0
[ 128.248292] generic_make_request+0xf2/0x370
[ 128.251900] submit_bio+0x5f/0x180
[ 128.255073] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 128.259151] xfs_vm_writepages+0x73/0xa0 [xfs]
[ 128.262690] do_writepages+0x41/0x100
[ 128.267082] ? sched_clock_cpu+0x12/0x160
[ 128.270697] ? psi_task_change+0x123/0x430
[ 128.274259] __writeback_single_inode+0x3d/0x3d0
[ 128.278024] ? psi_task_change+0x123/0x430
[ 128.281327] writeback_sb_inodes+0x20b/0x4a0
[ 128.284777] __writeback_inodes_wb+0x4c/0x140
[ 128.288677] wb_writeback+0x35c/0x410
[ 128.291625] ? set_worker_desc+0xc2/0xd0
[ 128.296076] wb_workfn+0x46a/0x560
[ 128.299680] process_one_work+0x1e2/0x3b0
[ 128.303163] worker_thread+0x5c/0x480
[ 128.306144] kthread+0x131/0x170
[ 128.309172] ? rescuer_thread+0x4d0/0x4d0
[ 128.312615] ? kthread_park+0x80/0x80
[ 128.315576] ret_from_fork+0x35/0x40
[ 128.318582] xfsaild/sda2 D 0 244 2 0x80004000
[ 128.322561] Call Trace:
[ 128.326085] ? __schedule+0x637/0x2af0
[ 128.329795] ? __bfq_deactivate_entity+0x19a/0x2b0
[ 128.333728] schedule+0x3e/0x140
[ 128.336164] io_schedule+0x41/0x70
[ 128.339493] blk_mq_get_tag+0x119/0x250
[ 128.342546] ? wait_woken+0x70/0x70
[ 128.346479] blk_mq_get_request+0x30a/0x410
[ 128.351602] blk_mq_make_request+0x15d/0x6f0
[ 128.354611] generic_make_request+0xf2/0x370
[ 128.359399] submit_bio+0x5f/0x180
[ 128.363135] _xfs_buf_ioapply+0x2b8/0x430 [xfs]
[ 128.369007] __xfs_buf_submit+0x82/0x1f0 [xfs]
[ 128.376663] xfs_buf_delwri_submit_buffers+0x109/0x260 [xfs]
[ 128.379223] ? xfsaild+0x3f0/0x8d0 [xfs]
[ 128.382396] xfsaild+0x3f0/0x8d0 [xfs]
[ 128.384589] kthread+0x131/0x170
[ 128.387601] ? xfs_trans_ail_cursor_clear+0x40/0x40 [xfs]
[ 128.391164] ? kthread_park+0x80/0x80
[ 128.401195] ret_from_fork+0x35/0x40
[ 234.904047] sysrq: Show Blocked State
[ 234.908142] task PC stack pid father
[ 234.911166] kworker/u2:3 D 0 220 2 0x80004000
[ 234.915348] Workqueue: writeback wb_workfn (flush-8:0)
[ 234.917924] Call Trace:
[ 234.920610] ? __schedule+0x637/0x2af0
[ 234.924304] schedule+0x3e/0x140
[ 234.927397] io_schedule+0x41/0x70
[ 234.934576] blk_mq_get_tag+0x119/0x250
[ 234.940699] ? bfq_timeout_sync_show+0x30/0x30
[ 234.942674] ? wait_woken+0x70/0x70
[ 234.945013] blk_mq_get_request+0x30a/0x410
[ 234.946858] blk_mq_make_request+0x15d/0x6f0
[ 234.949202] generic_make_request+0xf2/0x370
[ 234.951035] submit_bio+0x5f/0x180
[ 234.952663] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 234.954829] xfs_vm_writepages+0x73/0xa0 [xfs]
[ 234.957084] do_writepages+0x41/0x100
[ 234.960939] ? __switch_to_asm+0x34/0x70
[ 234.963202] ? __switch_to_asm+0x40/0x70
[ 234.964921] ? __switch_to_asm+0x34/0x70
[ 234.967063] ? __switch_to_asm+0x40/0x70
[ 234.968989] ? kvm_sched_clock_read+0x14/0x40
[ 234.970810] __writeback_single_inode+0x3d/0x3d0
[ 234.972835] ? psi_task_change+0x123/0x430
[ 234.976112] writeback_sb_inodes+0x20b/0x4a0
[ 234.978133] __writeback_inodes_wb+0x4c/0x140
[ 234.979943] wb_writeback+0x35c/0x410
[ 234.981742] ? set_worker_desc+0xc2/0xd0
[ 234.983428] ? soft_cursor+0x1a1/0x230
[ 234.985088] wb_workfn+0x46a/0x560
[ 234.986629] process_one_work+0x1e2/0x3b0
[ 234.990135] worker_thread+0x5c/0x480
[ 234.991870] kthread+0x131/0x170
[ 234.993523] ? rescuer_thread+0x4d0/0x4d0
[ 234.995287] ? kthread_park+0x80/0x80
[ 234.996971] ret_from_fork+0x35/0x40
[ 234.998827] kworker/u2:4 D 0 223 2 0x80004000
[ 235.001159] Workqueue: writeback wb_workfn (flush-8:0)
[ 235.003167] Call Trace:
[ 235.004605] ? __schedule+0x637/0x2af0
[ 235.006286] ? ktime_get+0x3c/0x90
[ 235.008191] ? _raw_spin_unlock_irq+0x1d/0x30
[ 235.010088] ? bfq_insert_requests+0x6a/0x11a0
[ 235.011891] ? preempt_count_add+0x30/0xa0
[ 235.013966] schedule+0x3e/0x140
[ 235.015705] io_schedule+0x41/0x70
[ 235.017234] blk_mq_get_tag+0x119/0x250
[ 235.022331] ? wait_woken+0x70/0x70
[ 235.027501] blk_mq_get_request+0x30a/0x410
[ 235.030930] blk_mq_make_request+0x15d/0x6f0
[ 235.034333] generic_make_request+0xf2/0x370
[ 235.038096] ? __test_set_page_writeback+0xfe/0x310
[ 235.042030] submit_bio+0x5f/0x180
[ 235.044645] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 235.047883] xfs_do_writepage+0x1c0/0x4f0 [xfs]
[ 235.053087] write_cache_pages+0x189/0x440
[ 235.056560] ? xfs_map_blocks+0x4c0/0x4c0 [xfs]
[ 235.060329] xfs_vm_writepages+0x62/0xa0 [xfs]
[ 235.064731] do_writepages+0x41/0x100
[ 235.067990] ? sched_clock_cpu+0x12/0x160
[ 235.071178] ? psi_task_change+0x123/0x430
[ 235.074144] __writeback_single_inode+0x3d/0x3d0
[ 235.078489] ? psi_task_change+0x123/0x430
[ 235.082597] writeback_sb_inodes+0x20b/0x4a0
[ 235.085988] __writeback_inodes_wb+0x4c/0x140
[ 235.089749] wb_writeback+0x35c/0x410
[ 235.092620] ? set_worker_desc+0xc2/0xd0
[ 235.096787] wb_workfn+0x46a/0x560
[ 235.099600] process_one_work+0x1e2/0x3b0
[ 235.103916] worker_thread+0x5c/0x480
[ 235.107162] kthread+0x131/0x170
[ 235.118469] ? rescuer_thread+0x4d0/0x4d0
[ 235.123893] ? kthread_park+0x80/0x80
[ 235.125617] ret_from_fork+0x35/0x40
[ 235.127317] kworker/u2:5 D 0 224 2 0x80004000
[ 235.130068] Workqueue: writeback wb_workfn (flush-8:0)
[ 235.132098] Call Trace:
[ 235.133579] ? __schedule+0x637/0x2af0
[ 235.135252] schedule+0x3e/0x140
[ 235.136942] io_schedule+0x41/0x70
[ 235.138752] blk_mq_get_tag+0x119/0x250
[ 235.141176] ? wait_woken+0x70/0x70
[ 235.142816] blk_mq_get_request+0x30a/0x410
[ 235.144816] blk_mq_make_request+0x15d/0x6f0
[ 235.146681] generic_make_request+0xf2/0x370
[ 235.150292] submit_bio+0x5f/0x180
[ 235.153366] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 235.157466] xfs_vm_writepages+0x73/0xa0 [xfs]
[ 235.161099] do_writepages+0x41/0x100
[ 235.164213] ? sched_clock_cpu+0x12/0x160
[ 235.167558] ? psi_task_change+0x123/0x430
[ 235.174031] __writeback_single_inode+0x3d/0x3d0
[ 235.178426] ? psi_task_change+0x123/0x430
[ 235.183123] writeback_sb_inodes+0x20b/0x4a0
[ 235.199636] __writeback_inodes_wb+0x4c/0x140
[ 235.205597] wb_writeback+0x35c/0x410
[ 235.217907] ? set_worker_desc+0xc2/0xd0
[ 235.219695] wb_workfn+0x46a/0x560
[ 235.221599] process_one_work+0x1e2/0x3b0
[ 235.224343] worker_thread+0x5c/0x480
[ 235.225978] kthread+0x131/0x170
[ 235.228234] ? rescuer_thread+0x4d0/0x4d0
[ 235.229958] ? kthread_park+0x80/0x80
[ 235.231578] ret_from_fork+0x35/0x40
[ 235.233324] xfsaild/sda2 D 0 244 2 0x80004000
[ 235.238349] Call Trace:
[ 235.240383] ? __schedule+0x637/0x2af0
[ 235.242182] ? __bfq_deactivate_entity+0x19a/0x2b0
[ 235.248196] schedule+0x3e/0x140
[ 235.250080] io_schedule+0x41/0x70
[ 235.252931] blk_mq_get_tag+0x119/0x250
[ 235.254804] ? wait_woken+0x70/0x70
[ 235.256396] blk_mq_get_request+0x30a/0x410
[ 235.262031] blk_mq_make_request+0x15d/0x6f0
[ 235.271989] generic_make_request+0xf2/0x370
[ 235.275119] submit_bio+0x5f/0x180
[ 235.277055] _xfs_buf_ioapply+0x2b8/0x430 [xfs]
[ 235.279084] __xfs_buf_submit+0x82/0x1f0 [xfs]
[ 235.281404] xfs_buf_delwri_submit_buffers+0x109/0x260 [xfs]
[ 235.283550] ? xfsaild+0x3f0/0x8d0 [xfs]
[ 235.285351] xfsaild+0x3f0/0x8d0 [xfs]
[ 235.287060] kthread+0x131/0x170
[ 235.290535] ? xfs_trans_ail_cursor_clear+0x40/0x40 [xfs]
[ 235.292775] ? kthread_park+0x80/0x80
[ 235.296030] ret_from_fork+0x35/0x40
[ 246.488123] INFO: task kworker/u2:3:220 blocked for more than 122
seconds.
[ 246.595672] Not tainted 5.3.0-pf7 #1
[ 246.602133] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 246.611323] kworker/u2:3 D 0 220 2 0x80004000
[ 246.616858] Workqueue: writeback wb_workfn (flush-8:0)
[ 246.623147] Call Trace:
[ 246.625763] ? __schedule+0x637/0x2af0
[ 246.627530] schedule+0x3e/0x140
[ 246.629607] io_schedule+0x41/0x70
[ 246.631407] blk_mq_get_tag+0x119/0x250
[ 246.633226] ? bfq_timeout_sync_show+0x30/0x30
[ 246.635814] ? wait_woken+0x70/0x70
[ 246.643587] blk_mq_get_request+0x30a/0x410
[ 246.647362] blk_mq_make_request+0x15d/0x6f0
[ 246.654491] generic_make_request+0xf2/0x370
[ 246.656568] submit_bio+0x5f/0x180
[ 246.658388] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 246.660772] xfs_vm_writepages+0x73/0xa0 [xfs]
[ 246.663464] do_writepages+0x41/0x100
[ 246.665259] ? __switch_to_asm+0x34/0x70
[ 246.667069] ? __switch_to_asm+0x40/0x70
[ 246.669581] ? __switch_to_asm+0x34/0x70
[ 246.671963] ? __switch_to_asm+0x40/0x70
[ 246.674022] ? kvm_sched_clock_read+0x14/0x40
[ 246.679684] __writeback_single_inode+0x3d/0x3d0
[ 246.709238] ? psi_task_change+0x123/0x430
[ 246.711444] writeback_sb_inodes+0x20b/0x4a0
[ 246.714632] __writeback_inodes_wb+0x4c/0x140
[ 246.718981] wb_writeback+0x35c/0x410
[ 246.725222] ? set_worker_desc+0xc2/0xd0
[ 246.728123] ? soft_cursor+0x1a1/0x230
[ 246.744090] wb_workfn+0x46a/0x560
[ 246.750812] process_one_work+0x1e2/0x3b0
[ 246.760162] worker_thread+0x5c/0x480
[ 246.761914] kthread+0x131/0x170
[ 246.763468] ? rescuer_thread+0x4d0/0x4d0
[ 246.766006] ? kthread_park+0x80/0x80
[ 246.767865] ret_from_fork+0x35/0x40
[ 246.769640] INFO: task kworker/u2:4:223 blocked for more than 123
seconds.
[ 246.772517] Not tainted 5.3.0-pf7 #1
[ 246.775114] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 246.779903] kworker/u2:4 D 0 223 2 0x80004000
[ 246.784611] Workqueue: writeback wb_workfn (flush-8:0)
[ 246.788280] Call Trace:
[ 246.790041] ? __schedule+0x637/0x2af0
[ 246.796877] ? ktime_get+0x3c/0x90
[ 246.802957] ? _raw_spin_unlock_irq+0x1d/0x30
[ 246.807930] ? bfq_insert_requests+0x6a/0x11a0
[ 246.812064] ? preempt_count_add+0x30/0xa0
[ 246.819097] schedule+0x3e/0x140
[ 246.821859] io_schedule+0x41/0x70
[ 246.825235] blk_mq_get_tag+0x119/0x250
[ 246.828659] ? wait_woken+0x70/0x70
[ 246.836064] blk_mq_get_request+0x30a/0x410
[ 246.848237] blk_mq_make_request+0x15d/0x6f0
[ 246.857921] generic_make_request+0xf2/0x370
[ 246.861569] ? __test_set_page_writeback+0xfe/0x310
[ 246.865759] submit_bio+0x5f/0x180
[ 246.868518] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 246.874268] xfs_do_writepage+0x1c0/0x4f0 [xfs]
[ 246.878794] write_cache_pages+0x189/0x440
[ 246.882209] ? xfs_map_blocks+0x4c0/0x4c0 [xfs]
[ 246.884118] xfs_vm_writepages+0x62/0xa0 [xfs]
[ 246.886729] do_writepages+0x41/0x100
[ 246.888570] ? sched_clock_cpu+0x12/0x160
[ 246.890648] ? psi_task_change+0x123/0x430
[ 246.898729] __writeback_single_inode+0x3d/0x3d0
[ 246.907282] ? psi_task_change+0x123/0x430
[ 246.909678] writeback_sb_inodes+0x20b/0x4a0
[ 246.911499] __writeback_inodes_wb+0x4c/0x140
[ 246.913324] wb_writeback+0x35c/0x410
[ 246.916341] ? set_worker_desc+0xc2/0xd0
[ 246.919498] wb_workfn+0x46a/0x560
[ 246.922393] process_one_work+0x1e2/0x3b0
[ 246.925693] worker_thread+0x5c/0x480
[ 246.929221] kthread+0x131/0x170
[ 246.936731] ? rescuer_thread+0x4d0/0x4d0
[ 246.946022] ? kthread_park+0x80/0x80
[ 246.949593] ret_from_fork+0x35/0x40
[ 246.952716] INFO: task kworker/u2:5:224 blocked for more than 123
seconds.
[ 246.958132] Not tainted 5.3.0-pf7 #1
[ 246.961479] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 246.968379] kworker/u2:5 D 0 224 2 0x80004000
[ 246.981073] Workqueue: writeback wb_workfn (flush-8:0)
[ 246.986238] Call Trace:
[ 246.988832] ? __schedule+0x637/0x2af0
[ 246.992416] schedule+0x3e/0x140
[ 246.995232] io_schedule+0x41/0x70
[ 246.998399] blk_mq_get_tag+0x119/0x250
[ 247.001661] ? wait_woken+0x70/0x70
[ 247.006540] blk_mq_get_request+0x30a/0x410
[ 247.010153] blk_mq_make_request+0x15d/0x6f0
[ 247.020215] generic_make_request+0xf2/0x370
[ 247.024701] submit_bio+0x5f/0x180
[ 247.027620] xfs_submit_ioend.isra.0+0x85/0x160 [xfs]
[ 247.031863] xfs_vm_writepages+0x73/0xa0 [xfs]
[ 247.036968] do_writepages+0x41/0x100
[ 247.040347] ? sched_clock_cpu+0x12/0x160
[ 247.044046] ? psi_task_change+0x123/0x430
[ 247.047533] __writeback_single_inode+0x3d/0x3d0
[ 247.051963] ? psi_task_change+0x123/0x430
[ 247.063498] writeback_sb_inodes+0x20b/0x4a0
[ 247.068234] __writeback_inodes_wb+0x4c/0x140
[ 247.072366] wb_writeback+0x35c/0x410
[ 247.075423] ? set_worker_desc+0xc2/0xd0
[ 247.078859] wb_workfn+0x46a/0x560
[ 247.082140] process_one_work+0x1e2/0x3b0
[ 247.086447] worker_thread+0x5c/0x480
[ 247.089657] kthread+0x131/0x170
[ 247.101209] ? rescuer_thread+0x4d0/0x4d0
[ 247.105680] ? kthread_park+0x80/0x80
[ 247.109483] ret_from_fork+0x35/0x40
--
Oleksandr Natalenko (post-factum)
