> Il giorno 13 feb 2018, alle ore 07:50, Mike Galbraith <efault@xxxxxx> ha scritto: > > Oops, meant to provide the dmesg spew. > > [ 1954.780829] INFO: task kworker/7:2:290 blocked for more than 480 seconds. > [ 1954.780837] Tainted: G E 4.15.3-smp #8 > [ 1954.780839] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.780843] kworker/7:2 D 0 290 2 0x80000000 > [ 1954.780858] Workqueue: events_freezable_power_ disk_events_workfn > [ 1954.780862] Call Trace: > [ 1954.780876] ? __schedule+0x268/0x840 > [ 1954.780883] schedule+0x32/0x80 > [ 1954.780891] io_schedule+0x12/0x40 > [ 1954.780896] blk_mq_get_tag+0x11e/0x230 > [ 1954.780902] ? blk_mq_sched_dispatch_requests+0x108/0x180 > [ 1954.780910] ? remove_wait_queue+0x60/0x60 > [ 1954.780920] blk_mq_get_request+0xcc/0x340 > [ 1954.780927] blk_mq_alloc_request+0x5a/0xa0 > [ 1954.780933] blk_get_request_flags+0x44/0x170 > [ 1954.780955] scsi_execute+0x38/0x1e0 [scsi_mod] > [ 1954.780971] scsi_test_unit_ready+0x9c/0xe0 [scsi_mod] > [ 1954.780981] sd_check_events+0xf7/0x170 [sd_mod] > [ 1954.780988] disk_check_events+0x55/0x120 > [ 1954.780997] process_one_work+0x147/0x350 > [ 1954.781003] worker_thread+0x47/0x3e0 > [ 1954.781009] kthread+0xf8/0x130 > [ 1954.781015] ? rescuer_thread+0x360/0x360 > [ 1954.781019] ? kthread_stop+0x120/0x120 > [ 1954.781025] ret_from_fork+0x35/0x40 > [ 1954.781033] INFO: task kworker/u16:6:540 blocked for more than 480 seconds. > [ 1954.781037] Tainted: G E 4.15.3-smp #8 > [ 1954.781039] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.781042] kworker/u16:6 D 0 540 2 0x80000000 > [ 1954.781053] Workqueue: writeback wb_workfn (flush-8:48) > [ 1954.781057] Call Trace: > [ 1954.781064] ? __schedule+0x268/0x840 > [ 1954.781071] schedule+0x32/0x80 > [ 1954.781076] io_schedule+0x12/0x40 > [ 1954.781081] blk_mq_get_tag+0x11e/0x230 > [ 1954.781087] ? remove_wait_queue+0x60/0x60 > [ 1954.781094] blk_mq_get_request+0xcc/0x340 > [ 1954.781099] blk_mq_make_request+0xf8/0x580 > [ 1954.781105] generic_make_request+0xfd/0x2d0 > [ 1954.781110] submit_bio+0x5e/0x120 > [ 1954.781151] ext4_io_submit+0x48/0x60 [ext4] > [ 1954.781178] ext4_bio_write_page+0x199/0x3a0 [ext4] > [ 1954.781202] mpage_submit_page+0x51/0x70 [ext4] > [ 1954.781223] mpage_map_and_submit_buffers+0x109/0x1d0 [ext4] > [ 1954.781248] ext4_writepages+0x831/0xe50 [ext4] > [ 1954.781255] ? bfq_deactivate_entity+0x21/0x50 > [ 1954.781263] ? cpumask_next_and+0x2b/0x40 > [ 1954.781272] do_writepages+0x1a/0x70 > [ 1954.781279] __writeback_single_inode+0x3d/0x340 > [ 1954.781286] writeback_sb_inodes+0x21f/0x4c0 > [ 1954.781294] __writeback_inodes_wb+0x87/0xb0 > [ 1954.781300] wb_writeback+0x258/0x2f0 > [ 1954.781306] ? cpumask_next+0x16/0x20 > [ 1954.781313] wb_workfn+0x2f0/0x400 > [ 1954.781319] process_one_work+0x147/0x350 > [ 1954.781325] worker_thread+0x47/0x3e0 > [ 1954.781330] kthread+0xf8/0x130 > [ 1954.781336] ? rescuer_thread+0x360/0x360 > [ 1954.781340] ? kthread_stop+0x120/0x120 > [ 1954.781345] ret_from_fork+0x35/0x40 > [ 1954.781356] INFO: task jbd2/sdd1-8:1170 blocked for more than 480 seconds. > [ 1954.781359] Tainted: G E 4.15.3-smp #8 > [ 1954.781361] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.781364] jbd2/sdd1-8 D 0 1170 2 0x80000000 > [ 1954.781368] Call Trace: > [ 1954.781375] ? __schedule+0x268/0x840 > [ 1954.781381] ? __wake_up_common_lock+0x77/0x90 > [ 1954.781387] schedule+0x32/0x80 > [ 1954.781401] jbd2_journal_commit_transaction+0x262/0x1b50 [jbd2] > [ 1954.781409] ? rb_erase_cached+0x31b/0x390 > [ 1954.781415] ? pick_next_task_fair+0x58d/0x8c0 > [ 1954.781424] ? __switch_to+0x98/0x3f0 > [ 1954.781430] ? remove_wait_queue+0x60/0x60 > [ 1954.781441] kjournald2+0xb1/0x230 [jbd2] > [ 1954.781447] ? remove_wait_queue+0x60/0x60 > [ 1954.781452] kthread+0xf8/0x130 > [ 1954.781460] ? commit_timeout+0x10/0x10 [jbd2] > [ 1954.781464] ? kthread_stop+0x120/0x120 > [ 1954.781469] ret_from_fork+0x35/0x40 > [ 1954.781493] INFO: task pool:19922 blocked for more than 480 seconds. > [ 1954.781498] Tainted: G E 4.15.3-smp #8 > [ 1954.781502] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.781506] pool D 0 19922 1 0x00000000 > [ 1954.781512] Call Trace: > [ 1954.781520] ? __schedule+0x268/0x840 > [ 1954.781526] schedule+0x32/0x80 > [ 1954.781531] schedule_timeout+0x1d2/0x2e0 > [ 1954.781538] wait_for_completion+0xff/0x160 > [ 1954.781543] ? wake_up_q+0x70/0x70 > [ 1954.781549] flush_work+0x109/0x180 > [ 1954.781554] ? wake_up_worker+0x30/0x30 > [ 1954.781560] __cancel_work_timer+0xe3/0x160 > [ 1954.781569] ? kobj_lookup+0x111/0x160 > [ 1954.781574] ? disk_map_sector_rcu+0x70/0x70 > [ 1954.781580] disk_block_events+0x6f/0x90 > [ 1954.781587] __blkdev_get+0x5a/0x470 > [ 1954.781592] ? bd_acquire+0xd0/0xd0 > [ 1954.781597] blkdev_get+0x195/0x2e0 > [ 1954.781605] ? __inode_permission+0x2d/0x110 > [ 1954.781609] ? bd_acquire+0x37/0xd0 > [ 1954.781613] ? bd_acquire+0xd0/0xd0 > [ 1954.781619] do_dentry_open.isra.20+0x1ee/0x300 > [ 1954.781625] path_openat+0x28a/0x1050 > [ 1954.781631] do_filp_open+0x7e/0xd0 > [ 1954.781640] ? read_null+0x10/0x10 > [ 1954.781646] ? _cond_resched+0x15/0x30 > [ 1954.781653] do_sys_open+0x116/0x1e0 > [ 1954.781659] do_syscall_64+0x75/0x1a0 > [ 1954.781665] entry_SYSCALL_64_after_hwframe+0x21/0x86 > [ 1954.781670] RIP: 0033:0x7f81a021d44d > [ 1954.781673] RSP: 002b:00007f819d542b30 EFLAGS: 00000293 ORIG_RAX: 0000000000000002 > [ 1954.781679] RAX: ffffffffffffffda RBX: 000000000234b0c0 RCX: 00007f81a021d44d > [ 1954.781682] RDX: 00007f819fc62f03 RSI: 0000000000000800 RDI: 00000000023606b0 > [ 1954.781685] RBP: 00007f8190011ec0 R08: 0000000000000073 R09: 0000000000000003 > [ 1954.781689] R10: 0000000000000000 R11: 0000000000000293 R12: 00007f819d542cc8 > [ 1954.781692] R13: 00007f819d542bf0 R14: 00007f8190011ec0 R15: 0000000000000001 > [ 1954.781735] INFO: task gcc:19633 blocked for more than 480 seconds. > [ 1954.781738] Tainted: G E 4.15.3-smp #8 > [ 1954.781741] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.781743] gcc D 0 19633 19632 0x00000000 > [ 1954.781748] Call Trace: > [ 1954.781755] ? __schedule+0x268/0x840 > [ 1954.781761] schedule+0x32/0x80 > [ 1954.781766] io_schedule+0x12/0x40 > [ 1954.781771] blk_mq_get_tag+0x11e/0x230 > [ 1954.781779] ? elv_merge+0x66/0xe0 > [ 1954.781786] ? remove_wait_queue+0x60/0x60 > [ 1954.781796] blk_mq_get_request+0xcc/0x340 > [ 1954.781803] blk_mq_make_request+0xf8/0x580 > [ 1954.781810] generic_make_request+0xfd/0x2d0 > [ 1954.781815] submit_bio+0x5e/0x120 > [ 1954.781835] ? __ext4_journal_stop+0x37/0xa0 [ext4] > [ 1954.781857] ext4_io_submit+0x48/0x60 [ext4] > [ 1954.781878] ext4_writepages+0x64a/0xe50 [ext4] > [ 1954.781888] do_writepages+0x1a/0x70 > [ 1954.781893] __filemap_fdatawrite_range+0x71/0x90 > [ 1954.781915] ext4_rename+0x600/0x830 [ext4] > [ 1954.781923] ? legitimize_path.isra.54+0x28/0x50 > [ 1954.781929] ? terminate_walk+0x55/0xb0 > [ 1954.781935] vfs_rename+0x1df/0x6d0 > [ 1954.781942] ? __d_lookup+0x111/0x130 > [ 1954.781948] SyS_rename+0x325/0x390 > [ 1954.781954] do_syscall_64+0x75/0x1a0 > [ 1954.781960] entry_SYSCALL_64_after_hwframe+0x21/0x86 > [ 1954.781964] RIP: 0033:0x147b429b7a67 > [ 1954.781967] RSP: 002b:00007ffca7063be8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 > [ 1954.781971] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 0000147b429b7a67 > [ 1954.781975] RDX: 0000000000000000 RSI: 000000000212e200 RDI: 000000000212f1c0 > [ 1954.781978] RBP: 000000000211a390 R08: 000000000212f310 R09: 0000147b433d4700 > [ 1954.781981] R10: 0000000000000000 R11: 0000000000000202 R12: 000000000212f230 > [ 1954.781984] R13: 000000000212e200 R14: 0000000000000000 R15: 0000000000000006 > [ 1954.781990] INFO: task gcc:19651 blocked for more than 480 seconds. > [ 1954.781993] Tainted: G E 4.15.3-smp #8 > [ 1954.781995] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.781998] gcc D 0 19651 19649 0x00000000 > [ 1954.782002] Call Trace: > [ 1954.782008] ? __schedule+0x268/0x840 > [ 1954.782014] schedule+0x32/0x80 > [ 1954.782020] io_schedule+0x12/0x40 > [ 1954.782025] blk_mq_get_tag+0x11e/0x230 > [ 1954.782030] ? elv_merge+0x66/0xe0 > [ 1954.782036] ? remove_wait_queue+0x60/0x60 > [ 1954.782042] blk_mq_get_request+0xcc/0x340 > [ 1954.782047] blk_mq_make_request+0xf8/0x580 > [ 1954.782053] generic_make_request+0xfd/0x2d0 > [ 1954.782058] submit_bio+0x5e/0x120 > [ 1954.782076] ? __ext4_journal_stop+0x37/0xa0 [ext4] > [ 1954.782095] ext4_io_submit+0x48/0x60 [ext4] > [ 1954.782114] ext4_writepages+0x64a/0xe50 [ext4] > [ 1954.782123] do_writepages+0x1a/0x70 > [ 1954.782128] __filemap_fdatawrite_range+0x71/0x90 > [ 1954.782147] ext4_rename+0x600/0x830 [ext4] > [ 1954.782154] ? legitimize_path.isra.54+0x28/0x50 > [ 1954.782160] ? terminate_walk+0x55/0xb0 > [ 1954.782165] vfs_rename+0x1df/0x6d0 > [ 1954.782172] ? __d_lookup+0x111/0x130 > [ 1954.782177] SyS_rename+0x325/0x390 > [ 1954.782183] do_syscall_64+0x75/0x1a0 > [ 1954.782188] entry_SYSCALL_64_after_hwframe+0x21/0x86 > [ 1954.782192] RIP: 0033:0x146b9f33ca67 > [ 1954.782194] RSP: 002b:00007fffe33828b8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 > [ 1954.782199] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 0000146b9f33ca67 > [ 1954.782202] RDX: 0000000000000000 RSI: 000000000233b910 RDI: 000000000233c110 > [ 1954.782205] RBP: 000000000232a390 R08: 000000000233c260 R09: 0000146b9fd59700 > [ 1954.782208] R10: 0000000000000000 R11: 0000000000000202 R12: 000000000233c180 > [ 1954.782211] R13: 000000000233b910 R14: 0000000000000000 R15: 0000000000000006 > [ 1954.782217] INFO: task gcc:19683 blocked for more than 480 seconds. > [ 1954.782220] Tainted: G E 4.15.3-smp #8 > [ 1954.782222] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.782225] gcc D 0 19683 19682 0x00000000 > [ 1954.782229] Call Trace: > [ 1954.782236] ? __schedule+0x268/0x840 > [ 1954.782242] schedule+0x32/0x80 > [ 1954.782247] io_schedule+0x12/0x40 > [ 1954.782252] blk_mq_get_tag+0x11e/0x230 > [ 1954.782257] ? elv_merge+0x66/0xe0 > [ 1954.782262] ? remove_wait_queue+0x60/0x60 > [ 1954.782269] blk_mq_get_request+0xcc/0x340 > [ 1954.782274] blk_mq_make_request+0xf8/0x580 > [ 1954.782279] generic_make_request+0xfd/0x2d0 > [ 1954.782284] submit_bio+0x5e/0x120 > [ 1954.782302] ? __ext4_journal_stop+0x37/0xa0 [ext4] > [ 1954.782320] ext4_io_submit+0x48/0x60 [ext4] > [ 1954.782338] ext4_writepages+0x64a/0xe50 [ext4] > [ 1954.782347] do_writepages+0x1a/0x70 > [ 1954.782352] __filemap_fdatawrite_range+0x71/0x90 > [ 1954.782370] ext4_rename+0x600/0x830 [ext4] > [ 1954.782376] ? legitimize_path.isra.54+0x28/0x50 > [ 1954.782382] ? terminate_walk+0x55/0xb0 > [ 1954.782388] vfs_rename+0x1df/0x6d0 > [ 1954.782394] ? __d_lookup+0x111/0x130 > [ 1954.782400] SyS_rename+0x325/0x390 > [ 1954.782405] do_syscall_64+0x75/0x1a0 > [ 1954.782411] entry_SYSCALL_64_after_hwframe+0x21/0x86 > [ 1954.782414] RIP: 0033:0x14d933ff7a67 > [ 1954.782417] RSP: 002b:00007fffc5db42c8 EFLAGS: 00000206 ORIG_RAX: 0000000000000052 > [ 1954.782421] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 000014d933ff7a67 > [ 1954.782424] RDX: 0000000000000000 RSI: 00000000016eba00 RDI: 00000000016e7b30 > [ 1954.782427] RBP: 00000000016d6390 R08: 00000000016e7c80 R09: 000014d934a14700 > [ 1954.782430] R10: 0000000000000000 R11: 0000000000000206 R12: 00000000016e7ba0 > [ 1954.782433] R13: 00000000016eba00 R14: 0000000000000000 R15: 0000000000000006 > [ 1954.782438] INFO: task rm:19709 blocked for more than 480 seconds. > [ 1954.782442] Tainted: G E 4.15.3-smp #8 > [ 1954.782444] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.782446] rm D 0 19709 19687 0x00000000 > [ 1954.782450] Call Trace: > [ 1954.782457] ? __schedule+0x268/0x840 > [ 1954.782463] schedule+0x32/0x80 > [ 1954.782471] wait_transaction_locked+0x76/0xa0 [jbd2] > [ 1954.782478] ? remove_wait_queue+0x60/0x60 > [ 1954.782486] add_transaction_credits+0x1a4/0x280 [jbd2] > [ 1954.782494] start_this_handle+0x189/0x3e0 [jbd2] > [ 1954.782500] ? _cond_resched+0x15/0x30 > [ 1954.782505] ? kmem_cache_alloc+0x142/0x150 > [ 1954.782513] jbd2__journal_start+0xe9/0x1f0 [jbd2] > [ 1954.782532] ext4_unlink+0x1ac/0x330 [ext4] > [ 1954.782537] vfs_unlink+0xb1/0x1a0 > [ 1954.782542] do_unlinkat+0x23b/0x280 > [ 1954.782548] do_syscall_64+0x75/0x1a0 > [ 1954.782553] entry_SYSCALL_64_after_hwframe+0x21/0x86 > [ 1954.782556] RIP: 0033:0x7fca75fcfba7 > [ 1954.782559] RSP: 002b:00007ffdaa5b75a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000107 > [ 1954.782563] RAX: ffffffffffffffda RBX: 00000000011bf770 RCX: 00007fca75fcfba7 > [ 1954.782566] RDX: 0000000000000000 RSI: 00000000011bf878 RDI: 0000000000000006 > [ 1954.782569] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 > [ 1954.782573] R10: 000000000000004a R11: 0000000000000246 R12: 00000000011b3fdc > [ 1954.782576] R13: 00007ffdaa5b7700 R14: 00000000011bf770 R15: 0000000000000000 > [ 1954.782581] INFO: task gcc:19728 blocked for more than 480 seconds. > [ 1954.782584] Tainted: G E 4.15.3-smp #8 > [ 1954.782586] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.782588] gcc D 0 19728 19727 0x00000000 > [ 1954.782592] Call Trace: > [ 1954.782599] ? __schedule+0x268/0x840 > [ 1954.782603] ? filename_parentat+0xc9/0x120 > [ 1954.782609] schedule+0x32/0x80 > [ 1954.782614] rwsem_down_write_failed+0x1e9/0x360 > [ 1954.782620] call_rwsem_down_write_failed+0x13/0x20 > [ 1954.782627] down_write+0x29/0x40 > [ 1954.782632] filename_create+0x66/0x150 > [ 1954.782637] SyS_symlink+0x4e/0xc0 > [ 1954.782642] do_syscall_64+0x75/0x1a0 > [ 1954.782647] entry_SYSCALL_64_after_hwframe+0x21/0x86 > [ 1954.782650] RIP: 0033:0x147656b2cab7 > [ 1954.782653] RSP: 002b:00007fff10c42988 EFLAGS: 00000206 ORIG_RAX: 0000000000000058 > [ 1954.782657] RAX: ffffffffffffffda RBX: 0000000000643250 RCX: 0000147656b2cab7 > [ 1954.782661] RDX: 0000000000643390 RSI: 0000000000643250 RDI: 0000000000643390 > [ 1954.782664] RBP: 0000000000000000 R08: 3836333633343800 R09: 0000000000658be0 > [ 1954.782667] R10: 00000000ba5a914c R11: 0000000000000206 R12: 0000000000643390 > [ 1954.782670] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000006 > [ 1954.782675] INFO: task gcc:19732 blocked for more than 480 seconds. > [ 1954.782678] Tainted: G E 4.15.3-smp #8 > [ 1954.782680] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 1954.782683] gcc D 0 19732 19731 0x00000000 > [ 1954.782687] Call Trace: > [ 1954.782693] ? __schedule+0x268/0x840 > [ 1954.782699] schedule+0x32/0x80 > [ 1954.782704] io_schedule+0x12/0x40 > [ 1954.782709] blk_mq_get_tag+0x11e/0x230 > [ 1954.782715] ? elv_merge+0x66/0xe0 > [ 1954.782720] ? remove_wait_queue+0x60/0x60 > [ 1954.782727] blk_mq_get_request+0xcc/0x340 > [ 1954.782732] blk_mq_make_request+0xf8/0x580 > [ 1954.782737] generic_make_request+0xfd/0x2d0 > [ 1954.782741] submit_bio+0x5e/0x120 > [ 1954.782759] ? __ext4_journal_stop+0x37/0xa0 [ext4] > [ 1954.782777] ext4_io_submit+0x48/0x60 [ext4] > [ 1954.782795] ext4_writepages+0x64a/0xe50 [ext4] > [ 1954.782805] do_writepages+0x1a/0x70 > [ 1954.782809] __filemap_fdatawrite_range+0x71/0x90 > [ 1954.782828] ext4_rename+0x600/0x830 [ext4] > [ 1954.782834] ? legitimize_path.isra.54+0x28/0x50 > [ 1954.782840] ? terminate_walk+0x55/0xb0 > [ 1954.782846] vfs_rename+0x1df/0x6d0 > [ 1954.782853] ? __d_lookup+0x111/0x130 > [ 1954.782858] SyS_rename+0x325/0x390 > [ 1954.782864] do_syscall_64+0x75/0x1a0 > [ 1954.782869] entry_SYSCALL_64_after_hwframe+0x21/0x86 > [ 1954.782872] RIP: 0033:0x15499c5b4a67 > [ 1954.782875] RSP: 002b:00007fff60bd92b8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 > [ 1954.782879] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 000015499c5b4a67 > [ 1954.782882] RDX: 0000000000000000 RSI: 0000000001966b60 RDI: 00000000019673c0 > [ 1954.782886] RBP: 000000000194d2e0 R08: 0000000001967510 R09: 000015499cfd1700 > [ 1954.782888] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000001967430 > [ 1954.782891] R13: 0000000001966b60 R14: 0000000000000000 R15: 0000000000000006 No bfq in the trace, so probably yet another problem stemming from the interaction between bfq and blk-mq. Hung tasks seem to wait indefinitely for a tag, and the only bfq patch that affects tag distribution is: a52a69ea89dc block, bfq: limit tags for writes and async I/O So, for the next step (and as you already decided to do), please retry after adding the above commit to your initial pair: patches/block-bfq:-fix-occurrences-of-request-finish-method-s-old-name.patch patches/block-bfq:-add-requeue-request-hook.patch Thanks, Paolo