* WARNING at blktests block/008 in ttwu_queue_wakelist()
@ 2021-06-09 6:53 Shinichiro Kawasaki
2021-06-09 6:55 ` Damien Le Moal
[not found] ` <20210610083200.3832-1-hdanton@sina.com>
0 siblings, 2 replies; 6+ messages in thread
From: Shinichiro Kawasaki @ 2021-06-09 6:53 UTC (permalink / raw)
To: linux-block; +Cc: Damien Le Moal
Hi there,
Let me share a blktests failure. When I ran blktests on the kernel v5.13-rc5,
block/008 failed. A WARNING below was the cause of the failure.
WARNING: CPU: 1 PID: 135817 at kernel/sched/core.c:3175 ttwu_queue_wakelist+0x284/0x2f0
I'm trying to recreate the failure repeating the test case, but so far, I am not
able to. This failure looks rare, but actually, I observed it 3 times in the
past one year.
1) Oct/2020, kernel: v5.9-rc7 test dev: dm-flakey on AHCI-SATA SMR HDD, log [1]
2) Mar/2021, kernel: v5.12-rc2 test dev: AHCI-SATA SMR HDD, log [2]
3) Jun/2021, kernel: v5.13-rc5 test dev: dm-linear on null_blk zoned, log [3]
The test case block/008 does IO during CPU hotplug, and the WARNING in
ttwu_queue_wakelist() checks "WARN_ON_ONCE(cpu == smp_processor_id())".
So it is likely that the test case triggers the warning, but I don't have
clear view why and how the warning was triggered. It was observed on various
block devices, so I would like to ask linux-block experts if anyone can tell
what is going on. Comments will be appreciated.
[1]
[29603.810633][T127266] ------------[ cut here ]------------
[29603.816381][T127266] WARNING: CPU: 4 PID: 127266 at kernel/sched/core.c:2670 ttwu_queue_wakelist+0x27c/0x2b0
[29603.826198][T127266] Modules linked in: dm_flakey iscsi_target_mod tcm_loop target_core_pscsi target_core_file target_core_iblock xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tftp nf_conntrack_tftp tun bridge stp llc nft_objref nf_conntrack_netbios_ns nf_conntrack_broadcast nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_tables ebtable_nat ebtable_broute ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c iptable_mangle iptable_raw iptable_security target_core_user rfkill target_core_mod ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter sunrpc intel_rapl_msr iTCO_wdt iTCO_vendor_support intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass intel_cstate intel_uncore joydev pcspkr i2c_i801 i2c_smbus mei_me mei lpc_ich ses enclosure ioatdma wmi
[29603.826259][T127266] ipmi_ssif ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad ip_tables drm_vram_helper drm_kms_helper crct10dif_pclmul drm_ttm_helper crc32_pclmul ttm crc32c_intel drm ghash_clmulni_intel igb mpt3sas nvme dca nvme_core i2c_algo_bit raid_class scsi_transport_sas fuse [last unloaded: null_blk]
[29603.941330][T127266] CPU: 4 PID: 127266 Comm: fio Not tainted 5.9.0-rc7 #1
[29603.948201][T127266] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 2.0 12/17/2015
[29603.956368][T127266] RIP: 0010:ttwu_queue_wakelist+0x27c/0x2b0
[29603.962198][T127266] Code: 89 e7 e8 37 5d 60 00 e9 2c fe ff ff e8 3d 5d 60 00 e9 f0 fd ff ff e8 53 5d 60 00 e9 41 ff ff ff e8 89 5d 60 00 e9 7b ff ff ff <0f> 0b e9 a6 fe ff ff 48 89 04 24 e8 04 5d 60 00 48 8b 04 24 e9 8e
[29603.981715][T127266] RSP: 0018:ffff88856b3ef3f0 EFLAGS: 00010046
[29603.987714][T127266] RAX: 0000000000000004 RBX: ffff88861ad21200 RCX: ffff88861ad00000
[29603.995616][T127266] RDX: 0000000000000000 RSI: 0000000000000004 RDI: ffffffff98dfe920
[29604.003521][T127266] RBP: 0000000000000000 R08: 0000000000000004 R09: ffffffff9988a227
[29604.011425][T127266] R10: fffffbfff3311444 R11: 0000000000000001 R12: 0000000000000004
[29604.019330][T127266] R13: ffff8886035b8000 R14: 0000000000000004 R15: ffffffff98dfe920
[29604.027235][T127266] FS: 00007f43b1067a40(0000) GS:ffff88861ad00000(0000) knlGS:0000000000000000
[29604.036099][T127266] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[29604.042618][T127266] CR2: 00007f2a8eeeb421 CR3: 000000057abf2001 CR4: 00000000001706e0
[29604.050523][T127266] Call Trace:
[29604.053757][T127266] ? lock_is_held_type+0xbb/0xf0
[29604.058640][T127266] ? rcu_read_lock_sched_held+0x3f/0x80
[29604.064123][T127266] try_to_wake_up+0x4f0/0x1420
[29604.068831][T127266] ? migrate_swap_stop+0x970/0x970
[29604.073882][T127266] ? insert_work+0x18b/0x2d0
[29604.078417][T127266] __queue_work+0x4f2/0xe90
[29604.082863][T127266] ? try_to_grab_pending.part.0+0x23/0x530
[29604.088604][T127266] ? lockdep_hardirqs_off+0x80/0xb0
[29604.093738][T127266] mod_delayed_work_on+0x9a/0x110
[29604.098703][T127266] ? cancel_delayed_work_sync+0x10/0x10
[29604.104182][T127266] ? __blk_mq_delay_run_hw_queue+0x95/0x570
[29604.110019][T127266] kblockd_mod_delayed_work_on+0x17/0x20
[29604.115586][T127266] blk_mq_run_hw_queue+0x125/0x270
[29604.120630][T127266] ? blk_mq_delay_run_hw_queues+0x150/0x150
[29604.126459][T127266] blk_mq_sched_insert_request+0x2d4/0x5f0
[29604.132201][T127266] ? __blk_mq_sched_bio_merge+0x440/0x440
[29604.137863][T127266] blk_mq_submit_bio+0xaa4/0x14e0
[29604.142828][T127266] ? blk_mq_try_issue_directly+0x120/0x120
[29604.148577][T127266] ? percpu_ref_put_many.constprop.0+0x83/0x150
[29604.154757][T127266] ? dm_wq_work+0x210/0x210
[29604.159201][T127266] submit_bio_noacct+0x6b9/0xc30
[29604.164078][T127266] ? lock_is_held_type+0xbb/0xf0
[29604.168960][T127266] ? bio_associate_blkg_from_css+0x1c6/0xb00
[29604.174877][T127266] ? blk_queue_enter+0x7c0/0x7c0
[29604.179762][T127266] submit_bio+0xe4/0x480
[29604.183943][T127266] ? submit_bio_noacct+0xc30/0xc30
[29604.188999][T127266] ? bio_add_pc_page+0xd0/0xd0
[29604.193702][T127266] ? bio_release_pages.part.0+0x10c/0x3d0
[29604.199367][T127266] __blkdev_direct_IO_simple+0x41f/0x7a0
[29604.204938][T127266] ? bd_link_disk_holder+0x780/0x780
[29604.210160][T127266] ? mark_lock+0x82/0x1470
[29604.214522][T127266] ? __lock_acquire+0xb66/0x5400
[29604.219400][T127266] ? bd_may_claim+0xc0/0xc0
[29604.223847][T127266] ? __lock_acquire+0x1603/0x5400
[29604.228811][T127266] blkdev_direct_IO+0xd6a/0x1070
[29604.233690][T127266] ? mark_lock+0x82/0x1470
[29604.238053][T127266] ? __lock_acquire+0x1603/0x5400
[29604.243016][T127266] ? bd_prepare_to_claim+0x220/0x220
[29604.248247][T127266] ? lockdep_hardirqs_on_prepare+0x4f0/0x4f0
[29604.254164][T127266] generic_file_read_iter+0x1f4/0x470
[29604.259477][T127266] new_sync_read+0x350/0x5d0
[29604.264007][T127266] ? vfs_dedupe_file_range+0x5c0/0x5c0
[29604.269414][T127266] ? inode_security+0x56/0xf0
[29604.274032][T127266] vfs_read+0x296/0x4a0
[29604.278126][T127266] __x64_sys_pread64+0x17d/0x1d0
[29604.283004][T127266] ? vfs_read+0x4a0/0x4a0
[29604.287271][T127266] ? trace_hardirqs_on+0x20/0x170
[29604.292238][T127266] do_syscall_64+0x33/0x40
[29604.296593][T127266] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[29604.302421][T127266] RIP: 0033:0x7f43baf6924f
[29604.306778][T127266] Code: 08 89 3c 24 48 89 4c 24 18 e8 ed f3 ff ff 4c 8b 54 24 18 48 8b 54 24 10 41 89 c0 48 8b 74 24 08 8b 3c 24 b8 11 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 31 44 89 c7 48 89 04 24 e8 1d f4 ff ff 48 8b
[29604.326303][T127266] RSP: 002b:00007ffec6c62e60 EFLAGS: 00000293 ORIG_RAX: 0000000000000011
[29604.334648][T127266] RAX: ffffffffffffffda RBX: 00000000011fc540 RCX: 00007f43baf6924f
[29604.342554][T127266] RDX: 0000000000001000 RSI: 00000000012ac000 RDI: 0000000000000008
[29604.350459][T127266] RBP: 00000000011fc540 R08: 0000000000000000 R09: 00007ffec6d7b1b0
[29604.358370][T127266] R10: 0000000001936000 R11: 0000000000000293 R12: 00007f43576f4d20
[29604.366276][T127266] R13: 0000000000000000 R14: 0000000000001000 R15: 00000000011fc568
[29604.374188][T127266] irq event stamp: 78824
[29604.378368][T127266] hardirqs last enabled at (78823): [<ffffffff963c4550>] ktime_get+0x150/0x190
[29604.387318][T127266] hardirqs last disabled at (78824): [<ffffffff96239567>] mod_delayed_work_on+0xd7/0x110
[29604.397045][T127266] softirqs last enabled at (78564): [<ffffffff98201092>] asm_call_irq_on_stack+0x12/0x20
[29604.406861][T127266] softirqs last disabled at (78555): [<ffffffff98201092>] asm_call_irq_on_stack+0x12/0x20
[29604.416673][T127266] ---[ end trace effce0b470837a17 ]---
[29604.422074][ C4]
[29604.422075][ C4] ======================================================
[29604.422076][ C4] WARNING: possible circular locking dependency detected
[29604.422077][ C4] 5.9.0-rc7 #1 Not tainted
[29604.422078][ C4] ------------------------------------------------------
[29604.422079][ C4] fio/127266 is trying to acquire lock:
[29604.422079][ C4] ffffffff9913a678 ((console_sem).lock){-.-.}-{2:2}, at: down_trylock+0x13/0x70
[29604.422083][ C4]
[29604.422083][ C4] but task is already holding lock:
[29604.422084][ C4] ffff8886035b8c38 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x84/0x1420
[29604.422087][ C4]
[29604.422088][ C4] which lock already depends on the new lock.
[29604.422088][ C4]
[29604.422089][ C4]
[29604.422090][ C4] the existing dependency chain (in reverse order) is:
[29604.422090][ C4]
[29604.422091][ C4] -> #1 (&p->pi_lock){-.-.}-{2:2}:
[29604.422094][ C4] _raw_spin_lock_irqsave+0x48/0x60
[29604.422095][ C4] try_to_wake_up+0x84/0x1420
[29604.422095][ C4] up+0x7a/0xb0
[29604.422096][ C4] __up_console_sem+0x3c/0x70
[29604.422097][ C4] console_unlock+0x451/0xa10
[29604.422098][ C4] vprintk_emit+0x232/0x510
[29604.422099][ C4] devkmsg_emit.constprop.0+0x97/0xb3
[29604.422100][ C4] devkmsg_write.cold+0x48/0x74
[29604.422101][ C4] do_iter_readv_writev+0x34c/0x6d0
[29604.422102][ C4] do_iter_write+0x137/0x5d0
[29604.422102][ C4] vfs_writev+0x14a/0x280
[29604.422103][ C4] do_writev+0x100/0x260
[29604.422104][ C4] do_syscall_64+0x33/0x40
[29604.422105][ C4] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[29604.422106][ C4]
[29604.422106][ C4] -> #0 ((console_sem).lock){-.-.}-{2:2}:
[29604.422110][ C4] __lock_acquire+0x29e4/0x5400
[29604.422111][ C4] lock_acquire+0x18f/0x990
[29604.422112][ C4] _raw_spin_lock_irqsave+0x48/0x60
[29604.422113][ C4] down_trylock+0x13/0x70
[29604.422114][ C4] __down_trylock_console_sem+0x33/0xb0
[29604.422115][ C4] vprintk_emit+0x203/0x510
[29604.422115][ C4] printk+0x96/0xb2
[29604.422116][ C4] report_bug.cold+0x31/0x5e
[29604.422117][ C4] handle_bug+0x3d/0xa0
[29604.422118][ C4] exc_invalid_op+0x14/0x40
[29604.422119][ C4] asm_exc_invalid_op+0x12/0x20
[29604.422120][ C4] ttwu_queue_wakelist+0x27c/0x2b0
[29604.422121][ C4] try_to_wake_up+0x4f0/0x1420
[29604.422122][ C4] __queue_work+0x4f2/0xe90
[29604.422122][ C4] mod_delayed_work_on+0x9a/0x110
[29604.422124][ C4] kblockd_mod_delayed_work_on+0x17/0x20
[29604.422124][ C4] blk_mq_run_hw_queue+0x125/0x270
[29604.422125][ C4] blk_mq_sched_insert_request+0x2d4/0x5f0
[29604.422126][ C4] blk_mq_submit_bio+0xaa4/0x14e0
[29604.422127][ C4] submit_bio_noacct+0x6b9/0xc30
[29604.422128][ C4] submit_bio+0xe4/0x480
[29604.422129][ C4] __blkdev_direct_IO_simple+0x41f/0x7a0
[29604.422130][ C4] blkdev_direct_IO+0xd6a/0x1070
[29604.422131][ C4] generic_file_read_iter+0x1f4/0x470
[29604.422132][ C4] new_sync_read+0x350/0x5d0
[29604.422133][ C4] vfs_read+0x296/0x4a0
[29604.422134][ C4] __x64_sys_pread64+0x17d/0x1d0
[29604.422135][ C4] do_syscall_64+0x33/0x40
[29604.422135][ C4] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[29604.422136][ C4]
[29604.422137][ C4] other info that might help us debug this:
[29604.422138][ C4]
[29604.422139][ C4] Possible unsafe locking scenario:
[29604.422139][ C4]
[29604.422140][ C4] CPU0 CPU1
[29604.422141][ C4] ---- ----
[29604.422142][ C4] lock(&p->pi_lock);
[29604.422144][ C4] lock((console_sem).lock);
[29604.422146][ C4] lock(&p->pi_lock);
[29604.422148][ C4] lock((console_sem).lock);
[29604.422149][ C4]
[29604.422150][ C4] *** DEADLOCK ***
[29604.422151][ C4]
[29604.422152][ C4] 3 locks held by fio/127266:
[29604.422152][ C4] #0: ffffffff99159260 (rcu_read_lock){....}-{1:2}, at: __queue_work+0xa0/0xe90
[29604.422156][ C4] #1: ffff88861ad33a58 (&pool->lock){-.-.}-{2:2}, at: __queue_work+0x2d3/0xe90
[29604.422159][ C4] #2: ffff8886035b8c38 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x84/0x1420
[29604.422163][ C4]
[29604.422164][ C4] stack backtrace:
[29604.422165][ C4] CPU: 4 PID: 127266 Comm: fio Not tainted 5.9.0-rc7 #1
[29604.422166][ C4] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 2.0 12/17/2015
[29604.422167][ C4] Call Trace:
[29604.422168][ C4] dump_stack+0xae/0xe8
[29604.422169][ C4] check_noncircular+0x2fc/0x3b0
[29604.422169][ C4] ? print_circular_bug+0x370/0x370
[29604.422170][ C4] ? stack_trace_save+0x81/0xa0
[29604.422171][ C4] ? lock_repin_lock+0x370/0x370
[29604.422172][ C4] __lock_acquire+0x29e4/0x5400
[29604.422173][ C4] ? lockdep_hardirqs_on_prepare+0x4f0/0x4f0
[29604.422174][ C4] lock_acquire+0x18f/0x990
[29604.422174][ C4] ? down_trylock+0x13/0x70
[29604.422175][ C4] ? sched_clock_cpu+0x18/0x170
[29604.422176][ C4] ? lock_release+0x7c0/0x7c0
[29604.422177][ C4] ? find_held_lock+0x2c/0x110
[29604.422178][ C4] ? vprintk_emit+0x1ba/0x510
[29604.422179][ C4] _raw_spin_lock_irqsave+0x48/0x60
[29604.422179][ C4] ? down_trylock+0x13/0x70
[29604.422180][ C4] down_trylock+0x13/0x70
[29604.422181][ C4] ? printk+0x96/0xb2
[29604.422182][ C4] __down_trylock_console_sem+0x33/0xb0
[29604.422183][ C4] vprintk_emit+0x203/0x510
[29604.422183][ C4] ? ttwu_queue_wakelist+0x27c/0x2b0
[29604.422184][ C4] printk+0x96/0xb2
[29604.422185][ C4] ? log_store.cold+0x11/0x11
[29604.422187][ C4] ? mark_lock+0x82/0x1470
[29604.422188][ C4] report_bug.cold+0x31/0x5e
[29604.422189][ C4] handle_bug+0x3d/0xa0
[29604.422190][ C4] ? lock_acquire+0x18f/0x990
[29604.422191][ C4] exc_invalid_op+0x14/0x40
[29604.422191][ C4] asm_exc_invalid_op+0x12/0x20
[29604.422192][ C4] RIP: 0010:ttwu_queue_wakelist+0x27c/0x2b0
[29604.422193][ C4] Code: 89 e7 e8 37 5d 60 00 e9 2c fe ff ff e8 3d 5d 60 00 e9 f0 fd ff ff e8 53 5d 60 00 e9 41 ff ff ff e8 89 5d 60 00 e9 7b ff ff ff <0f> 0b e9 a6 fe ff ff 48 89 04 24 e8 04 5d 60 00 48 8b 04 24 e9 8e
[29604.422194][ C4] RSP: 0018:ffff88856b3ef3f0 EFLAGS: 00010046
[29604.422195][ C4] RAX: 000000000
[29604.422197][ C4] Lost 62 message(s)!
[2]
[ 8339.653610][ C2] ------------[ cut here ]------------
[ 8339.659324][ C2] WARNING: CPU: 2 PID: 558 at kernel/sched/core.c:3158 ttwu_queue_wakelist+0x284/0x2f0
[ 8339.668804][ C2] Modules linked in: iscsi_target_mod tcm_loop target_core_pscsi target_core_file target_core_iblock nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw iptable_security ip_set nf_tables bridge stp llc nfnetlink rfkill target_core_user ip6table_filter target_core_mod ip6_tables iptable_filter sunrpc intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_wdt rapl intel_pmc_bxt iTCO_vendor_support intel_cstate joydev mei_me ses i2c_i801 mei intel_uncore enclosure ipmi_ssif lpc_ich i2c_smbus ioatdma wmi acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad zram ip_tables ast drm_vram_helper drm_kms_helper crc32c_intel syscopyarea sysfillrect sysimgblt fb_sys_fops cec
[ 8339.668927][ C2] drm_ttm_helper ttm ghash_clmulni_intel drm mpt3sas igb raid_class scsi_transport_sas nvme dca nvme_core i2c_algo_bit pkcs8_key_parser [last unloaded: zonefs]
[ 8339.770658][ C2] CPU: 2 PID: 558 Comm: systemd-udevd Not tainted 5.12.0-rc2+ #1
[ 8339.778222][ C2] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 3.2 11/22/2019
[ 8339.786310][ C2] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
[ 8339.792054][ C2] Code: 34 24 e8 3f 7d 63 00 4c 8b 44 24 10 48 8b 4c 24 08 8b 34 24 e9 a1 fe ff ff e8 78 7d 63 00 e9 66 ff ff ff e8 8e 7d 63 00 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 19 7d 63 00 48 8b 04
[ 8339.811494][ C2] RSP: 0000:ffff888811489ce0 EFLAGS: 00010046
[ 8339.817415][ C2] RAX: 0000000000000002 RBX: ffff88810eee3240 RCX: ffff888811480000
[ 8339.825240][ C2] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffffffff91e2c6f0
[ 8339.833067][ C2] RBP: 0000000000000002 R08: ffffffff91e2c6f0 R09: ffffffff929a2ba7
[ 8339.840894][ C2] R10: fffffbfff2534574 R11: 0000000000000001 R12: 0000000000000000
[ 8339.848719][ C2] R13: ffff88881149f8c0 R14: 0000000000000002 R15: 0000000000032c01
[ 8339.856545][ C2] FS: 00007fe9e16cc380(0000) GS:ffff888811480000(0000) knlGS:0000000000000000
[ 8339.865325][ C2] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 8339.871763][ C2] CR2: 000055d9e787ea88 CR3: 000000011d906004 CR4: 00000000001706e0
[ 8339.879591][ C2] Call Trace:
[ 8339.882730][ C2] <IRQ>
[ 8339.885440][ C2] ? lock_is_held_type+0x98/0x110
[ 8339.890321][ C2] try_to_wake_up+0x5c7/0x1780
[ 8339.894940][ C2] ? migrate_swap_stop+0x970/0x970
[ 8339.899907][ C2] blk_update_request+0x711/0xe50
[ 8339.904787][ C2] ? scsi_cleanup_rq+0x110/0x180
[ 8339.909578][ C2] scsi_end_request+0x71/0x620
[ 8339.914199][ C2] scsi_io_completion+0x176/0xe00
[ 8339.919078][ C2] ? provisioning_mode_store+0x3f0/0x3f0
[ 8339.924562][ C2] ? scsi_run_host_queues+0x60/0x60
[ 8339.929616][ C2] blk_complete_reqs+0x9a/0xd0
[ 8339.934235][ C2] __do_softirq+0x1d0/0x881
[ 8339.938596][ C2] __irq_exit_rcu+0x1b9/0x270
[ 8339.943137][ C2] irq_exit_rcu+0xa/0x20
[ 8339.947235][ C2] sysvec_call_function_single+0x6f/0x90
[ 8339.952721][ C2] </IRQ>
[ 8339.955520][ C2] asm_sysvec_call_function_single+0x12/0x20
[ 8339.961353][ C2] RIP: 0010:ptep_clear_flush+0x4f/0x150
[ 8339.966753][ C2] Code: 48 89 f5 48 c1 ea 03 53 80 3c 02 00 0f 85 00 01 00 00 be 08 00 00 00 4c 89 ef 49 8b 5f 40 45 31 f6 e8 85 64 0a 00 4d 87 75 00 <48> c7 c0 78 cf e3 91 48 ba 00 00 00 00 00 fc ff df 48 c1 e8 03 80
[ 8339.986193][ C2] RSP: 0000:ffff88811faf7ba0 EFLAGS: 00000246
[ 8339.992111][ C2] RAX: 0000000000000001 RBX: ffff888118eb9c00 RCX: ffffffff8f7c368b
[ 8339.999939][ C2] RDX: ffffed102446ac7f RSI: 0000000000000008 RDI: ffff8881223563f0
[ 8340.007764][ C2] RBP: 000055d9e787e000 R08: 0000000000000001 R09: ffff8881223563f7
[ 8340.015589][ C2] R10: ffffed102446ac7e R11: 0000000000000001 R12: ffff888121105a08
[ 8340.023417][ C2] R13: ffff8881223563f0 R14: 8000000213aa9865 R15: ffff8881211059c8
[ 8340.031246][ C2] ? ptep_clear_flush+0x4b/0x150
[ 8340.036037][ C2] wp_page_copy+0x839/0x1fd0
[ 8340.040485][ C2] ? lock_release+0x680/0x680
[ 8340.045015][ C2] ? __do_fault+0x5d0/0x5d0
[ 8340.049376][ C2] ? do_wp_page+0x318/0x1650
[ 8340.053822][ C2] __handle_mm_fault+0x1f31/0x4af0
[ 8340.058787][ C2] ? lock_is_held_type+0x98/0x110
[ 8340.063666][ C2] ? copy_page_range+0x3810/0x3810
[ 8340.068635][ C2] ? count_memcg_event_mm.part.0+0xfc/0x1a0
[ 8340.074377][ C2] ? trace_hardirqs_on+0x1c/0x110
[ 8340.079257][ C2] handle_mm_fault+0x15f/0x620
[ 8340.083879][ C2] do_user_addr_fault+0x385/0xe30
[ 8340.088758][ C2] ? do_kern_addr_fault+0xb0/0xb0
[ 8340.093636][ C2] ? irqentry_enter+0x55/0x60
[ 8340.098170][ C2] exc_page_fault+0x60/0xe0
[ 8340.102528][ C2] ? asm_exc_page_fault+0x8/0x30
[ 8340.107321][ C2] asm_exc_page_fault+0x1e/0x30
[ 8340.112027][ C2] RIP: 0033:0x7fe9e25c5cdd
[ 8340.116301][ C2] Code: 08 48 8b 4f 08 48 89 c8 48 83 e0 f8 48 3b 04 07 0f 85 91 00 00 00 48 8b 47 10 48 8b 57 18 48 3b 78 18 75 69 48 3b 7a 10 75 63 <48> 89 50 18 48 89 42 10 48 81 f9 ff 03 00 00 76 2c 48 8b 57 20 48
[ 8340.135739][ C2] RSP: 002b:00007fff57b878d0 EFLAGS: 00010246
[ 8340.141658][ C2] RAX: 000055d9e787ea70 RBX: 000055d9e78851d0 RCX: 0000000000000291
[ 8340.149485][ C2] RDX: 00007fe9e2701ce0 RSI: 0000000000000002 RDI: 000055d9e78851d0
[ 8340.157310][ C2] RBP: 00000000000002c0 R08: 000055d9e789cc70 R09: 0000000000000290
[ 8340.165137][ C2] R10: 0000000000000047 R11: 000055d9e780d130 R12: 00007fe9e2701a00
[ 8340.172963][ C2] R13: 00007fe9e2701a18 R14: 000000055d9e7885 R15: 000055d9e7885490
[ 8340.180794][ C2] irq event stamp: 13527209
[ 8340.185149][ C2] hardirqs last enabled at (13527208): [<ffffffff91400185>] __do_softirq+0x185/0x881
[ 8340.194536][ C2] hardirqs last disabled at (13527209): [<ffffffff911e2c30>] _raw_spin_lock_irqsave+0x50/0x60
[ 8340.204616][ C2] softirqs last enabled at (13527014): [<ffffffff8f1af839>] __irq_exit_rcu+0x1b9/0x270
[ 8340.214175][ C2] softirqs last disabled at (13527207): [<ffffffff8f1af839>] __irq_exit_rcu+0x1b9/0x270
[ 8340.223735][ C2] ---[ end trace b4a0f179ac6a8cbe ]---
[ 8340.229054][ C2]
[ 8340.229056][ C2] ======================================================
[ 8340.229057][ C2] WARNING: possible circular locking dependency detected
[ 8340.229058][ C2] 5.12.0-rc2+ #1 Not tainted
[ 8340.229059][ C2] ------------------------------------------------------
[ 8340.229059][ C2] systemd-udevd/558 is trying to acquire lock:
[ 8340.229060][ C2] ffffffff92218b18 ((console_sem).lock){-.-.}-{2:2}, at: down_trylock+0x13/0x70
[ 8340.229064][ C2]
[ 8340.229065][ C2] but task is already holding lock:
[ 8340.229065][ C2] ffff88810eee3f20 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x88/0x1780
[ 8340.229068][ C2]
[ 8340.229069][ C2] which lock already depends on the new lock.
[ 8340.229069][ C2]
[ 8340.229070][ C2]
[ 8340.229071][ C2] the existing dependency chain (in reverse order) is:
[ 8340.229071][ C2]
[ 8340.229072][ C2] -> #1 (&p->pi_lock){-.-.}-{2:2}:
[ 8340.229074][ C2] _raw_spin_lock_irqsave+0x3b/0x60
[ 8340.229075][ C2] try_to_wake_up+0x88/0x1780
[ 8340.229076][ C2] up+0x7a/0xb0
[ 8340.229076][ C2] __up_console_sem+0x2d/0x60
[ 8340.229077][ C2] console_unlock+0x41b/0x880
[ 8340.229078][ C2] vprintk_emit+0x257/0x420
[ 8340.229079][ C2] devkmsg_emit.constprop.0+0x95/0xb1
[ 8340.229080][ C2] devkmsg_write.cold+0x48/0x74
[ 8340.229082][ C2] do_iter_readv_writev+0x32b/0x6b0
[ 8340.229083][ C2] do_iter_write+0x137/0x5d0
[ 8340.229084][ C2] vfs_writev+0x147/0x4a0
[ 8340.229084][ C2] do_writev+0x100/0x260
[ 8340.229085][ C2] do_syscall_64+0x33/0x40
[ 8340.229086][ C2] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 8340.229086][ C2]
[ 8340.229087][ C2] -> #0 ((console_sem).lock){-.-.}-{2:2}:
[ 8340.229090][ C2] __lock_acquire+0x290e/0x58b0
[ 8340.229090][ C2] lock_acquire+0x181/0x6a0
[ 8340.229091][ C2] _raw_spin_lock_irqsave+0x3b/0x60
[ 8340.229092][ C2] down_trylock+0x13/0x70
[ 8340.229092][ C2] __down_trylock_console_sem+0x24/0x90
[ 8340.229093][ C2] vprintk_emit+0x230/0x420
[ 8340.229094][ C2] printk+0x96/0xb2
[ 8340.229094][ C2] report_bug.cold+0x31/0x53
[ 8340.229095][ C2] handle_bug+0x41/0x80
[ 8340.229096][ C2] exc_invalid_op+0x14/0x40
[ 8340.229096][ C2] asm_exc_invalid_op+0x12/0x20
[ 8340.229097][ C2] ttwu_queue_wakelist+0x284/0x2f0
[ 8340.229098][ C2] try_to_wake_up+0x5c7/0x1780
[ 8340.229098][ C2] blk_update_request+0x711/0xe50
[ 8340.229099][ C2] scsi_end_request+0x71/0x620
[ 8340.229100][ C2] scsi_io_completion+0x176/0xe00
[ 8340.229100][ C2] blk_complete_reqs+0x9a/0xd0
[ 8340.229101][ C2] __do_softirq+0x1d0/0x881
[ 8340.229102][ C2] __irq_exit_rcu+0x1b9/0x270
[ 8340.229102][ C2] irq_exit_rcu+0xa/0x20
[ 8340.229103][ C2] sysvec_call_function_single+0x6f/0x90
[ 8340.229103][ C2] asm_sysvec_call_function_single+0x12/0x20
[ 8340.229104][ C2] ptep_clear_flush+0x4f/0x150
[ 8340.229105][ C2] wp_page_copy+0x839/0x1fd0
[ 8340.229106][ C2] __handle_mm_fault+0x1f31/0x4af0
[ 8340.229106][ C2] handle_mm_fault+0x15f/0x620
[ 8340.229107][ C2] do_user_addr_fault+0x385/0xe30
[ 8340.229108][ C2] exc_page_fault+0x60/0xe0
[ 8340.229108][ C2] asm_exc_page_fault+0x1e/0x30
[ 8340.229109][ C2]
[ 8340.229109][ C2] other info that might help us debug this:
[ 8340.229110][ C2]
[ 8340.229110][ C2] Possible unsafe locking scenario:
[ 8340.229111][ C2]
[ 8340.229112][ C2] CPU0 CPU1
[ 8340.229112][ C2] ---- ----
[ 8340.229113][ C2] lock(&p->pi_lock);
[ 8340.229114][ C2] lock((console_sem).lock);
[ 8340.229116][ C2] lock(&p->pi_lock);
[ 8340.229118][ C2] lock((console_sem).lock);
[ 8340.229119][ C2]
[ 8340.229120][ C2] *** DEADLOCK ***
[ 8340.229120][ C2]
[ 8340.229121][ C2] 3 locks held by systemd-udevd/558:
[ 8340.229121][ C2] #0: ffff888118eb9d58 (&mm->mmap_lock#2){++++}-{3:3}, at: do_user_addr_fault+0x228/0xe30
[ 8340.229125][ C2] #1: ffff88811f57f438 (ptlock_ptr(page)#2){+.+.}-{2:2}, at: wp_page_copy+0x5e5/0x1fd0
[ 8340.229129][ C2] #2: ffff88810eee3f20 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x88/0x1780
[ 8340.229132][ C2]
[ 8340.229132][ C2] stack backtrace:
[ 8340.229133][ C2] CPU: 2 PID: 558 Comm: systemd-udevd Not tainted 5.12.0-rc2+ #1
[ 8340.229134][ C2] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 3.2 11/22/2019
[ 8340.229135][ C2] Call Trace:
[ 8340.229135][ C2] <IRQ>
[ 8340.229136][ C2] dump_stack+0x93/0xc2
[ 8340.229136][ C2] check_noncircular+0x235/0x2b0
[ 8340.229137][ C2] ? print_circular_bug+0x460/0x460
[ 8340.229138][ C2] ? vsnprintf+0x830/0x15c0
[ 8340.229138][ C2] __lock_acquire+0x290e/0x58b0
[ 8340.229139][ C2] ? printk_sprint+0x89/0x110
[ 8340.229139][ C2] ? lockdep_hardirqs_on_prepare+0x3e0/0x3e0
[ 8340.229140][ C2] ? vprintk_store+0x4ba/0x630
[ 8340.229141][ C2] lock_acquire+0x181/0x6a0
[ 8340.229141][ C2] ? down_trylock+0x13/0x70
[ 8340.229142][ C2] ? lock_release+0x680/0x680
[ 8340.229142][ C2] ? printk+0x96/0xb2
[ 8340.229143][ C2] _raw_spin_lock_irqsave+0x3b/0x60
[ 8340.229144][ C2] ? down_trylock+0x13/0x70
[ 8340.229144][ C2] down_trylock+0x13/0x70
[ 8340.229145][ C2] ? printk+0x96/0xb2
[ 8340.229145][ C2] __down_trylock_console_sem+0x24/0x90
[ 8340.229146][ C2] vprintk_emit+0x230/0x420
[ 8340.229147][ C2] ? ttwu_queue_wakelist+0x284/0x2f0
[ 8340.229147][ C2] printk+0x96/0xb2
[ 8340.229148][ C2] ? record_print_text.cold+0x11/0x11
[ 8340.229148][ C2] ? find_held_lock+0x2c/0x110
[ 8340.229149][ C2] report_bug.cold+0x31/0x53
[ 8340.229150][ C2] handle_bug+0x41/0x80
[ 8340.229150][ C2] exc_invalid_op+0x14/0x40
[ 8340.229151][ C2] asm_exc_invalid_op+0x12/0x20
[ 8340.229152][ C2] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
[ 8340.229152][ C2] Code: 34 24 e8 3f 7d 63 00 4c 8b 44 24 10 48 8b 4c 24 08 8b 34 24 e9 a1 fe ff ff e8 78 7d 63 00 e9 66 ff ff ff e8 8e 7d 63 00 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 19 7d 63 00 48 8b 04
[ 8340.229154][ C2] RSP: 0000:ffff888811489ce0 EFLAGS: 00010046
[ 8340.229155][ C2] RAX: 0000000000000002 RBX: ffff88810eee3240
[ 8340.229156][ C2] Lost 55 message(s)!
[3]
[40041.712804][T135817] ------------[ cut here ]------------
[40041.718489][T135817] WARNING: CPU: 1 PID: 135817 at kernel/sched/core.c:3175 ttwu_queue_wakelist+0x284/0x2f0
[40041.728311][T135817] Modules linked in: null_blk dm_flakey iscsi_target_mod tcm_loop target_core_pscsi target_core_file target_core_iblock nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw bridge iptable_security stp llc ip_set rfkill nf_tables target_core_user target_core_mod nfnetlink ip6table_filter ip6_tables iptable_filter sunrpc intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_wdt intel_pmc_bxt iTCO_vendor_support rapl intel_cstate intel_uncore joydev lpc_ich i2c_i801 i2c_smbus ses enclosure mei_me mei ipmi_ssif ioatdma wmi acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad zram ip_tables ast drm_vram_helper drm_kms_helper syscopyarea sysfillrect crc32c_intel sysimgblt
[40041.728481][T135817] fb_sys_fops cec drm_ttm_helper ttm ghash_clmulni_intel drm igb mpt3sas nvme dca i2c_algo_bit nvme_core raid_class scsi_transport_sas pkcs8_key_parser [last unloaded: null_blk]
[40041.832215][T135817] CPU: 1 PID: 135817 Comm: fio Not tainted 5.13.0-rc5+ #1
[40041.839262][T135817] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 3.2 11/22/2019
[40041.847434][T135817] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
[40041.853266][T135817] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48 8b 4c 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71 64 00 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 49 71 64 00 48 8b 04
[40041.872793][T135817] RSP: 0018:ffff888106bff348 EFLAGS: 00010046
[40041.878800][T135817] RAX: 0000000000000001 RBX: ffff888117ec3240 RCX: ffff888811440000
[40041.886711][T135817] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffffffffb603d6e8
[40041.894625][T135817] RBP: 0000000000000001 R08: ffffffffb603d6e8 R09: ffffffffb6ba6167
[40041.902537][T135817] R10: fffffbfff6d74c2c R11: 0000000000000001 R12: 0000000000000000
[40041.910451][T135817] R13: ffff88881145fd00 R14: 0000000000000001 R15: ffff888811440001
[40041.918364][T135817] FS: 00007f8eabf14b80(0000) GS:ffff888811440000(0000) knlGS:0000000000000000
[40041.927229][T135817] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[40041.933756][T135817] CR2: 000055ce81e2cc78 CR3: 000000011be92005 CR4: 00000000001706e0
[40041.941669][T135817] Call Trace:
[40041.944895][T135817] ? lock_is_held_type+0x98/0x110
[40041.949860][T135817] try_to_wake_up+0x6f9/0x15e0
[40041.954567][T135817] ? migrate_swap_stop+0x970/0x970
[40041.959618][T135817] ? insert_work+0x193/0x2e0
[40041.964152][T135817] __queue_work+0x4e8/0xdb0
[40041.968599][T135817] ? try_to_grab_pending.part.0+0x439/0x530
[40041.974429][T135817] ? hctx_unlock+0x7d/0xe0
[40041.978790][T135817] mod_delayed_work_on+0x8c/0x100
[40041.983755][T135817] ? cancel_delayed_work+0x1f0/0x1f0
[40041.988982][T135817] ? __blk_mq_delay_run_hw_queue+0x95/0x4b0
[40041.994817][T135817] kblockd_mod_delayed_work_on+0x17/0x20
[40042.000390][T135817] blk_mq_run_hw_queue+0x125/0x270
[40042.005439][T135817] ? blk_mq_delay_run_hw_queues+0x410/0x410
[40042.011275][T135817] blk_mq_sched_insert_request+0x294/0x420
[40042.017020][T135817] ? __blk_mq_sched_bio_merge+0x340/0x340
[40042.022677][T135817] ? blk_mq_rq_ctx_init+0x99a/0xe80
[40042.027819][T135817] blk_mq_submit_bio+0xb37/0x15f0
[40042.032786][T135817] ? blk_mq_try_issue_list_directly+0x940/0x940
[40042.038966][T135817] ? percpu_ref_put_many.constprop.0+0x82/0x1b0
[40042.045148][T135817] submit_bio_noacct+0x79c/0xe60
[40042.050023][T135817] ? blk_queue_enter+0x810/0x810
[40042.054902][T135817] ? find_held_lock+0x2c/0x110
[40042.059611][T135817] submit_bio+0xe4/0x4c0
[40042.063795][T135817] ? submit_bio_noacct+0xe60/0xe60
[40042.068847][T135817] ? bio_add_zone_append_page+0x2c0/0x2c0
[40042.074507][T135817] ? bio_release_pages.part.0+0x10c/0x3d0
[40042.080167][T135817] ? __blkdev_direct_IO_simple+0x436/0x7d0
[40042.085912][T135817] __blkdev_direct_IO_simple+0x40d/0x7d0
[40042.091488][T135817] ? bd_link_disk_holder+0x6e0/0x6e0
[40042.096711][T135817] ? __lock_acquire+0xbbc/0x51b0
[40042.101591][T135817] ? mark_lock+0xe4/0x18a0
[40042.105953][T135817] ? set_init_blocksize.isra.0+0x140/0x140
[40042.111698][T135817] ? mark_lock+0xe4/0x18a0
[40042.116054][T135817] ? lock_is_held_type+0x98/0x110
[40042.121021][T135817] ? find_held_lock+0x2c/0x110
[40042.125730][T135817] blkdev_direct_IO+0xd23/0x11d0
[40042.130607][T135817] ? __lock_acquire+0x15c2/0x51b0
[40042.135577][T135817] ? bd_prepare_to_claim+0x2a0/0x2a0
[40042.140799][T135817] ? __lock_acquire+0x15c2/0x51b0
[40042.145770][T135817] generic_file_read_iter+0x1f4/0x470
[40042.151080][T135817] blkdev_read_iter+0x100/0x190
[40042.155871][T135817] new_sync_read+0x352/0x5d0
[40042.160403][T135817] ? __ia32_sys_llseek+0x310/0x310
[40042.165458][T135817] ? __cond_resched+0x15/0x30
[40042.170076][T135817] ? inode_security+0x56/0xf0
[40042.174698][T135817] vfs_read+0x26c/0x470
[40042.178796][T135817] __x64_sys_pread64+0x17d/0x1d0
[40042.183674][T135817] ? vfs_read+0x470/0x470
[40042.187946][T135817] ? syscall_enter_from_user_mode+0x27/0x70
[40042.193780][T135817] ? trace_hardirqs_on+0x1c/0x110
[40042.198747][T135817] do_syscall_64+0x40/0x80
[40042.203107][T135817] entry_SYSCALL_64_after_hwframe+0x44/0xae
[40042.208939][T135817] RIP: 0033:0x7f8eb5cdb96f
[40042.213297][T135817] Code: 08 89 3c 24 48 89 4c 24 18 e8 7d f3 ff ff 4c 8b 54 24 18 48 8b 54 24 10 41 89 c0 48 8b 74 24 08 8b 3c 24 b8 11 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 31 44 89 c7 48 89 04 24 e8 cd f3 ff ff 48 8b
[40042.232824][T135817] RSP: 002b:00007fffaa10c9d0 EFLAGS: 00000293 ORIG_RAX: 0000000000000011
[40042.241169][T135817] RAX: ffffffffffffffda RBX: 00000000012e2540 RCX: 00007f8eb5cdb96f
[40042.249074][T135817] RDX: 0000000000001000 RSI: 000000000130a000 RDI: 0000000000000009
[40042.256985][T135817] RBP: 00000000012e2540 R08: 0000000000000000 R09: 00007fffaa163080
[40042.264898][T135817] R10: 0000000000862000 R11: 0000000000000293 R12: 00007f8e96829458
[40042.272813][T135817] R13: 0000000000000000 R14: 0000000000001000 R15: 00000000012e2568
[40042.280732][T135817] irq event stamp: 1042448
[40042.285084][T135817] hardirqs last enabled at (1042447): [<ffffffffb320209e>] try_to_grab_pending.part.0+0x1ae/0x530
[40042.295683][T135817] hardirqs last disabled at (1042448): [<ffffffffb3202b3b>] mod_delayed_work_on+0xcb/0x100
[40042.305591][T135817] softirqs last enabled at (1041222): [<ffffffffb31b5316>] __irq_exit_rcu+0x1c6/0x270
[40042.315150][T135817] softirqs last disabled at (1041215): [<ffffffffb31b5316>] __irq_exit_rcu+0x1c6/0x270
[40042.324711][T135817] ---[ end trace b6f997c9a553aa02 ]---
[40042.330118][ C1]
[40042.330119][ C1] ======================================================
[40042.330121][ C1] WARNING: possible circular locking dependency detected
[40042.330123][ C1] 5.13.0-rc5+ #1 Not tainted
[40042.330125][ C1] ------------------------------------------------------
[40042.330126][ C1] fio/135817 is trying to acquire lock:
[40042.330128][ C1] ffffffffb641acb8 ((console_sem).lock){-.-.}-{2:2}, at: down_trylock+0x13/0x70
[40042.330134][ C1]
[40042.330135][ C1] but task is already holding lock:
[40042.330137][ C1] ffff888117ec3f30 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x88/0x15e0
[40042.330142][ C1]
[40042.330144][ C1] which lock already depends on the new lock.
[40042.330145][ C1]
[40042.330146][ C1]
[40042.330147][ C1] the existing dependency chain (in reverse order) is:
[40042.330149][ C1]
[40042.330150][ C1] -> #1 (&p->pi_lock){-.-.}-{2:2}:
[40042.330155][ C1] _raw_spin_lock_irqsave+0x3b/0x60
[40042.330156][ C1] try_to_wake_up+0x88/0x15e0
[40042.330157][ C1] up+0x7a/0xb0
[40042.330159][ C1] __up_console_sem+0x2d/0x60
[40042.330161][ C1] console_unlock+0x3f7/0x840
[40042.330162][ C1] vprintk_emit+0x257/0x420
[40042.330163][ C1] devkmsg_emit.constprop.0+0x95/0xb1
[40042.330165][ C1] devkmsg_write.cold+0x48/0x74
[40042.330166][ C1] do_iter_readv_writev+0x32b/0x6b0
[40042.330167][ C1] do_iter_write+0x137/0x5d0
[40042.330169][ C1] vfs_writev+0x147/0x4a0
[40042.330170][ C1] do_writev+0x100/0x260
[40042.330172][ C1] do_syscall_64+0x40/0x80
[40042.330173][ C1] entry_SYSCALL_64_after_hwframe+0x44/0xae
[40042.330175][ C1]
[40042.330176][ C1] -> #0 ((console_sem).lock){-.-.}-{2:2}:
[40042.330181][ C1] __lock_acquire+0x2940/0x51b0
[40042.330182][ C1] lock_acquire+0x181/0x6a0
[40042.330183][ C1] _raw_spin_lock_irqsave+0x3b/0x60
[40042.330184][ C1] down_trylock+0x13/0x70
[40042.330185][ C1] __down_trylock_console_sem+0x24/0x90
[40042.330186][ C1] vprintk_emit+0x230/0x420
[40042.330187][ C1] printk+0x96/0xb2
[40042.330187][ C1] report_bug.cold+0x31/0x53
[40042.330188][ C1] handle_bug+0x3c/0x70
[40042.330189][ C1] exc_invalid_op+0x14/0x40
[40042.330189][ C1] asm_exc_invalid_op+0x12/0x20
[40042.330190][ C1] ttwu_queue_wakelist+0x284/0x2f0
[40042.330191][ C1] try_to_wake_up+0x6f9/0x15e0
[40042.330192][ C1] __queue_work+0x4e8/0xdb0
[40042.330193][ C1] mod_delayed_work_on+0x8c/0x100
[40042.330194][ C1] kblockd_mod_delayed_work_on+0x17/0x20
[40042.330194][ C1] blk_mq_run_hw_queue+0x125/0x270
[40042.330195][ C1] blk_mq_sched_insert_request+0x294/0x420
[40042.330196][ C1] blk_mq_submit_bio+0xb37/0x15f0
[40042.330197][ C1] submit_bio_noacct+0x79c/0xe60
[40042.330198][ C1] submit_bio+0xe4/0x4c0
[40042.330199][ C1] __blkdev_direct_IO_simple+0x40d/0x7d0
[40042.330199][ C1] blkdev_direct_IO+0xd23/0x11d0
[40042.330200][ C1] generic_file_read_iter+0x1f4/0x470
[40042.330201][ C1] blkdev_read_iter+0x100/0x190
[40042.330202][ C1] new_sync_read+0x352/0x5d0
[40042.330203][ C1] vfs_read+0x26c/0x470
[40042.330203][ C1] __x64_sys_pread64+0x17d/0x1d0
[40042.330204][ C1] do_syscall_64+0x40/0x80
[40042.330205][ C1] entry_SYSCALL_64_after_hwframe+0x44/0xae
[40042.330206][ C1]
[40042.330206][ C1] other info that might help us debug this:
[40042.330207][ C1]
[40042.330208][ C1] Possible unsafe locking scenario:
[40042.330208][ C1]
[40042.330209][ C1] CPU0 CPU1
[40042.330210][ C1] ---- ----
[40042.330210][ C1] lock(&p->pi_lock);
[40042.330212][ C1] lock((console_sem).lock);
[40042.330214][ C1] lock(&p->pi_lock);
[40042.330216][ C1] lock((console_sem).lock);
[40042.330217][ C1]
[40042.330218][ C1] *** DEADLOCK ***
[40042.330218][ C1]
[40042.330219][ C1] 3 locks held by fio/135817:
[40042.330220][ C1] #0: ffffffffb643ae80 (rcu_read_lock){....}-{1:2}, at: __queue_work+0xa0/0xdb0
[40042.330223][ C1] #1: ffff8888114730d8 (&pool->lock){-.-.}-{2:2}, at: __queue_work+0x2ce/0xdb0
[40042.330227][ C1] #2: ffff888117ec3f30 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x88/0x15e0
[40042.330230][ C1]
[40042.330231][ C1] stack backtrace:
[40042.330231][ C1] CPU: 1 PID: 135817 Comm: fio Not tainted 5.13.0-rc5+ #1
[40042.330232][ C1] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 3.2 11/22/2019
[40042.330233][ C1] Call Trace:
[40042.330234][ C1] dump_stack+0x93/0xc2
[40042.330234][ C1] check_noncircular+0x235/0x2b0
[40042.330235][ C1] ? print_circular_bug+0x1f0/0x1f0
[40042.330236][ C1] ? enable_ptr_key_workfn+0x20/0x20
[40042.330237][ C1] ? desc_read+0x218/0x2e0
[40042.330237][ C1] ? vsnprintf+0x830/0x15c0
[40042.330238][ C1] __lock_acquire+0x2940/0x51b0
[40042.330239][ C1] ? printk_sprint+0x89/0x110
[40042.330239][ C1] ? lockdep_hardirqs_on_prepare+0x3e0/0x3e0
[40042.330240][ C1] ? vprintk_store+0x581/0x630
[40042.330241][ C1] lock_acquire+0x181/0x6a0
[40042.330242][ C1] ? down_trylock+0x13/0x70
[40042.330242][ C1] ? lock_release+0x680/0x680
[40042.330243][ C1] ? lock_chain_count+0x20/0x20
[40042.330244][ C1] ? lock_downgrade+0x6a0/0x6a0
[40042.330245][ C1] ? printk+0x96/0xb2
[40042.330246][ C1] _raw_spin_lock_irqsave+0x3b/0x60
[40042.330248][ C1] ? down_trylock+0x13/0x70
[40042.330249][ C1] down_trylock+0x13/0x70
[40042.330250][ C1] ? printk+0x96/0xb2
[40042.330252][ C1] __down_trylock_console_sem+0x24/0x90
[40042.330253][ C1] vprintk_emit+0x230/0x420
[40042.330254][ C1] ? ttwu_queue_wakelist+0x284/0x2f0
[40042.330255][ C1] printk+0x96/0xb2
[40042.330256][ C1] ? record_print_text.cold+0x11/0x11
[40042.330258][ C1] report_bug.cold+0x31/0x53
[40042.330259][ C1] ? ttwu_queue_wakelist+0x284/0x2f0
[40042.330260][ C1] handle_bug+0x3c/0x70
[40042.330262][ C1] exc_invalid_op+0x14/0x40
[40042.330263][ C1] asm_exc_invalid_op+0x12/0x20
[40042.330264][ C1] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
[40042.330266][ C1] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48 8b 4c 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71 64 00 eb a0 <0f> 0b 45 31 ff e9 cb
[40042.330269][ C1] Lost 69 message(s)!
--
Best Regards,
Shin'ichiro Kawasaki
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: WARNING at blktests block/008 in ttwu_queue_wakelist()
2021-06-09 6:53 WARNING at blktests block/008 in ttwu_queue_wakelist() Shinichiro Kawasaki
@ 2021-06-09 6:55 ` Damien Le Moal
2021-07-09 14:50 ` Bart Van Assche
[not found] ` <20210610083200.3832-1-hdanton@sina.com>
1 sibling, 1 reply; 6+ messages in thread
From: Damien Le Moal @ 2021-06-09 6:55 UTC (permalink / raw)
To: Shinichiro Kawasaki, linux-block, Jens Axboe, LKML
+ Jens and linux-kernel
On 2021/06/09 15:53, Shinichiro Kawasaki wrote:
> Hi there,
>
> Let me share a blktests failure. When I ran blktests on the kernel v5.13-rc5,
> block/008 failed. A WARNING below was the cause of the failure.
>
> WARNING: CPU: 1 PID: 135817 at kernel/sched/core.c:3175 ttwu_queue_wakelist+0x284/0x2f0
>
> I'm trying to recreate the failure repeating the test case, but so far, I am not
> able to. This failure looks rare, but actually, I observed it 3 times in the
> past one year.
>
> 1) Oct/2020, kernel: v5.9-rc7 test dev: dm-flakey on AHCI-SATA SMR HDD, log [1]
> 2) Mar/2021, kernel: v5.12-rc2 test dev: AHCI-SATA SMR HDD, log [2]
> 3) Jun/2021, kernel: v5.13-rc5 test dev: dm-linear on null_blk zoned, log [3]
>
> The test case block/008 does IO during CPU hotplug, and the WARNING in
> ttwu_queue_wakelist() checks "WARN_ON_ONCE(cpu == smp_processor_id())".
> So it is likely that the test case triggers the warning, but I don't have
> clear view why and how the warning was triggered. It was observed on various
> block devices, so I would like to ask linux-block experts if anyone can tell
> what is going on. Comments will be appreciated.
>
>
> [1]
>
> [29603.810633][T127266] ------------[ cut here ]------------
> [29603.816381][T127266] WARNING: CPU: 4 PID: 127266 at kernel/sched/core.c:2670 ttwu_queue_wakelist+0x27c/0x2b0
> [29603.826198][T127266] Modules linked in: dm_flakey iscsi_target_mod tcm_loop target_core_pscsi target_core_file target_core_iblock xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tftp nf_conntrack_tftp tun bridge stp llc nft_objref nf_conntrack_netbios_ns nf_conntrack_broadcast nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_tables ebtable_nat ebtable_broute ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c iptable_mangle iptable_raw iptable_security target_core_user rfkill target_core_mod ip_set nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter sunrpc intel_rapl_msr iTCO_wdt iTCO_vendor_support intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass intel_cstate intel_uncore joydev pcspkr i2c_i801 i2c_smbus mei_me mei lpc_ich ses enclosure ioatdma wmi
> [29603.826259][T127266] ipmi_ssif ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad ip_tables drm_vram_helper drm_kms_helper crct10dif_pclmul drm_ttm_helper crc32_pclmul ttm crc32c_intel drm ghash_clmulni_intel igb mpt3sas nvme dca nvme_core i2c_algo_bit raid_class scsi_transport_sas fuse [last unloaded: null_blk]
> [29603.941330][T127266] CPU: 4 PID: 127266 Comm: fio Not tainted 5.9.0-rc7 #1
> [29603.948201][T127266] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 2.0 12/17/2015
> [29603.956368][T127266] RIP: 0010:ttwu_queue_wakelist+0x27c/0x2b0
> [29603.962198][T127266] Code: 89 e7 e8 37 5d 60 00 e9 2c fe ff ff e8 3d 5d 60 00 e9 f0 fd ff ff e8 53 5d 60 00 e9 41 ff ff ff e8 89 5d 60 00 e9 7b ff ff ff <0f> 0b e9 a6 fe ff ff 48 89 04 24 e8 04 5d 60 00 48 8b 04 24 e9 8e
> [29603.981715][T127266] RSP: 0018:ffff88856b3ef3f0 EFLAGS: 00010046
> [29603.987714][T127266] RAX: 0000000000000004 RBX: ffff88861ad21200 RCX: ffff88861ad00000
> [29603.995616][T127266] RDX: 0000000000000000 RSI: 0000000000000004 RDI: ffffffff98dfe920
> [29604.003521][T127266] RBP: 0000000000000000 R08: 0000000000000004 R09: ffffffff9988a227
> [29604.011425][T127266] R10: fffffbfff3311444 R11: 0000000000000001 R12: 0000000000000004
> [29604.019330][T127266] R13: ffff8886035b8000 R14: 0000000000000004 R15: ffffffff98dfe920
> [29604.027235][T127266] FS: 00007f43b1067a40(0000) GS:ffff88861ad00000(0000) knlGS:0000000000000000
> [29604.036099][T127266] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [29604.042618][T127266] CR2: 00007f2a8eeeb421 CR3: 000000057abf2001 CR4: 00000000001706e0
> [29604.050523][T127266] Call Trace:
> [29604.053757][T127266] ? lock_is_held_type+0xbb/0xf0
> [29604.058640][T127266] ? rcu_read_lock_sched_held+0x3f/0x80
> [29604.064123][T127266] try_to_wake_up+0x4f0/0x1420
> [29604.068831][T127266] ? migrate_swap_stop+0x970/0x970
> [29604.073882][T127266] ? insert_work+0x18b/0x2d0
> [29604.078417][T127266] __queue_work+0x4f2/0xe90
> [29604.082863][T127266] ? try_to_grab_pending.part.0+0x23/0x530
> [29604.088604][T127266] ? lockdep_hardirqs_off+0x80/0xb0
> [29604.093738][T127266] mod_delayed_work_on+0x9a/0x110
> [29604.098703][T127266] ? cancel_delayed_work_sync+0x10/0x10
> [29604.104182][T127266] ? __blk_mq_delay_run_hw_queue+0x95/0x570
> [29604.110019][T127266] kblockd_mod_delayed_work_on+0x17/0x20
> [29604.115586][T127266] blk_mq_run_hw_queue+0x125/0x270
> [29604.120630][T127266] ? blk_mq_delay_run_hw_queues+0x150/0x150
> [29604.126459][T127266] blk_mq_sched_insert_request+0x2d4/0x5f0
> [29604.132201][T127266] ? __blk_mq_sched_bio_merge+0x440/0x440
> [29604.137863][T127266] blk_mq_submit_bio+0xaa4/0x14e0
> [29604.142828][T127266] ? blk_mq_try_issue_directly+0x120/0x120
> [29604.148577][T127266] ? percpu_ref_put_many.constprop.0+0x83/0x150
> [29604.154757][T127266] ? dm_wq_work+0x210/0x210
> [29604.159201][T127266] submit_bio_noacct+0x6b9/0xc30
> [29604.164078][T127266] ? lock_is_held_type+0xbb/0xf0
> [29604.168960][T127266] ? bio_associate_blkg_from_css+0x1c6/0xb00
> [29604.174877][T127266] ? blk_queue_enter+0x7c0/0x7c0
> [29604.179762][T127266] submit_bio+0xe4/0x480
> [29604.183943][T127266] ? submit_bio_noacct+0xc30/0xc30
> [29604.188999][T127266] ? bio_add_pc_page+0xd0/0xd0
> [29604.193702][T127266] ? bio_release_pages.part.0+0x10c/0x3d0
> [29604.199367][T127266] __blkdev_direct_IO_simple+0x41f/0x7a0
> [29604.204938][T127266] ? bd_link_disk_holder+0x780/0x780
> [29604.210160][T127266] ? mark_lock+0x82/0x1470
> [29604.214522][T127266] ? __lock_acquire+0xb66/0x5400
> [29604.219400][T127266] ? bd_may_claim+0xc0/0xc0
> [29604.223847][T127266] ? __lock_acquire+0x1603/0x5400
> [29604.228811][T127266] blkdev_direct_IO+0xd6a/0x1070
> [29604.233690][T127266] ? mark_lock+0x82/0x1470
> [29604.238053][T127266] ? __lock_acquire+0x1603/0x5400
> [29604.243016][T127266] ? bd_prepare_to_claim+0x220/0x220
> [29604.248247][T127266] ? lockdep_hardirqs_on_prepare+0x4f0/0x4f0
> [29604.254164][T127266] generic_file_read_iter+0x1f4/0x470
> [29604.259477][T127266] new_sync_read+0x350/0x5d0
> [29604.264007][T127266] ? vfs_dedupe_file_range+0x5c0/0x5c0
> [29604.269414][T127266] ? inode_security+0x56/0xf0
> [29604.274032][T127266] vfs_read+0x296/0x4a0
> [29604.278126][T127266] __x64_sys_pread64+0x17d/0x1d0
> [29604.283004][T127266] ? vfs_read+0x4a0/0x4a0
> [29604.287271][T127266] ? trace_hardirqs_on+0x20/0x170
> [29604.292238][T127266] do_syscall_64+0x33/0x40
> [29604.296593][T127266] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [29604.302421][T127266] RIP: 0033:0x7f43baf6924f
> [29604.306778][T127266] Code: 08 89 3c 24 48 89 4c 24 18 e8 ed f3 ff ff 4c 8b 54 24 18 48 8b 54 24 10 41 89 c0 48 8b 74 24 08 8b 3c 24 b8 11 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 31 44 89 c7 48 89 04 24 e8 1d f4 ff ff 48 8b
> [29604.326303][T127266] RSP: 002b:00007ffec6c62e60 EFLAGS: 00000293 ORIG_RAX: 0000000000000011
> [29604.334648][T127266] RAX: ffffffffffffffda RBX: 00000000011fc540 RCX: 00007f43baf6924f
> [29604.342554][T127266] RDX: 0000000000001000 RSI: 00000000012ac000 RDI: 0000000000000008
> [29604.350459][T127266] RBP: 00000000011fc540 R08: 0000000000000000 R09: 00007ffec6d7b1b0
> [29604.358370][T127266] R10: 0000000001936000 R11: 0000000000000293 R12: 00007f43576f4d20
> [29604.366276][T127266] R13: 0000000000000000 R14: 0000000000001000 R15: 00000000011fc568
> [29604.374188][T127266] irq event stamp: 78824
> [29604.378368][T127266] hardirqs last enabled at (78823): [<ffffffff963c4550>] ktime_get+0x150/0x190
> [29604.387318][T127266] hardirqs last disabled at (78824): [<ffffffff96239567>] mod_delayed_work_on+0xd7/0x110
> [29604.397045][T127266] softirqs last enabled at (78564): [<ffffffff98201092>] asm_call_irq_on_stack+0x12/0x20
> [29604.406861][T127266] softirqs last disabled at (78555): [<ffffffff98201092>] asm_call_irq_on_stack+0x12/0x20
> [29604.416673][T127266] ---[ end trace effce0b470837a17 ]---
> [29604.422074][ C4]
> [29604.422075][ C4] ======================================================
> [29604.422076][ C4] WARNING: possible circular locking dependency detected
> [29604.422077][ C4] 5.9.0-rc7 #1 Not tainted
> [29604.422078][ C4] ------------------------------------------------------
> [29604.422079][ C4] fio/127266 is trying to acquire lock:
> [29604.422079][ C4] ffffffff9913a678 ((console_sem).lock){-.-.}-{2:2}, at: down_trylock+0x13/0x70
> [29604.422083][ C4]
> [29604.422083][ C4] but task is already holding lock:
> [29604.422084][ C4] ffff8886035b8c38 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x84/0x1420
> [29604.422087][ C4]
> [29604.422088][ C4] which lock already depends on the new lock.
> [29604.422088][ C4]
> [29604.422089][ C4]
> [29604.422090][ C4] the existing dependency chain (in reverse order) is:
> [29604.422090][ C4]
> [29604.422091][ C4] -> #1 (&p->pi_lock){-.-.}-{2:2}:
> [29604.422094][ C4] _raw_spin_lock_irqsave+0x48/0x60
> [29604.422095][ C4] try_to_wake_up+0x84/0x1420
> [29604.422095][ C4] up+0x7a/0xb0
> [29604.422096][ C4] __up_console_sem+0x3c/0x70
> [29604.422097][ C4] console_unlock+0x451/0xa10
> [29604.422098][ C4] vprintk_emit+0x232/0x510
> [29604.422099][ C4] devkmsg_emit.constprop.0+0x97/0xb3
> [29604.422100][ C4] devkmsg_write.cold+0x48/0x74
> [29604.422101][ C4] do_iter_readv_writev+0x34c/0x6d0
> [29604.422102][ C4] do_iter_write+0x137/0x5d0
> [29604.422102][ C4] vfs_writev+0x14a/0x280
> [29604.422103][ C4] do_writev+0x100/0x260
> [29604.422104][ C4] do_syscall_64+0x33/0x40
> [29604.422105][ C4] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [29604.422106][ C4]
> [29604.422106][ C4] -> #0 ((console_sem).lock){-.-.}-{2:2}:
> [29604.422110][ C4] __lock_acquire+0x29e4/0x5400
> [29604.422111][ C4] lock_acquire+0x18f/0x990
> [29604.422112][ C4] _raw_spin_lock_irqsave+0x48/0x60
> [29604.422113][ C4] down_trylock+0x13/0x70
> [29604.422114][ C4] __down_trylock_console_sem+0x33/0xb0
> [29604.422115][ C4] vprintk_emit+0x203/0x510
> [29604.422115][ C4] printk+0x96/0xb2
> [29604.422116][ C4] report_bug.cold+0x31/0x5e
> [29604.422117][ C4] handle_bug+0x3d/0xa0
> [29604.422118][ C4] exc_invalid_op+0x14/0x40
> [29604.422119][ C4] asm_exc_invalid_op+0x12/0x20
> [29604.422120][ C4] ttwu_queue_wakelist+0x27c/0x2b0
> [29604.422121][ C4] try_to_wake_up+0x4f0/0x1420
> [29604.422122][ C4] __queue_work+0x4f2/0xe90
> [29604.422122][ C4] mod_delayed_work_on+0x9a/0x110
> [29604.422124][ C4] kblockd_mod_delayed_work_on+0x17/0x20
> [29604.422124][ C4] blk_mq_run_hw_queue+0x125/0x270
> [29604.422125][ C4] blk_mq_sched_insert_request+0x2d4/0x5f0
> [29604.422126][ C4] blk_mq_submit_bio+0xaa4/0x14e0
> [29604.422127][ C4] submit_bio_noacct+0x6b9/0xc30
> [29604.422128][ C4] submit_bio+0xe4/0x480
> [29604.422129][ C4] __blkdev_direct_IO_simple+0x41f/0x7a0
> [29604.422130][ C4] blkdev_direct_IO+0xd6a/0x1070
> [29604.422131][ C4] generic_file_read_iter+0x1f4/0x470
> [29604.422132][ C4] new_sync_read+0x350/0x5d0
> [29604.422133][ C4] vfs_read+0x296/0x4a0
> [29604.422134][ C4] __x64_sys_pread64+0x17d/0x1d0
> [29604.422135][ C4] do_syscall_64+0x33/0x40
> [29604.422135][ C4] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [29604.422136][ C4]
> [29604.422137][ C4] other info that might help us debug this:
> [29604.422138][ C4]
> [29604.422139][ C4] Possible unsafe locking scenario:
> [29604.422139][ C4]
> [29604.422140][ C4] CPU0 CPU1
> [29604.422141][ C4] ---- ----
> [29604.422142][ C4] lock(&p->pi_lock);
> [29604.422144][ C4] lock((console_sem).lock);
> [29604.422146][ C4] lock(&p->pi_lock);
> [29604.422148][ C4] lock((console_sem).lock);
> [29604.422149][ C4]
> [29604.422150][ C4] *** DEADLOCK ***
> [29604.422151][ C4]
> [29604.422152][ C4] 3 locks held by fio/127266:
> [29604.422152][ C4] #0: ffffffff99159260 (rcu_read_lock){....}-{1:2}, at: __queue_work+0xa0/0xe90
> [29604.422156][ C4] #1: ffff88861ad33a58 (&pool->lock){-.-.}-{2:2}, at: __queue_work+0x2d3/0xe90
> [29604.422159][ C4] #2: ffff8886035b8c38 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x84/0x1420
> [29604.422163][ C4]
> [29604.422164][ C4] stack backtrace:
> [29604.422165][ C4] CPU: 4 PID: 127266 Comm: fio Not tainted 5.9.0-rc7 #1
> [29604.422166][ C4] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 2.0 12/17/2015
> [29604.422167][ C4] Call Trace:
> [29604.422168][ C4] dump_stack+0xae/0xe8
> [29604.422169][ C4] check_noncircular+0x2fc/0x3b0
> [29604.422169][ C4] ? print_circular_bug+0x370/0x370
> [29604.422170][ C4] ? stack_trace_save+0x81/0xa0
> [29604.422171][ C4] ? lock_repin_lock+0x370/0x370
> [29604.422172][ C4] __lock_acquire+0x29e4/0x5400
> [29604.422173][ C4] ? lockdep_hardirqs_on_prepare+0x4f0/0x4f0
> [29604.422174][ C4] lock_acquire+0x18f/0x990
> [29604.422174][ C4] ? down_trylock+0x13/0x70
> [29604.422175][ C4] ? sched_clock_cpu+0x18/0x170
> [29604.422176][ C4] ? lock_release+0x7c0/0x7c0
> [29604.422177][ C4] ? find_held_lock+0x2c/0x110
> [29604.422178][ C4] ? vprintk_emit+0x1ba/0x510
> [29604.422179][ C4] _raw_spin_lock_irqsave+0x48/0x60
> [29604.422179][ C4] ? down_trylock+0x13/0x70
> [29604.422180][ C4] down_trylock+0x13/0x70
> [29604.422181][ C4] ? printk+0x96/0xb2
> [29604.422182][ C4] __down_trylock_console_sem+0x33/0xb0
> [29604.422183][ C4] vprintk_emit+0x203/0x510
> [29604.422183][ C4] ? ttwu_queue_wakelist+0x27c/0x2b0
> [29604.422184][ C4] printk+0x96/0xb2
> [29604.422185][ C4] ? log_store.cold+0x11/0x11
> [29604.422187][ C4] ? mark_lock+0x82/0x1470
> [29604.422188][ C4] report_bug.cold+0x31/0x5e
> [29604.422189][ C4] handle_bug+0x3d/0xa0
> [29604.422190][ C4] ? lock_acquire+0x18f/0x990
> [29604.422191][ C4] exc_invalid_op+0x14/0x40
> [29604.422191][ C4] asm_exc_invalid_op+0x12/0x20
> [29604.422192][ C4] RIP: 0010:ttwu_queue_wakelist+0x27c/0x2b0
> [29604.422193][ C4] Code: 89 e7 e8 37 5d 60 00 e9 2c fe ff ff e8 3d 5d 60 00 e9 f0 fd ff ff e8 53 5d 60 00 e9 41 ff ff ff e8 89 5d 60 00 e9 7b ff ff ff <0f> 0b e9 a6 fe ff ff 48 89 04 24 e8 04 5d 60 00 48 8b 04 24 e9 8e
> [29604.422194][ C4] RSP: 0018:ffff88856b3ef3f0 EFLAGS: 00010046
> [29604.422195][ C4] RAX: 000000000
> [29604.422197][ C4] Lost 62 message(s)!
>
>
> [2]
>
> [ 8339.653610][ C2] ------------[ cut here ]------------
> [ 8339.659324][ C2] WARNING: CPU: 2 PID: 558 at kernel/sched/core.c:3158 ttwu_queue_wakelist+0x284/0x2f0
> [ 8339.668804][ C2] Modules linked in: iscsi_target_mod tcm_loop target_core_pscsi target_core_file target_core_iblock nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw iptable_security ip_set nf_tables bridge stp llc nfnetlink rfkill target_core_user ip6table_filter target_core_mod ip6_tables iptable_filter sunrpc intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_wdt rapl intel_pmc_bxt iTCO_vendor_support intel_cstate joydev mei_me ses i2c_i801 mei intel_uncore enclosure ipmi_ssif lpc_ich i2c_smbus ioatdma wmi acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad zram ip_tables ast drm_vram_helper drm_kms_helper crc32c_intel syscopyarea sysfillrect sysimgblt fb_sys_fops cec
> [ 8339.668927][ C2] drm_ttm_helper ttm ghash_clmulni_intel drm mpt3sas igb raid_class scsi_transport_sas nvme dca nvme_core i2c_algo_bit pkcs8_key_parser [last unloaded: zonefs]
> [ 8339.770658][ C2] CPU: 2 PID: 558 Comm: systemd-udevd Not tainted 5.12.0-rc2+ #1
> [ 8339.778222][ C2] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 3.2 11/22/2019
> [ 8339.786310][ C2] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> [ 8339.792054][ C2] Code: 34 24 e8 3f 7d 63 00 4c 8b 44 24 10 48 8b 4c 24 08 8b 34 24 e9 a1 fe ff ff e8 78 7d 63 00 e9 66 ff ff ff e8 8e 7d 63 00 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 19 7d 63 00 48 8b 04
> [ 8339.811494][ C2] RSP: 0000:ffff888811489ce0 EFLAGS: 00010046
> [ 8339.817415][ C2] RAX: 0000000000000002 RBX: ffff88810eee3240 RCX: ffff888811480000
> [ 8339.825240][ C2] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffffffff91e2c6f0
> [ 8339.833067][ C2] RBP: 0000000000000002 R08: ffffffff91e2c6f0 R09: ffffffff929a2ba7
> [ 8339.840894][ C2] R10: fffffbfff2534574 R11: 0000000000000001 R12: 0000000000000000
> [ 8339.848719][ C2] R13: ffff88881149f8c0 R14: 0000000000000002 R15: 0000000000032c01
> [ 8339.856545][ C2] FS: 00007fe9e16cc380(0000) GS:ffff888811480000(0000) knlGS:0000000000000000
> [ 8339.865325][ C2] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 8339.871763][ C2] CR2: 000055d9e787ea88 CR3: 000000011d906004 CR4: 00000000001706e0
> [ 8339.879591][ C2] Call Trace:
> [ 8339.882730][ C2] <IRQ>
> [ 8339.885440][ C2] ? lock_is_held_type+0x98/0x110
> [ 8339.890321][ C2] try_to_wake_up+0x5c7/0x1780
> [ 8339.894940][ C2] ? migrate_swap_stop+0x970/0x970
> [ 8339.899907][ C2] blk_update_request+0x711/0xe50
> [ 8339.904787][ C2] ? scsi_cleanup_rq+0x110/0x180
> [ 8339.909578][ C2] scsi_end_request+0x71/0x620
> [ 8339.914199][ C2] scsi_io_completion+0x176/0xe00
> [ 8339.919078][ C2] ? provisioning_mode_store+0x3f0/0x3f0
> [ 8339.924562][ C2] ? scsi_run_host_queues+0x60/0x60
> [ 8339.929616][ C2] blk_complete_reqs+0x9a/0xd0
> [ 8339.934235][ C2] __do_softirq+0x1d0/0x881
> [ 8339.938596][ C2] __irq_exit_rcu+0x1b9/0x270
> [ 8339.943137][ C2] irq_exit_rcu+0xa/0x20
> [ 8339.947235][ C2] sysvec_call_function_single+0x6f/0x90
> [ 8339.952721][ C2] </IRQ>
> [ 8339.955520][ C2] asm_sysvec_call_function_single+0x12/0x20
> [ 8339.961353][ C2] RIP: 0010:ptep_clear_flush+0x4f/0x150
> [ 8339.966753][ C2] Code: 48 89 f5 48 c1 ea 03 53 80 3c 02 00 0f 85 00 01 00 00 be 08 00 00 00 4c 89 ef 49 8b 5f 40 45 31 f6 e8 85 64 0a 00 4d 87 75 00 <48> c7 c0 78 cf e3 91 48 ba 00 00 00 00 00 fc ff df 48 c1 e8 03 80
> [ 8339.986193][ C2] RSP: 0000:ffff88811faf7ba0 EFLAGS: 00000246
> [ 8339.992111][ C2] RAX: 0000000000000001 RBX: ffff888118eb9c00 RCX: ffffffff8f7c368b
> [ 8339.999939][ C2] RDX: ffffed102446ac7f RSI: 0000000000000008 RDI: ffff8881223563f0
> [ 8340.007764][ C2] RBP: 000055d9e787e000 R08: 0000000000000001 R09: ffff8881223563f7
> [ 8340.015589][ C2] R10: ffffed102446ac7e R11: 0000000000000001 R12: ffff888121105a08
> [ 8340.023417][ C2] R13: ffff8881223563f0 R14: 8000000213aa9865 R15: ffff8881211059c8
> [ 8340.031246][ C2] ? ptep_clear_flush+0x4b/0x150
> [ 8340.036037][ C2] wp_page_copy+0x839/0x1fd0
> [ 8340.040485][ C2] ? lock_release+0x680/0x680
> [ 8340.045015][ C2] ? __do_fault+0x5d0/0x5d0
> [ 8340.049376][ C2] ? do_wp_page+0x318/0x1650
> [ 8340.053822][ C2] __handle_mm_fault+0x1f31/0x4af0
> [ 8340.058787][ C2] ? lock_is_held_type+0x98/0x110
> [ 8340.063666][ C2] ? copy_page_range+0x3810/0x3810
> [ 8340.068635][ C2] ? count_memcg_event_mm.part.0+0xfc/0x1a0
> [ 8340.074377][ C2] ? trace_hardirqs_on+0x1c/0x110
> [ 8340.079257][ C2] handle_mm_fault+0x15f/0x620
> [ 8340.083879][ C2] do_user_addr_fault+0x385/0xe30
> [ 8340.088758][ C2] ? do_kern_addr_fault+0xb0/0xb0
> [ 8340.093636][ C2] ? irqentry_enter+0x55/0x60
> [ 8340.098170][ C2] exc_page_fault+0x60/0xe0
> [ 8340.102528][ C2] ? asm_exc_page_fault+0x8/0x30
> [ 8340.107321][ C2] asm_exc_page_fault+0x1e/0x30
> [ 8340.112027][ C2] RIP: 0033:0x7fe9e25c5cdd
> [ 8340.116301][ C2] Code: 08 48 8b 4f 08 48 89 c8 48 83 e0 f8 48 3b 04 07 0f 85 91 00 00 00 48 8b 47 10 48 8b 57 18 48 3b 78 18 75 69 48 3b 7a 10 75 63 <48> 89 50 18 48 89 42 10 48 81 f9 ff 03 00 00 76 2c 48 8b 57 20 48
> [ 8340.135739][ C2] RSP: 002b:00007fff57b878d0 EFLAGS: 00010246
> [ 8340.141658][ C2] RAX: 000055d9e787ea70 RBX: 000055d9e78851d0 RCX: 0000000000000291
> [ 8340.149485][ C2] RDX: 00007fe9e2701ce0 RSI: 0000000000000002 RDI: 000055d9e78851d0
> [ 8340.157310][ C2] RBP: 00000000000002c0 R08: 000055d9e789cc70 R09: 0000000000000290
> [ 8340.165137][ C2] R10: 0000000000000047 R11: 000055d9e780d130 R12: 00007fe9e2701a00
> [ 8340.172963][ C2] R13: 00007fe9e2701a18 R14: 000000055d9e7885 R15: 000055d9e7885490
> [ 8340.180794][ C2] irq event stamp: 13527209
> [ 8340.185149][ C2] hardirqs last enabled at (13527208): [<ffffffff91400185>] __do_softirq+0x185/0x881
> [ 8340.194536][ C2] hardirqs last disabled at (13527209): [<ffffffff911e2c30>] _raw_spin_lock_irqsave+0x50/0x60
> [ 8340.204616][ C2] softirqs last enabled at (13527014): [<ffffffff8f1af839>] __irq_exit_rcu+0x1b9/0x270
> [ 8340.214175][ C2] softirqs last disabled at (13527207): [<ffffffff8f1af839>] __irq_exit_rcu+0x1b9/0x270
> [ 8340.223735][ C2] ---[ end trace b4a0f179ac6a8cbe ]---
> [ 8340.229054][ C2]
> [ 8340.229056][ C2] ======================================================
> [ 8340.229057][ C2] WARNING: possible circular locking dependency detected
> [ 8340.229058][ C2] 5.12.0-rc2+ #1 Not tainted
> [ 8340.229059][ C2] ------------------------------------------------------
> [ 8340.229059][ C2] systemd-udevd/558 is trying to acquire lock:
> [ 8340.229060][ C2] ffffffff92218b18 ((console_sem).lock){-.-.}-{2:2}, at: down_trylock+0x13/0x70
> [ 8340.229064][ C2]
> [ 8340.229065][ C2] but task is already holding lock:
> [ 8340.229065][ C2] ffff88810eee3f20 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x88/0x1780
> [ 8340.229068][ C2]
> [ 8340.229069][ C2] which lock already depends on the new lock.
> [ 8340.229069][ C2]
> [ 8340.229070][ C2]
> [ 8340.229071][ C2] the existing dependency chain (in reverse order) is:
> [ 8340.229071][ C2]
> [ 8340.229072][ C2] -> #1 (&p->pi_lock){-.-.}-{2:2}:
> [ 8340.229074][ C2] _raw_spin_lock_irqsave+0x3b/0x60
> [ 8340.229075][ C2] try_to_wake_up+0x88/0x1780
> [ 8340.229076][ C2] up+0x7a/0xb0
> [ 8340.229076][ C2] __up_console_sem+0x2d/0x60
> [ 8340.229077][ C2] console_unlock+0x41b/0x880
> [ 8340.229078][ C2] vprintk_emit+0x257/0x420
> [ 8340.229079][ C2] devkmsg_emit.constprop.0+0x95/0xb1
> [ 8340.229080][ C2] devkmsg_write.cold+0x48/0x74
> [ 8340.229082][ C2] do_iter_readv_writev+0x32b/0x6b0
> [ 8340.229083][ C2] do_iter_write+0x137/0x5d0
> [ 8340.229084][ C2] vfs_writev+0x147/0x4a0
> [ 8340.229084][ C2] do_writev+0x100/0x260
> [ 8340.229085][ C2] do_syscall_64+0x33/0x40
> [ 8340.229086][ C2] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [ 8340.229086][ C2]
> [ 8340.229087][ C2] -> #0 ((console_sem).lock){-.-.}-{2:2}:
> [ 8340.229090][ C2] __lock_acquire+0x290e/0x58b0
> [ 8340.229090][ C2] lock_acquire+0x181/0x6a0
> [ 8340.229091][ C2] _raw_spin_lock_irqsave+0x3b/0x60
> [ 8340.229092][ C2] down_trylock+0x13/0x70
> [ 8340.229092][ C2] __down_trylock_console_sem+0x24/0x90
> [ 8340.229093][ C2] vprintk_emit+0x230/0x420
> [ 8340.229094][ C2] printk+0x96/0xb2
> [ 8340.229094][ C2] report_bug.cold+0x31/0x53
> [ 8340.229095][ C2] handle_bug+0x41/0x80
> [ 8340.229096][ C2] exc_invalid_op+0x14/0x40
> [ 8340.229096][ C2] asm_exc_invalid_op+0x12/0x20
> [ 8340.229097][ C2] ttwu_queue_wakelist+0x284/0x2f0
> [ 8340.229098][ C2] try_to_wake_up+0x5c7/0x1780
> [ 8340.229098][ C2] blk_update_request+0x711/0xe50
> [ 8340.229099][ C2] scsi_end_request+0x71/0x620
> [ 8340.229100][ C2] scsi_io_completion+0x176/0xe00
> [ 8340.229100][ C2] blk_complete_reqs+0x9a/0xd0
> [ 8340.229101][ C2] __do_softirq+0x1d0/0x881
> [ 8340.229102][ C2] __irq_exit_rcu+0x1b9/0x270
> [ 8340.229102][ C2] irq_exit_rcu+0xa/0x20
> [ 8340.229103][ C2] sysvec_call_function_single+0x6f/0x90
> [ 8340.229103][ C2] asm_sysvec_call_function_single+0x12/0x20
> [ 8340.229104][ C2] ptep_clear_flush+0x4f/0x150
> [ 8340.229105][ C2] wp_page_copy+0x839/0x1fd0
> [ 8340.229106][ C2] __handle_mm_fault+0x1f31/0x4af0
> [ 8340.229106][ C2] handle_mm_fault+0x15f/0x620
> [ 8340.229107][ C2] do_user_addr_fault+0x385/0xe30
> [ 8340.229108][ C2] exc_page_fault+0x60/0xe0
> [ 8340.229108][ C2] asm_exc_page_fault+0x1e/0x30
> [ 8340.229109][ C2]
> [ 8340.229109][ C2] other info that might help us debug this:
> [ 8340.229110][ C2]
> [ 8340.229110][ C2] Possible unsafe locking scenario:
> [ 8340.229111][ C2]
> [ 8340.229112][ C2] CPU0 CPU1
> [ 8340.229112][ C2] ---- ----
> [ 8340.229113][ C2] lock(&p->pi_lock);
> [ 8340.229114][ C2] lock((console_sem).lock);
> [ 8340.229116][ C2] lock(&p->pi_lock);
> [ 8340.229118][ C2] lock((console_sem).lock);
> [ 8340.229119][ C2]
> [ 8340.229120][ C2] *** DEADLOCK ***
> [ 8340.229120][ C2]
> [ 8340.229121][ C2] 3 locks held by systemd-udevd/558:
> [ 8340.229121][ C2] #0: ffff888118eb9d58 (&mm->mmap_lock#2){++++}-{3:3}, at: do_user_addr_fault+0x228/0xe30
> [ 8340.229125][ C2] #1: ffff88811f57f438 (ptlock_ptr(page)#2){+.+.}-{2:2}, at: wp_page_copy+0x5e5/0x1fd0
> [ 8340.229129][ C2] #2: ffff88810eee3f20 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x88/0x1780
> [ 8340.229132][ C2]
> [ 8340.229132][ C2] stack backtrace:
> [ 8340.229133][ C2] CPU: 2 PID: 558 Comm: systemd-udevd Not tainted 5.12.0-rc2+ #1
> [ 8340.229134][ C2] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 3.2 11/22/2019
> [ 8340.229135][ C2] Call Trace:
> [ 8340.229135][ C2] <IRQ>
> [ 8340.229136][ C2] dump_stack+0x93/0xc2
> [ 8340.229136][ C2] check_noncircular+0x235/0x2b0
> [ 8340.229137][ C2] ? print_circular_bug+0x460/0x460
> [ 8340.229138][ C2] ? vsnprintf+0x830/0x15c0
> [ 8340.229138][ C2] __lock_acquire+0x290e/0x58b0
> [ 8340.229139][ C2] ? printk_sprint+0x89/0x110
> [ 8340.229139][ C2] ? lockdep_hardirqs_on_prepare+0x3e0/0x3e0
> [ 8340.229140][ C2] ? vprintk_store+0x4ba/0x630
> [ 8340.229141][ C2] lock_acquire+0x181/0x6a0
> [ 8340.229141][ C2] ? down_trylock+0x13/0x70
> [ 8340.229142][ C2] ? lock_release+0x680/0x680
> [ 8340.229142][ C2] ? printk+0x96/0xb2
> [ 8340.229143][ C2] _raw_spin_lock_irqsave+0x3b/0x60
> [ 8340.229144][ C2] ? down_trylock+0x13/0x70
> [ 8340.229144][ C2] down_trylock+0x13/0x70
> [ 8340.229145][ C2] ? printk+0x96/0xb2
> [ 8340.229145][ C2] __down_trylock_console_sem+0x24/0x90
> [ 8340.229146][ C2] vprintk_emit+0x230/0x420
> [ 8340.229147][ C2] ? ttwu_queue_wakelist+0x284/0x2f0
> [ 8340.229147][ C2] printk+0x96/0xb2
> [ 8340.229148][ C2] ? record_print_text.cold+0x11/0x11
> [ 8340.229148][ C2] ? find_held_lock+0x2c/0x110
> [ 8340.229149][ C2] report_bug.cold+0x31/0x53
> [ 8340.229150][ C2] handle_bug+0x41/0x80
> [ 8340.229150][ C2] exc_invalid_op+0x14/0x40
> [ 8340.229151][ C2] asm_exc_invalid_op+0x12/0x20
> [ 8340.229152][ C2] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> [ 8340.229152][ C2] Code: 34 24 e8 3f 7d 63 00 4c 8b 44 24 10 48 8b 4c 24 08 8b 34 24 e9 a1 fe ff ff e8 78 7d 63 00 e9 66 ff ff ff e8 8e 7d 63 00 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 19 7d 63 00 48 8b 04
> [ 8340.229154][ C2] RSP: 0000:ffff888811489ce0 EFLAGS: 00010046
> [ 8340.229155][ C2] RAX: 0000000000000002 RBX: ffff88810eee3240
> [ 8340.229156][ C2] Lost 55 message(s)!
>
>
> [3]
>
> [40041.712804][T135817] ------------[ cut here ]------------
> [40041.718489][T135817] WARNING: CPU: 1 PID: 135817 at kernel/sched/core.c:3175 ttwu_queue_wakelist+0x284/0x2f0
> [40041.728311][T135817] Modules linked in: null_blk dm_flakey iscsi_target_mod tcm_loop target_core_pscsi target_core_file target_core_iblock nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw bridge iptable_security stp llc ip_set rfkill nf_tables target_core_user target_core_mod nfnetlink ip6table_filter ip6_tables iptable_filter sunrpc intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_wdt intel_pmc_bxt iTCO_vendor_support rapl intel_cstate intel_uncore joydev lpc_ich i2c_i801 i2c_smbus ses enclosure mei_me mei ipmi_ssif ioatdma wmi acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad zram ip_tables ast drm_vram_helper drm_kms_helper syscopyarea sysfillrect crc32c_intel sysimgblt
> [40041.728481][T135817] fb_sys_fops cec drm_ttm_helper ttm ghash_clmulni_intel drm igb mpt3sas nvme dca i2c_algo_bit nvme_core raid_class scsi_transport_sas pkcs8_key_parser [last unloaded: null_blk]
> [40041.832215][T135817] CPU: 1 PID: 135817 Comm: fio Not tainted 5.13.0-rc5+ #1
> [40041.839262][T135817] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 3.2 11/22/2019
> [40041.847434][T135817] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> [40041.853266][T135817] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48 8b 4c 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71 64 00 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 49 71 64 00 48 8b 04
> [40041.872793][T135817] RSP: 0018:ffff888106bff348 EFLAGS: 00010046
> [40041.878800][T135817] RAX: 0000000000000001 RBX: ffff888117ec3240 RCX: ffff888811440000
> [40041.886711][T135817] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffffffffb603d6e8
> [40041.894625][T135817] RBP: 0000000000000001 R08: ffffffffb603d6e8 R09: ffffffffb6ba6167
> [40041.902537][T135817] R10: fffffbfff6d74c2c R11: 0000000000000001 R12: 0000000000000000
> [40041.910451][T135817] R13: ffff88881145fd00 R14: 0000000000000001 R15: ffff888811440001
> [40041.918364][T135817] FS: 00007f8eabf14b80(0000) GS:ffff888811440000(0000) knlGS:0000000000000000
> [40041.927229][T135817] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [40041.933756][T135817] CR2: 000055ce81e2cc78 CR3: 000000011be92005 CR4: 00000000001706e0
> [40041.941669][T135817] Call Trace:
> [40041.944895][T135817] ? lock_is_held_type+0x98/0x110
> [40041.949860][T135817] try_to_wake_up+0x6f9/0x15e0
> [40041.954567][T135817] ? migrate_swap_stop+0x970/0x970
> [40041.959618][T135817] ? insert_work+0x193/0x2e0
> [40041.964152][T135817] __queue_work+0x4e8/0xdb0
> [40041.968599][T135817] ? try_to_grab_pending.part.0+0x439/0x530
> [40041.974429][T135817] ? hctx_unlock+0x7d/0xe0
> [40041.978790][T135817] mod_delayed_work_on+0x8c/0x100
> [40041.983755][T135817] ? cancel_delayed_work+0x1f0/0x1f0
> [40041.988982][T135817] ? __blk_mq_delay_run_hw_queue+0x95/0x4b0
> [40041.994817][T135817] kblockd_mod_delayed_work_on+0x17/0x20
> [40042.000390][T135817] blk_mq_run_hw_queue+0x125/0x270
> [40042.005439][T135817] ? blk_mq_delay_run_hw_queues+0x410/0x410
> [40042.011275][T135817] blk_mq_sched_insert_request+0x294/0x420
> [40042.017020][T135817] ? __blk_mq_sched_bio_merge+0x340/0x340
> [40042.022677][T135817] ? blk_mq_rq_ctx_init+0x99a/0xe80
> [40042.027819][T135817] blk_mq_submit_bio+0xb37/0x15f0
> [40042.032786][T135817] ? blk_mq_try_issue_list_directly+0x940/0x940
> [40042.038966][T135817] ? percpu_ref_put_many.constprop.0+0x82/0x1b0
> [40042.045148][T135817] submit_bio_noacct+0x79c/0xe60
> [40042.050023][T135817] ? blk_queue_enter+0x810/0x810
> [40042.054902][T135817] ? find_held_lock+0x2c/0x110
> [40042.059611][T135817] submit_bio+0xe4/0x4c0
> [40042.063795][T135817] ? submit_bio_noacct+0xe60/0xe60
> [40042.068847][T135817] ? bio_add_zone_append_page+0x2c0/0x2c0
> [40042.074507][T135817] ? bio_release_pages.part.0+0x10c/0x3d0
> [40042.080167][T135817] ? __blkdev_direct_IO_simple+0x436/0x7d0
> [40042.085912][T135817] __blkdev_direct_IO_simple+0x40d/0x7d0
> [40042.091488][T135817] ? bd_link_disk_holder+0x6e0/0x6e0
> [40042.096711][T135817] ? __lock_acquire+0xbbc/0x51b0
> [40042.101591][T135817] ? mark_lock+0xe4/0x18a0
> [40042.105953][T135817] ? set_init_blocksize.isra.0+0x140/0x140
> [40042.111698][T135817] ? mark_lock+0xe4/0x18a0
> [40042.116054][T135817] ? lock_is_held_type+0x98/0x110
> [40042.121021][T135817] ? find_held_lock+0x2c/0x110
> [40042.125730][T135817] blkdev_direct_IO+0xd23/0x11d0
> [40042.130607][T135817] ? __lock_acquire+0x15c2/0x51b0
> [40042.135577][T135817] ? bd_prepare_to_claim+0x2a0/0x2a0
> [40042.140799][T135817] ? __lock_acquire+0x15c2/0x51b0
> [40042.145770][T135817] generic_file_read_iter+0x1f4/0x470
> [40042.151080][T135817] blkdev_read_iter+0x100/0x190
> [40042.155871][T135817] new_sync_read+0x352/0x5d0
> [40042.160403][T135817] ? __ia32_sys_llseek+0x310/0x310
> [40042.165458][T135817] ? __cond_resched+0x15/0x30
> [40042.170076][T135817] ? inode_security+0x56/0xf0
> [40042.174698][T135817] vfs_read+0x26c/0x470
> [40042.178796][T135817] __x64_sys_pread64+0x17d/0x1d0
> [40042.183674][T135817] ? vfs_read+0x470/0x470
> [40042.187946][T135817] ? syscall_enter_from_user_mode+0x27/0x70
> [40042.193780][T135817] ? trace_hardirqs_on+0x1c/0x110
> [40042.198747][T135817] do_syscall_64+0x40/0x80
> [40042.203107][T135817] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [40042.208939][T135817] RIP: 0033:0x7f8eb5cdb96f
> [40042.213297][T135817] Code: 08 89 3c 24 48 89 4c 24 18 e8 7d f3 ff ff 4c 8b 54 24 18 48 8b 54 24 10 41 89 c0 48 8b 74 24 08 8b 3c 24 b8 11 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 31 44 89 c7 48 89 04 24 e8 cd f3 ff ff 48 8b
> [40042.232824][T135817] RSP: 002b:00007fffaa10c9d0 EFLAGS: 00000293 ORIG_RAX: 0000000000000011
> [40042.241169][T135817] RAX: ffffffffffffffda RBX: 00000000012e2540 RCX: 00007f8eb5cdb96f
> [40042.249074][T135817] RDX: 0000000000001000 RSI: 000000000130a000 RDI: 0000000000000009
> [40042.256985][T135817] RBP: 00000000012e2540 R08: 0000000000000000 R09: 00007fffaa163080
> [40042.264898][T135817] R10: 0000000000862000 R11: 0000000000000293 R12: 00007f8e96829458
> [40042.272813][T135817] R13: 0000000000000000 R14: 0000000000001000 R15: 00000000012e2568
> [40042.280732][T135817] irq event stamp: 1042448
> [40042.285084][T135817] hardirqs last enabled at (1042447): [<ffffffffb320209e>] try_to_grab_pending.part.0+0x1ae/0x530
> [40042.295683][T135817] hardirqs last disabled at (1042448): [<ffffffffb3202b3b>] mod_delayed_work_on+0xcb/0x100
> [40042.305591][T135817] softirqs last enabled at (1041222): [<ffffffffb31b5316>] __irq_exit_rcu+0x1c6/0x270
> [40042.315150][T135817] softirqs last disabled at (1041215): [<ffffffffb31b5316>] __irq_exit_rcu+0x1c6/0x270
> [40042.324711][T135817] ---[ end trace b6f997c9a553aa02 ]---
> [40042.330118][ C1]
> [40042.330119][ C1] ======================================================
> [40042.330121][ C1] WARNING: possible circular locking dependency detected
> [40042.330123][ C1] 5.13.0-rc5+ #1 Not tainted
> [40042.330125][ C1] ------------------------------------------------------
> [40042.330126][ C1] fio/135817 is trying to acquire lock:
> [40042.330128][ C1] ffffffffb641acb8 ((console_sem).lock){-.-.}-{2:2}, at: down_trylock+0x13/0x70
> [40042.330134][ C1]
> [40042.330135][ C1] but task is already holding lock:
> [40042.330137][ C1] ffff888117ec3f30 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x88/0x15e0
> [40042.330142][ C1]
> [40042.330144][ C1] which lock already depends on the new lock.
> [40042.330145][ C1]
> [40042.330146][ C1]
> [40042.330147][ C1] the existing dependency chain (in reverse order) is:
> [40042.330149][ C1]
> [40042.330150][ C1] -> #1 (&p->pi_lock){-.-.}-{2:2}:
> [40042.330155][ C1] _raw_spin_lock_irqsave+0x3b/0x60
> [40042.330156][ C1] try_to_wake_up+0x88/0x15e0
> [40042.330157][ C1] up+0x7a/0xb0
> [40042.330159][ C1] __up_console_sem+0x2d/0x60
> [40042.330161][ C1] console_unlock+0x3f7/0x840
> [40042.330162][ C1] vprintk_emit+0x257/0x420
> [40042.330163][ C1] devkmsg_emit.constprop.0+0x95/0xb1
> [40042.330165][ C1] devkmsg_write.cold+0x48/0x74
> [40042.330166][ C1] do_iter_readv_writev+0x32b/0x6b0
> [40042.330167][ C1] do_iter_write+0x137/0x5d0
> [40042.330169][ C1] vfs_writev+0x147/0x4a0
> [40042.330170][ C1] do_writev+0x100/0x260
> [40042.330172][ C1] do_syscall_64+0x40/0x80
> [40042.330173][ C1] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [40042.330175][ C1]
> [40042.330176][ C1] -> #0 ((console_sem).lock){-.-.}-{2:2}:
> [40042.330181][ C1] __lock_acquire+0x2940/0x51b0
> [40042.330182][ C1] lock_acquire+0x181/0x6a0
> [40042.330183][ C1] _raw_spin_lock_irqsave+0x3b/0x60
> [40042.330184][ C1] down_trylock+0x13/0x70
> [40042.330185][ C1] __down_trylock_console_sem+0x24/0x90
> [40042.330186][ C1] vprintk_emit+0x230/0x420
> [40042.330187][ C1] printk+0x96/0xb2
> [40042.330187][ C1] report_bug.cold+0x31/0x53
> [40042.330188][ C1] handle_bug+0x3c/0x70
> [40042.330189][ C1] exc_invalid_op+0x14/0x40
> [40042.330189][ C1] asm_exc_invalid_op+0x12/0x20
> [40042.330190][ C1] ttwu_queue_wakelist+0x284/0x2f0
> [40042.330191][ C1] try_to_wake_up+0x6f9/0x15e0
> [40042.330192][ C1] __queue_work+0x4e8/0xdb0
> [40042.330193][ C1] mod_delayed_work_on+0x8c/0x100
> [40042.330194][ C1] kblockd_mod_delayed_work_on+0x17/0x20
> [40042.330194][ C1] blk_mq_run_hw_queue+0x125/0x270
> [40042.330195][ C1] blk_mq_sched_insert_request+0x294/0x420
> [40042.330196][ C1] blk_mq_submit_bio+0xb37/0x15f0
> [40042.330197][ C1] submit_bio_noacct+0x79c/0xe60
> [40042.330198][ C1] submit_bio+0xe4/0x4c0
> [40042.330199][ C1] __blkdev_direct_IO_simple+0x40d/0x7d0
> [40042.330199][ C1] blkdev_direct_IO+0xd23/0x11d0
> [40042.330200][ C1] generic_file_read_iter+0x1f4/0x470
> [40042.330201][ C1] blkdev_read_iter+0x100/0x190
> [40042.330202][ C1] new_sync_read+0x352/0x5d0
> [40042.330203][ C1] vfs_read+0x26c/0x470
> [40042.330203][ C1] __x64_sys_pread64+0x17d/0x1d0
> [40042.330204][ C1] do_syscall_64+0x40/0x80
> [40042.330205][ C1] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [40042.330206][ C1]
> [40042.330206][ C1] other info that might help us debug this:
> [40042.330207][ C1]
> [40042.330208][ C1] Possible unsafe locking scenario:
> [40042.330208][ C1]
> [40042.330209][ C1] CPU0 CPU1
> [40042.330210][ C1] ---- ----
> [40042.330210][ C1] lock(&p->pi_lock);
> [40042.330212][ C1] lock((console_sem).lock);
> [40042.330214][ C1] lock(&p->pi_lock);
> [40042.330216][ C1] lock((console_sem).lock);
> [40042.330217][ C1]
> [40042.330218][ C1] *** DEADLOCK ***
> [40042.330218][ C1]
> [40042.330219][ C1] 3 locks held by fio/135817:
> [40042.330220][ C1] #0: ffffffffb643ae80 (rcu_read_lock){....}-{1:2}, at: __queue_work+0xa0/0xdb0
> [40042.330223][ C1] #1: ffff8888114730d8 (&pool->lock){-.-.}-{2:2}, at: __queue_work+0x2ce/0xdb0
> [40042.330227][ C1] #2: ffff888117ec3f30 (&p->pi_lock){-.-.}-{2:2}, at: try_to_wake_up+0x88/0x15e0
> [40042.330230][ C1]
> [40042.330231][ C1] stack backtrace:
> [40042.330231][ C1] CPU: 1 PID: 135817 Comm: fio Not tainted 5.13.0-rc5+ #1
> [40042.330232][ C1] Hardware name: Supermicro Super Server/X10SRL-F, BIOS 3.2 11/22/2019
> [40042.330233][ C1] Call Trace:
> [40042.330234][ C1] dump_stack+0x93/0xc2
> [40042.330234][ C1] check_noncircular+0x235/0x2b0
> [40042.330235][ C1] ? print_circular_bug+0x1f0/0x1f0
> [40042.330236][ C1] ? enable_ptr_key_workfn+0x20/0x20
> [40042.330237][ C1] ? desc_read+0x218/0x2e0
> [40042.330237][ C1] ? vsnprintf+0x830/0x15c0
> [40042.330238][ C1] __lock_acquire+0x2940/0x51b0
> [40042.330239][ C1] ? printk_sprint+0x89/0x110
> [40042.330239][ C1] ? lockdep_hardirqs_on_prepare+0x3e0/0x3e0
> [40042.330240][ C1] ? vprintk_store+0x581/0x630
> [40042.330241][ C1] lock_acquire+0x181/0x6a0
> [40042.330242][ C1] ? down_trylock+0x13/0x70
> [40042.330242][ C1] ? lock_release+0x680/0x680
> [40042.330243][ C1] ? lock_chain_count+0x20/0x20
> [40042.330244][ C1] ? lock_downgrade+0x6a0/0x6a0
> [40042.330245][ C1] ? printk+0x96/0xb2
> [40042.330246][ C1] _raw_spin_lock_irqsave+0x3b/0x60
> [40042.330248][ C1] ? down_trylock+0x13/0x70
> [40042.330249][ C1] down_trylock+0x13/0x70
> [40042.330250][ C1] ? printk+0x96/0xb2
> [40042.330252][ C1] __down_trylock_console_sem+0x24/0x90
> [40042.330253][ C1] vprintk_emit+0x230/0x420
> [40042.330254][ C1] ? ttwu_queue_wakelist+0x284/0x2f0
> [40042.330255][ C1] printk+0x96/0xb2
> [40042.330256][ C1] ? record_print_text.cold+0x11/0x11
> [40042.330258][ C1] report_bug.cold+0x31/0x53
> [40042.330259][ C1] ? ttwu_queue_wakelist+0x284/0x2f0
> [40042.330260][ C1] handle_bug+0x3c/0x70
> [40042.330262][ C1] exc_invalid_op+0x14/0x40
> [40042.330263][ C1] asm_exc_invalid_op+0x12/0x20
> [40042.330264][ C1] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> [40042.330266][ C1] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48 8b 4c 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71 64 00 eb a0 <0f> 0b 45 31 ff e9 cb
> [40042.330269][ C1] Lost 69 message(s)!
>
--
Damien Le Moal
Western Digital Research
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: WARNING at blktests block/008 in ttwu_queue_wakelist()
[not found] ` <20210610083200.3832-1-hdanton@sina.com>
@ 2021-06-28 4:43 ` Shinichiro Kawasaki
2021-07-09 3:57 ` Shinichiro Kawasaki
0 siblings, 1 reply; 6+ messages in thread
From: Shinichiro Kawasaki @ 2021-06-28 4:43 UTC (permalink / raw)
To: Hillf Danton
Cc: Damien Le Moal, Block, Jens Axboe, Peter Zijlstra, Tejun Heo, LKML
On Jun 10, 2021 / 16:32, Hillf Danton wrote:
> On Wed, 9 Jun 2021 06:55:59 +0000 Damien Le Moal wrote:
> >+ Jens and linux-kernel
> >
> >On 2021/06/09 15:53, Shinichiro Kawasaki wrote:
> >> Hi there,
> >>
> >> Let me share a blktests failure. When I ran blktests on the kernel v5.13-rc5,
> >> block/008 failed. A WARNING below was the cause of the failure.
> >>
> >> WARNING: CPU: 1 PID: 135817 at kernel/sched/core.c:3175 ttwu_queue_wakelist+0x284/0x2f0
> >>
> >> I'm trying to recreate the failure repeating the test case, but so far, I am
> >> not able to. This failure looks rare, but actually, I observed it 3 times in
> >> the past one year.
> >>
> >> 1) Oct/2020, kernel: v5.9-rc7 test dev: dm-flakey on AHCI-SATA SMR HDD, log [1]
> >> 2) Mar/2021, kernel: v5.12-rc2 test dev: AHCI-SATA SMR HDD, log [2]
> >> 3) Jun/2021, kernel: v5.13-rc5 test dev: dm-linear on null_blk zoned, log [3]
> >>
> >> The test case block/008 does IO during CPU hotplug, and the WARNING in
> >> ttwu_queue_wakelist() checks "WARN_ON_ONCE(cpu == smp_processor_id())".
> >> So it is likely that the test case triggers the warning, but I don't have
> >> clear view why and how the warning was triggered. It was observed on various
> >> block devices, so I would like to ask linux-block experts if anyone can tell
> >> what is going on. Comments will be appreciated.
>
> [...]
>
> >> [40041.712804][T135817] ------------[ cut here ]------------
> >> [40041.718489][T135817] WARNING: CPU: 1 PID: 135817 at kernel/sched/core.=
> >c:3175 ttwu_queue_wakelist+0x284/0x2f0
> >> [40041.728311][T135817] Modules linked in: null_blk dm_flakey iscsi_targe=
> >t_mod tcm_loop target_core_pscsi target_core_file target_core_iblock nft_fi=
> >b_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_=
> >reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat ip6table_mangle ip=
> >6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6=
> > nf_defrag_ipv4 iptable_mangle iptable_raw bridge iptable_security stp llc =
> >ip_set rfkill nf_tables target_core_user target_core_mod nfnetlink ip6table=
> >_filter ip6_tables iptable_filter sunrpc intel_rapl_msr intel_rapl_common x=
> >86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_=
> >wdt intel_pmc_bxt iTCO_vendor_support rapl intel_cstate intel_uncore joydev=
> > lpc_ich i2c_i801 i2c_smbus ses enclosure mei_me mei ipmi_ssif ioatdma wmi =
> >acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad zr=
> >am ip_tables ast drm_vram_helper drm_kms_helper syscopyarea sysfillrect crc=
> >32c_intel sysimgblt
> >> [40041.728481][T135817] fb_sys_fops cec drm_ttm_helper ttm ghash_clmulni=
> >_intel drm igb mpt3sas nvme dca i2c_algo_bit nvme_core raid_class scsi_tran=
> >sport_sas pkcs8_key_parser [last unloaded: null_blk]
> >> [40041.832215][T135817] CPU: 1 PID: 135817 Comm: fio Not tainted 5.13.0-r=
> >c5+ #1
> >> [40041.839262][T135817] Hardware name: Supermicro Super Server/X10SRL-F, =
> >BIOS 3.2 11/22/2019
> >> [40041.847434][T135817] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> >> [40041.853266][T135817] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48 8b 4=
> >c 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71 64 0=
> >0 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 49 71 64 00 48 8b 04=
> >
> >> [40041.872793][T135817] RSP: 0018:ffff888106bff348 EFLAGS: 00010046
> >> [40041.878800][T135817] RAX: 0000000000000001 RBX: ffff888117ec3240 RCX: =
> >ffff888811440000
> >> [40041.886711][T135817] RDX: 0000000000000000 RSI: 0000000000000001 RDI: =
> >ffffffffb603d6e8
> >> [40041.894625][T135817] RBP: 0000000000000001 R08: ffffffffb603d6e8 R09: =
> >ffffffffb6ba6167
> >> [40041.902537][T135817] R10: fffffbfff6d74c2c R11: 0000000000000001 R12: =
> >0000000000000000
> >> [40041.910451][T135817] R13: ffff88881145fd00 R14: 0000000000000001 R15: =
> >ffff888811440001
> >> [40041.918364][T135817] FS: 00007f8eabf14b80(0000) GS:ffff888811440000(0=
> >000) knlGS:0000000000000000
> >> [40041.927229][T135817] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033=
> >
> >> [40041.933756][T135817] CR2: 000055ce81e2cc78 CR3: 000000011be92005 CR4: =
> >00000000001706e0
> >> [40041.941669][T135817] Call Trace:
> >> [40041.944895][T135817] ? lock_is_held_type+0x98/0x110
> >> [40041.949860][T135817] try_to_wake_up+0x6f9/0x15e0
>
> 2) __queue_work
> raw_spin_lock(&pwq->pool->lock) with irq disabled
> insert_work
> wake_up_worker(pool);
> wake_up_process first_idle_worker(pool);
>
> Even if waker is lucky enough running on worker's CPU, what is weird is an
> idle worker can trigger the warning, given
>
> if (smp_load_acquire(&p->on_cpu) &&
> ttwu_queue_wakelist(p, task_cpu(p), wake_flags | WF_ON_CPU))
> goto unlock;
>
> because p->on_cpu must have been false for quite a while.
>
> Is there any chance for CPU hotplug to make a difference?
>
> Thoughts are welcome.
>
> Hillf
Hillf, thank you very much for the comments, and sorry about this late reply.
I walked through related functions to understand your comments and, but I have
to say that I still don't have enough background knowledge to provide valuable
comments back to you. I understand that the waker and the wakee are on same CPU,
and it is weird that p->on_cpu is true. This looks indicating that the task
scheduler failing to control task status on task migration triggered by CPU
hotplugs, but as far as I read comments in kernel/sched/core.c, CPU hotplug and
task migration are folded into the design and implementation.
The blktests test case block/008 runs I/Os to a test target block device 30
seconds. During this I/O, it repeats offlining CPUs and onlining CPUs: when
there are N CPUs are available, it offlines N-1 CPUs to have only one online
CPU, then onlines all CPUs again. It repeats this online and offline until I/O
workload completes. When the only one CPU is online, the waker and the wakee can
be on the same CPU. Or, one of the waker or the wakee might have been migrated
from other CPUs to the only one online CPU. But still it is not clear for me why
it results in the WARNING.
Now I'm trying to recreate the failure. By repeating test cases in "block
group" on the kernel v5.13-rc5, I was able to recreate the failure. It took 3 to
5 hours to recreate it. The test target block device used was a null_blk with
rather unique configuration (zoned device with zone capacity smaller than zone
size). I will try to confirm the failure recreation with latest kernel version
and other block devices.
--
Best Regards,
Shin'ichiro Kawasaki
>
> >> [40041.954567][T135817] ? migrate_swap_stop+0x970/0x970
> >> [40041.959618][T135817] ? insert_work+0x193/0x2e0
> >> [40041.964152][T135817] __queue_work+0x4e8/0xdb0
> >> [40041.968599][T135817] ? try_to_grab_pending.part.0+0x439/0x530
> >> [40041.974429][T135817] ? hctx_unlock+0x7d/0xe0
> >> [40041.978790][T135817] mod_delayed_work_on+0x8c/0x100
> >> [40041.983755][T135817] ? cancel_delayed_work+0x1f0/0x1f0
> >> [40041.988982][T135817] ? __blk_mq_delay_run_hw_queue+0x95/0x4b0
> >> [40041.994817][T135817] kblockd_mod_delayed_work_on+0x17/0x20
>
> 1) try to queue work on kblockd_workqueue that is bound percpu workqueue, so
> kworker is bound to one CPU.
>
> >> [40042.000390][T135817] blk_mq_run_hw_queue+0x125/0x270
> >> [40042.005439][T135817] ? blk_mq_delay_run_hw_queues+0x410/0x410
> >> [40042.011275][T135817] blk_mq_sched_insert_request+0x294/0x420
> >> [40042.017020][T135817] ? __blk_mq_sched_bio_merge+0x340/0x340
> >> [40042.022677][T135817] ? blk_mq_rq_ctx_init+0x99a/0xe80
> >> [40042.027819][T135817] blk_mq_submit_bio+0xb37/0x15f0
> >> [40042.032786][T135817] ? blk_mq_try_issue_list_directly+0x940/0x940
> >> [40042.038966][T135817] ? percpu_ref_put_many.constprop.0+0x82/0x1b0
> >> [40042.045148][T135817] submit_bio_noacct+0x79c/0xe60
> >> [40042.050023][T135817] ? blk_queue_enter+0x810/0x810
> >> [40042.054902][T135817] ? find_held_lock+0x2c/0x110
> >> [40042.059611][T135817] submit_bio+0xe4/0x4c0
> >> [40042.063795][T135817] ? submit_bio_noacct+0xe60/0xe60
> >> [40042.068847][T135817] ? bio_add_zone_append_page+0x2c0/0x2c0
> >> [40042.074507][T135817] ? bio_release_pages.part.0+0x10c/0x3d0
> >> [40042.080167][T135817] ? __blkdev_direct_IO_simple+0x436/0x7d0
> >> [40042.085912][T135817] __blkdev_direct_IO_simple+0x40d/0x7d0
> >> [40042.091488][T135817] ? bd_link_disk_holder+0x6e0/0x6e0
> >> [40042.096711][T135817] ? __lock_acquire+0xbbc/0x51b0
> >> [40042.101591][T135817] ? mark_lock+0xe4/0x18a0
> >> [40042.105953][T135817] ? set_init_blocksize.isra.0+0x140/0x140
> >> [40042.111698][T135817] ? mark_lock+0xe4/0x18a0
> >> [40042.116054][T135817] ? lock_is_held_type+0x98/0x110
> >> [40042.121021][T135817] ? find_held_lock+0x2c/0x110
> >> [40042.125730][T135817] blkdev_direct_IO+0xd23/0x11d0
> >> [40042.130607][T135817] ? __lock_acquire+0x15c2/0x51b0
> >> [40042.135577][T135817] ? bd_prepare_to_claim+0x2a0/0x2a0
> >> [40042.140799][T135817] ? __lock_acquire+0x15c2/0x51b0
> >> [40042.145770][T135817] generic_file_read_iter+0x1f4/0x470
> >> [40042.151080][T135817] blkdev_read_iter+0x100/0x190
> >> [40042.155871][T135817] new_sync_read+0x352/0x5d0
> >> [40042.160403][T135817] ? __ia32_sys_llseek+0x310/0x310
> >> [40042.165458][T135817] ? __cond_resched+0x15/0x30
> >> [40042.170076][T135817] ? inode_security+0x56/0xf0
> >> [40042.174698][T135817] vfs_read+0x26c/0x470
> >> [40042.178796][T135817] __x64_sys_pread64+0x17d/0x1d0
> >> [40042.183674][T135817] ? vfs_read+0x470/0x470
> >> [40042.187946][T135817] ? syscall_enter_from_user_mode+0x27/0x70
> >> [40042.193780][T135817] ? trace_hardirqs_on+0x1c/0x110
> >> [40042.198747][T135817] do_syscall_64+0x40/0x80
> >> [40042.203107][T135817] entry_SYSCALL_64_after_hwframe+0x44/0xae
> >> [40042.208939][T135817] RIP: 0033:0x7f8eb5cdb96f
> >> [40042.213297][T135817] Code: 08 89 3c 24 48 89 4c 24 18 e8 7d f3 ff ff 4=
> >c 8b 54 24 18 48 8b 54 24 10 41 89 c0 48 8b 74 24 08 8b 3c 24 b8 11 00 00 0=
> >0 0f 05 <48> 3d 00 f0 ff ff 77 31 44 89 c7 48 89 04 24 e8 cd f3 ff ff 48 8b=
> >
> >> [40042.232824][T135817] RSP: 002b:00007fffaa10c9d0 EFLAGS: 00000293 ORIG_=
> >RAX: 0000000000000011
> >> [40042.241169][T135817] RAX: ffffffffffffffda RBX: 00000000012e2540 RCX: =
> >00007f8eb5cdb96f
> >> [40042.249074][T135817] RDX: 0000000000001000 RSI: 000000000130a000 RDI: =
> >0000000000000009
> >> [40042.256985][T135817] RBP: 00000000012e2540 R08: 0000000000000000 R09: =
> >00007fffaa163080
> >> [40042.264898][T135817] R10: 0000000000862000 R11: 0000000000000293 R12: =
> >00007f8e96829458
> >> [40042.272813][T135817] R13: 0000000000000000 R14: 0000000000001000 R15: =
> >00000000012e2568
> >> [40042.280732][T135817] irq event stamp: 1042448
> >> [40042.285084][T135817] hardirqs last enabled at (1042447): [<ffffffffb3=
> >20209e>] try_to_grab_pending.part.0+0x1ae/0x530
> >> [40042.295683][T135817] hardirqs last disabled at (1042448): [<ffffffffb3=
> >202b3b>] mod_delayed_work_on+0xcb/0x100
> >> [40042.305591][T135817] softirqs last enabled at (1041222): [<ffffffffb3=
> >1b5316>] __irq_exit_rcu+0x1c6/0x270
> >> [40042.315150][T135817] softirqs last disabled at (1041215): [<ffffffffb3=
> >1b5316>] __irq_exit_rcu+0x1c6/0x270
> >> [40042.324711][T135817] ---[ end trace b6f997c9a553aa02 ]---
> >> [40042.330118][ C1]
> >> [40042.330119][ C1] =================
> >==========================
> >=============
> >> [40042.330121][ C1] WARNING: possible circular locking dependency dete=
> >cted
> >> [40042.330123][ C1] 5.13.0-rc5+ #1 Not tainted
> >> [40042.330125][ C1] --------------------------------------------------=
> >----
> >> [40042.330126][ C1] fio/135817 is trying to acquire lock:
> >> [40042.330128][ C1] ffffffffb641acb8 ((console_sem).lock){-.-.}-{2:2},=
> > at: down_trylock+0x13/0x70
> >> [40042.330134][ C1]
> >> [40042.330135][ C1] but task is already holding lock:
> >> [40042.330137][ C1] ffff888117ec3f30 (&p->pi_lock){-.-.}-{2:2}, at: tr=
> >y_to_wake_up+0x88/0x15e0
> >> [40042.330142][ C1]
> >> [40042.330144][ C1] which lock already depends on the new lock.
> >> [40042.330145][ C1]
> >> [40042.330146][ C1]
> >> [40042.330147][ C1] the existing dependency chain (in reverse order) i=
> >s:
> >> [40042.330149][ C1]
> >> [40042.330150][ C1] -> #1 (&p->pi_lock){-.-.}-{2:2}:
> >> [40042.330155][ C1] _raw_spin_lock_irqsave+0x3b/0x60
> >> [40042.330156][ C1] try_to_wake_up+0x88/0x15e0
> >> [40042.330157][ C1] up+0x7a/0xb0
> >> [40042.330159][ C1] __up_console_sem+0x2d/0x60
> >> [40042.330161][ C1] console_unlock+0x3f7/0x840
> >> [40042.330162][ C1] vprintk_emit+0x257/0x420
> >> [40042.330163][ C1] devkmsg_emit.constprop.0+0x95/0xb1
> >> [40042.330165][ C1] devkmsg_write.cold+0x48/0x74
> >> [40042.330166][ C1] do_iter_readv_writev+0x32b/0x6b0
> >> [40042.330167][ C1] do_iter_write+0x137/0x5d0
> >> [40042.330169][ C1] vfs_writev+0x147/0x4a0
> >> [40042.330170][ C1] do_writev+0x100/0x260
> >> [40042.330172][ C1] do_syscall_64+0x40/0x80
> >> [40042.330173][ C1] entry_SYSCALL_64_after_hwframe+0x44/0xae
> >> [40042.330175][ C1]
> >> [40042.330176][ C1] -> #0 ((console_sem).lock){-.-.}-{2:2}:
> >> [40042.330181][ C1] __lock_acquire+0x2940/0x51b0
> >> [40042.330182][ C1] lock_acquire+0x181/0x6a0
> >> [40042.330183][ C1] _raw_spin_lock_irqsave+0x3b/0x60
> >> [40042.330184][ C1] down_trylock+0x13/0x70
> >> [40042.330185][ C1] __down_trylock_console_sem+0x24/0x90
> >> [40042.330186][ C1] vprintk_emit+0x230/0x420
> >> [40042.330187][ C1] printk+0x96/0xb2
> >> [40042.330187][ C1] report_bug.cold+0x31/0x53
> >> [40042.330188][ C1] handle_bug+0x3c/0x70
> >> [40042.330189][ C1] exc_invalid_op+0x14/0x40
> >> [40042.330189][ C1] asm_exc_invalid_op+0x12/0x20
> >> [40042.330190][ C1] ttwu_queue_wakelist+0x284/0x2f0
> >> [40042.330191][ C1] try_to_wake_up+0x6f9/0x15e0
> >> [40042.330192][ C1] __queue_work+0x4e8/0xdb0
> >> [40042.330193][ C1] mod_delayed_work_on+0x8c/0x100
> >> [40042.330194][ C1] kblockd_mod_delayed_work_on+0x17/0x20
> >> [40042.330194][ C1] blk_mq_run_hw_queue+0x125/0x270
> >> [40042.330195][ C1] blk_mq_sched_insert_request+0x294/0x420
> >> [40042.330196][ C1] blk_mq_submit_bio+0xb37/0x15f0
> >> [40042.330197][ C1] submit_bio_noacct+0x79c/0xe60
> >> [40042.330198][ C1] submit_bio+0xe4/0x4c0
> >> [40042.330199][ C1] __blkdev_direct_IO_simple+0x40d/0x7d0
> >> [40042.330199][ C1] blkdev_direct_IO+0xd23/0x11d0
> >> [40042.330200][ C1] generic_file_read_iter+0x1f4/0x470
> >> [40042.330201][ C1] blkdev_read_iter+0x100/0x190
> >> [40042.330202][ C1] new_sync_read+0x352/0x5d0
> >> [40042.330203][ C1] vfs_read+0x26c/0x470
> >> [40042.330203][ C1] __x64_sys_pread64+0x17d/0x1d0
> >> [40042.330204][ C1] do_syscall_64+0x40/0x80
> >> [40042.330205][ C1] entry_SYSCALL_64_after_hwframe+0x44/0xae
> >> [40042.330206][ C1]
> >> [40042.330206][ C1] other info that might help us debug this:
> >> [40042.330207][ C1]
> >> [40042.330208][ C1] Possible unsafe locking scenario:
> >> [40042.330208][ C1]
> >> [40042.330209][ C1] CPU0 CPU1
> >> [40042.330210][ C1] ---- ----
> >> [40042.330210][ C1] lock(&p->pi_lock);
> >> [40042.330212][ C1] lock((console_sem).=
> >lock);
> >> [40042.330214][ C1] lock(&p->pi_lock);=
> >
> >> [40042.330216][ C1] lock((console_sem).lock);
> >> [40042.330217][ C1]
> >> [40042.330218][ C1] *** DEADLOCK ***
> >> [40042.330218][ C1]
> >> [40042.330219][ C1] 3 locks held by fio/135817:
> >> [40042.330220][ C1] #0: ffffffffb643ae80 (rcu_read_lock){....}-{1:2},=
> > at: __queue_work+0xa0/0xdb0
> >> [40042.330223][ C1] #1: ffff8888114730d8 (&pool->lock){-.-.}-{2:2}, a=
> >t: __queue_work+0x2ce/0xdb0
> >> [40042.330227][ C1] #2: ffff888117ec3f30 (&p->pi_lock){-.-.}-{2:2}, a=
> >t: try_to_wake_up+0x88/0x15e0
> >> [40042.330230][ C1]
> >> [40042.330231][ C1] stack backtrace:
> >> [40042.330231][ C1] CPU: 1 PID: 135817 Comm: fio Not tainted 5.13.0-rc=
> >5+ #1
> >> [40042.330232][ C1] Hardware name: Supermicro Super Server/X10SRL-F, B=
> >IOS 3.2 11/22/2019
> >> [40042.330233][ C1] Call Trace:
> >> [40042.330234][ C1] dump_stack+0x93/0xc2
> >> [40042.330234][ C1] check_noncircular+0x235/0x2b0
> >> [40042.330235][ C1] ? print_circular_bug+0x1f0/0x1f0
> >> [40042.330236][ C1] ? enable_ptr_key_workfn+0x20/0x20
> >> [40042.330237][ C1] ? desc_read+0x218/0x2e0
> >> [40042.330237][ C1] ? vsnprintf+0x830/0x15c0
> >> [40042.330238][ C1] __lock_acquire+0x2940/0x51b0
> >> [40042.330239][ C1] ? printk_sprint+0x89/0x110
> >> [40042.330239][ C1] ? lockdep_hardirqs_on_prepare+0x3e0/0x3e0
> >> [40042.330240][ C1] ? vprintk_store+0x581/0x630
> >> [40042.330241][ C1] lock_acquire+0x181/0x6a0
> >> [40042.330242][ C1] ? down_trylock+0x13/0x70
> >> [40042.330242][ C1] ? lock_release+0x680/0x680
> >> [40042.330243][ C1] ? lock_chain_count+0x20/0x20
> >> [40042.330244][ C1] ? lock_downgrade+0x6a0/0x6a0
> >> [40042.330245][ C1] ? printk+0x96/0xb2
> >> [40042.330246][ C1] _raw_spin_lock_irqsave+0x3b/0x60
> >> [40042.330248][ C1] ? down_trylock+0x13/0x70
> >> [40042.330249][ C1] down_trylock+0x13/0x70
> >> [40042.330250][ C1] ? printk+0x96/0xb2
> >> [40042.330252][ C1] __down_trylock_console_sem+0x24/0x90
> >> [40042.330253][ C1] vprintk_emit+0x230/0x420
> >> [40042.330254][ C1] ? ttwu_queue_wakelist+0x284/0x2f0
> >> [40042.330255][ C1] printk+0x96/0xb2
> >> [40042.330256][ C1] ? record_print_text.cold+0x11/0x11
> >> [40042.330258][ C1] report_bug.cold+0x31/0x53
> >> [40042.330259][ C1] ? ttwu_queue_wakelist+0x284/0x2f0
> >> [40042.330260][ C1] handle_bug+0x3c/0x70
> >> [40042.330262][ C1] exc_invalid_op+0x14/0x40
> >> [40042.330263][ C1] asm_exc_invalid_op+0x12/0x20
> >> [40042.330264][ C1] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> >> [40042.330266][ C1] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48 8b 4c=
> > 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71 64 00=
> > eb a0 <0f> 0b 45 31 ff e9 cb
> >> [40042.330269][ C1] Lost 69 message(s)!
> >>
> >
> >
> >--
> >Damien Le Moal
> >Western Digital Research
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: WARNING at blktests block/008 in ttwu_queue_wakelist()
2021-06-28 4:43 ` Shinichiro Kawasaki
@ 2021-07-09 3:57 ` Shinichiro Kawasaki
2021-10-29 0:54 ` Shinichiro Kawasaki
0 siblings, 1 reply; 6+ messages in thread
From: Shinichiro Kawasaki @ 2021-07-09 3:57 UTC (permalink / raw)
To: Hillf Danton
Cc: Damien Le Moal, Block, Jens Axboe, Peter Zijlstra, Tejun Heo, LKML
On Jun 28, 2021 / 13:43, Shin'ichiro Kawasaki wrote:
> On Jun 10, 2021 / 16:32, Hillf Danton wrote:
> > On Wed, 9 Jun 2021 06:55:59 +0000 Damien Le Moal wrote:
> > >+ Jens and linux-kernel
> > >
> > >On 2021/06/09 15:53, Shinichiro Kawasaki wrote:
> > >> Hi there,
> > >>
> > >> Let me share a blktests failure. When I ran blktests on the kernel v5.13-rc5,
> > >> block/008 failed. A WARNING below was the cause of the failure.
> > >>
> > >> WARNING: CPU: 1 PID: 135817 at kernel/sched/core.c:3175 ttwu_queue_wakelist+0x284/0x2f0
> > >>
> > >> I'm trying to recreate the failure repeating the test case, but so far, I am
> > >> not able to. This failure looks rare, but actually, I observed it 3 times in
> > >> the past one year.
> > >>
> > >> 1) Oct/2020, kernel: v5.9-rc7 test dev: dm-flakey on AHCI-SATA SMR HDD, log [1]
> > >> 2) Mar/2021, kernel: v5.12-rc2 test dev: AHCI-SATA SMR HDD, log [2]
> > >> 3) Jun/2021, kernel: v5.13-rc5 test dev: dm-linear on null_blk zoned, log [3]
> > >>
> > >> The test case block/008 does IO during CPU hotplug, and the WARNING in
> > >> ttwu_queue_wakelist() checks "WARN_ON_ONCE(cpu == smp_processor_id())".
> > >> So it is likely that the test case triggers the warning, but I don't have
> > >> clear view why and how the warning was triggered. It was observed on various
> > >> block devices, so I would like to ask linux-block experts if anyone can tell
> > >> what is going on. Comments will be appreciated.
> >
> > [...]
> >
> > >> [40041.712804][T135817] ------------[ cut here ]------------
> > >> [40041.718489][T135817] WARNING: CPU: 1 PID: 135817 at kernel/sched/core.=
> > >c:3175 ttwu_queue_wakelist+0x284/0x2f0
> > >> [40041.728311][T135817] Modules linked in: null_blk dm_flakey iscsi_targe=
> > >t_mod tcm_loop target_core_pscsi target_core_file target_core_iblock nft_fi=
> > >b_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_=
> > >reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat ip6table_mangle ip=
> > >6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6=
> > > nf_defrag_ipv4 iptable_mangle iptable_raw bridge iptable_security stp llc =
> > >ip_set rfkill nf_tables target_core_user target_core_mod nfnetlink ip6table=
> > >_filter ip6_tables iptable_filter sunrpc intel_rapl_msr intel_rapl_common x=
> > >86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_=
> > >wdt intel_pmc_bxt iTCO_vendor_support rapl intel_cstate intel_uncore joydev=
> > > lpc_ich i2c_i801 i2c_smbus ses enclosure mei_me mei ipmi_ssif ioatdma wmi =
> > >acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad zr=
> > >am ip_tables ast drm_vram_helper drm_kms_helper syscopyarea sysfillrect crc=
> > >32c_intel sysimgblt
> > >> [40041.728481][T135817] fb_sys_fops cec drm_ttm_helper ttm ghash_clmulni=
> > >_intel drm igb mpt3sas nvme dca i2c_algo_bit nvme_core raid_class scsi_tran=
> > >sport_sas pkcs8_key_parser [last unloaded: null_blk]
> > >> [40041.832215][T135817] CPU: 1 PID: 135817 Comm: fio Not tainted 5.13.0-r=
> > >c5+ #1
> > >> [40041.839262][T135817] Hardware name: Supermicro Super Server/X10SRL-F, =
> > >BIOS 3.2 11/22/2019
> > >> [40041.847434][T135817] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> > >> [40041.853266][T135817] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48 8b 4=
> > >c 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71 64 0=
> > >0 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 49 71 64 00 48 8b 04=
> > >
> > >> [40041.872793][T135817] RSP: 0018:ffff888106bff348 EFLAGS: 00010046
> > >> [40041.878800][T135817] RAX: 0000000000000001 RBX: ffff888117ec3240 RCX: =
> > >ffff888811440000
> > >> [40041.886711][T135817] RDX: 0000000000000000 RSI: 0000000000000001 RDI: =
> > >ffffffffb603d6e8
> > >> [40041.894625][T135817] RBP: 0000000000000001 R08: ffffffffb603d6e8 R09: =
> > >ffffffffb6ba6167
> > >> [40041.902537][T135817] R10: fffffbfff6d74c2c R11: 0000000000000001 R12: =
> > >0000000000000000
> > >> [40041.910451][T135817] R13: ffff88881145fd00 R14: 0000000000000001 R15: =
> > >ffff888811440001
> > >> [40041.918364][T135817] FS: 00007f8eabf14b80(0000) GS:ffff888811440000(0=
> > >000) knlGS:0000000000000000
> > >> [40041.927229][T135817] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033=
> > >
> > >> [40041.933756][T135817] CR2: 000055ce81e2cc78 CR3: 000000011be92005 CR4: =
> > >00000000001706e0
> > >> [40041.941669][T135817] Call Trace:
> > >> [40041.944895][T135817] ? lock_is_held_type+0x98/0x110
> > >> [40041.949860][T135817] try_to_wake_up+0x6f9/0x15e0
> >
> > 2) __queue_work
> > raw_spin_lock(&pwq->pool->lock) with irq disabled
> > insert_work
> > wake_up_worker(pool);
> > wake_up_process first_idle_worker(pool);
> >
> > Even if waker is lucky enough running on worker's CPU, what is weird is an
> > idle worker can trigger the warning, given
> >
> > if (smp_load_acquire(&p->on_cpu) &&
> > ttwu_queue_wakelist(p, task_cpu(p), wake_flags | WF_ON_CPU))
> > goto unlock;
> >
> > because p->on_cpu must have been false for quite a while.
> >
> > Is there any chance for CPU hotplug to make a difference?
> >
> > Thoughts are welcome.
> >
> > Hillf
>
> Hillf, thank you very much for the comments, and sorry about this late reply.
>
> I walked through related functions to understand your comments and, but I have
> to say that I still don't have enough background knowledge to provide valuable
> comments back to you. I understand that the waker and the wakee are on same CPU,
> and it is weird that p->on_cpu is true. This looks indicating that the task
> scheduler failing to control task status on task migration triggered by CPU
> hotplugs, but as far as I read comments in kernel/sched/core.c, CPU hotplug and
> task migration are folded into the design and implementation.
>
> The blktests test case block/008 runs I/Os to a test target block device 30
> seconds. During this I/O, it repeats offlining CPUs and onlining CPUs: when
> there are N CPUs are available, it offlines N-1 CPUs to have only one online
> CPU, then onlines all CPUs again. It repeats this online and offline until I/O
> workload completes. When the only one CPU is online, the waker and the wakee can
> be on the same CPU. Or, one of the waker or the wakee might have been migrated
> from other CPUs to the only one online CPU. But still it is not clear for me why
> it results in the WARNING.
>
> Now I'm trying to recreate the failure. By repeating test cases in "block
> group" on the kernel v5.13-rc5, I was able to recreate the failure. It took 3 to
> 5 hours to recreate it. The test target block device used was a null_blk with
> rather unique configuration (zoned device with zone capacity smaller than zone
> size). I will try to confirm the failure recreation with latest kernel version
> and other block devices.
I tried some device setups, and found that dm-linear device on null_blk
recreates the warning consistently. In case anyone wishes to recreate it, let
me share the bash script below which I used. I tried it several times on the
kernel v5.13, and all tries recreated the warning. With my system (nproc is 8),
it took from 3 to 6 hours to recreate.
--------------------------------------------------------------------------------
#!/bin/bash
# create a null_blk device
declare sysfs=/sys/kernel/config/nullb/nullb0
modprobe null_blk nr_devices=0
mkdir "${sysfs}"
echo 1024 > "${sysfs}"/size
echo 1 > "${sysfs}"/memory_backed
echo 1 > "${sysfs}"/power
sleep 1
# create a dm-linear device on the null_blk device
echo "0 $((0x2000 * 4)) linear /dev/nullb0 0" | dmsetup create test
sleep 1
# run blktests, block/008 many times
git clone https://github.com/osandov/blktests.git
cd blktests
echo "TEST_DEVS=( /dev/mapper/test )" > config
for ((i=0;i<1000;i++)); do
echo $i;
if ! ./check block/008; then
break;
fi
done
--
Best Regards,
Shin'ichiro Kawasaki
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: WARNING at blktests block/008 in ttwu_queue_wakelist()
2021-06-09 6:55 ` Damien Le Moal
@ 2021-07-09 14:50 ` Bart Van Assche
0 siblings, 0 replies; 6+ messages in thread
From: Bart Van Assche @ 2021-07-09 14:50 UTC (permalink / raw)
To: Damien Le Moal, Shinichiro Kawasaki, linux-block, Jens Axboe, LKML
On 6/8/21 11:55 PM, Damien Le Moal wrote:
> + Jens and linux-kernel
Since console_sem is involved, could this be a printk() bug?
Bart.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: WARNING at blktests block/008 in ttwu_queue_wakelist()
2021-07-09 3:57 ` Shinichiro Kawasaki
@ 2021-10-29 0:54 ` Shinichiro Kawasaki
0 siblings, 0 replies; 6+ messages in thread
From: Shinichiro Kawasaki @ 2021-10-29 0:54 UTC (permalink / raw)
To: Hillf Danton
Cc: Damien Le Moal, Block, Jens Axboe, Peter Zijlstra, Tejun Heo, LKML
The WARNING I reported with the kernel v5.13-rc5 is still observed with
v5.15-rc7. It took long, but now I think I understand the cause. Here I share my
findings in line.
On Jul 09, 2021 / 03:57, Shinichiro Kawasaki wrote:
> On Jun 28, 2021 / 13:43, Shin'ichiro Kawasaki wrote:
> > On Jun 10, 2021 / 16:32, Hillf Danton wrote:
> > > On Wed, 9 Jun 2021 06:55:59 +0000 Damien Le Moal wrote:
> > > >+ Jens and linux-kernel
> > > >
> > > >On 2021/06/09 15:53, Shinichiro Kawasaki wrote:
> > > >> Hi there,
> > > >>
> > > >> Let me share a blktests failure. When I ran blktests on the kernel v5.13-rc5,
> > > >> block/008 failed. A WARNING below was the cause of the failure.
> > > >>
> > > >> WARNING: CPU: 1 PID: 135817 at kernel/sched/core.c:3175 ttwu_queue_wakelist+0x284/0x2f0
> > > >>
> > > >> I'm trying to recreate the failure repeating the test case, but so far, I am
> > > >> not able to. This failure looks rare, but actually, I observed it 3 times in
> > > >> the past one year.
> > > >>
> > > >> 1) Oct/2020, kernel: v5.9-rc7 test dev: dm-flakey on AHCI-SATA SMR HDD, log [1]
> > > >> 2) Mar/2021, kernel: v5.12-rc2 test dev: AHCI-SATA SMR HDD, log [2]
> > > >> 3) Jun/2021, kernel: v5.13-rc5 test dev: dm-linear on null_blk zoned, log [3]
> > > >>
> > > >> The test case block/008 does IO during CPU hotplug, and the WARNING in
> > > >> ttwu_queue_wakelist() checks "WARN_ON_ONCE(cpu == smp_processor_id())".
> > > >> So it is likely that the test case triggers the warning, but I don't have
> > > >> clear view why and how the warning was triggered. It was observed on various
> > > >> block devices, so I would like to ask linux-block experts if anyone can tell
> > > >> what is going on. Comments will be appreciated.
> > >
> > > [...]
> > >
> > > >> [40041.712804][T135817] ------------[ cut here ]------------
> > > >> [40041.718489][T135817] WARNING: CPU: 1 PID: 135817 at kernel/sched/core.=
> > > >c:3175 ttwu_queue_wakelist+0x284/0x2f0
> > > >> [40041.728311][T135817] Modules linked in: null_blk dm_flakey iscsi_targe=
> > > >t_mod tcm_loop target_core_pscsi target_core_file target_core_iblock nft_fi=
> > > >b_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_=
> > > >reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat ip6table_mangle ip=
> > > >6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6=
> > > > nf_defrag_ipv4 iptable_mangle iptable_raw bridge iptable_security stp llc =
> > > >ip_set rfkill nf_tables target_core_user target_core_mod nfnetlink ip6table=
> > > >_filter ip6_tables iptable_filter sunrpc intel_rapl_msr intel_rapl_common x=
> > > >86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass iTCO_=
> > > >wdt intel_pmc_bxt iTCO_vendor_support rapl intel_cstate intel_uncore joydev=
> > > > lpc_ich i2c_i801 i2c_smbus ses enclosure mei_me mei ipmi_ssif ioatdma wmi =
> > > >acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter acpi_pad zr=
> > > >am ip_tables ast drm_vram_helper drm_kms_helper syscopyarea sysfillrect crc=
> > > >32c_intel sysimgblt
> > > >> [40041.728481][T135817] fb_sys_fops cec drm_ttm_helper ttm ghash_clmulni=
> > > >_intel drm igb mpt3sas nvme dca i2c_algo_bit nvme_core raid_class scsi_tran=
> > > >sport_sas pkcs8_key_parser [last unloaded: null_blk]
> > > >> [40041.832215][T135817] CPU: 1 PID: 135817 Comm: fio Not tainted 5.13.0-r=
> > > >c5+ #1
> > > >> [40041.839262][T135817] Hardware name: Supermicro Super Server/X10SRL-F, =
> > > >BIOS 3.2 11/22/2019
> > > >> [40041.847434][T135817] RIP: 0010:ttwu_queue_wakelist+0x284/0x2f0
> > > >> [40041.853266][T135817] Code: 34 24 e8 6f 71 64 00 4c 8b 44 24 10 48 8b 4=
> > > >c 24 08 8b 34 24 e9 a1 fe ff ff e8 a8 71 64 00 e9 66 ff ff ff e8 be 71 64 0=
> > > >0 eb a0 <0f> 0b 45 31 ff e9 cb fe ff ff 48 89 04 24 e8 49 71 64 00 48 8b 04=
> > > >
> > > >> [40041.872793][T135817] RSP: 0018:ffff888106bff348 EFLAGS: 00010046
> > > >> [40041.878800][T135817] RAX: 0000000000000001 RBX: ffff888117ec3240 RCX: =
> > > >ffff888811440000
> > > >> [40041.886711][T135817] RDX: 0000000000000000 RSI: 0000000000000001 RDI: =
> > > >ffffffffb603d6e8
> > > >> [40041.894625][T135817] RBP: 0000000000000001 R08: ffffffffb603d6e8 R09: =
> > > >ffffffffb6ba6167
> > > >> [40041.902537][T135817] R10: fffffbfff6d74c2c R11: 0000000000000001 R12: =
> > > >0000000000000000
> > > >> [40041.910451][T135817] R13: ffff88881145fd00 R14: 0000000000000001 R15: =
> > > >ffff888811440001
> > > >> [40041.918364][T135817] FS: 00007f8eabf14b80(0000) GS:ffff888811440000(0=
> > > >000) knlGS:0000000000000000
> > > >> [40041.927229][T135817] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033=
> > > >
> > > >> [40041.933756][T135817] CR2: 000055ce81e2cc78 CR3: 000000011be92005 CR4: =
> > > >00000000001706e0
> > > >> [40041.941669][T135817] Call Trace:
> > > >> [40041.944895][T135817] ? lock_is_held_type+0x98/0x110
> > > >> [40041.949860][T135817] try_to_wake_up+0x6f9/0x15e0
> > >
> > > 2) __queue_work
> > > raw_spin_lock(&pwq->pool->lock) with irq disabled
> > > insert_work
> > > wake_up_worker(pool);
> > > wake_up_process first_idle_worker(pool);
> > >
> > > Even if waker is lucky enough running on worker's CPU, what is weird is an
> > > idle worker can trigger the warning, given
> > >
> > > if (smp_load_acquire(&p->on_cpu) &&
> > > ttwu_queue_wakelist(p, task_cpu(p), wake_flags | WF_ON_CPU))
> > > goto unlock;
> > >
> > > because p->on_cpu must have been false for quite a while.
The call trace indicated that the try_to_wake_up() called ttwu_queue_wakelist().
So I had assumed that the ttwu_queue_wakelist() call was in the hunk that Hillf
quoted above. I also had thorugh that weird, but I noticed that there is another
path to call ttwu_queue_wakelist(). try_to_wake_up() calls ttwu_queue() at
another place, and ttwu_queue() calls ttwu_queue_wakelist(). I confirmed that
the warning is reported with this call path. I think this path can happen on
p->cpu false condition.
> > >
> > > Is there any chance for CPU hotplug to make a difference?
I found sd_llc_id change by CPU hotplug affects ttwu_queue_wakelist(). When the
warning is reported, ttwu_queue_cond() returns true in the ttwu_queue_wakelist()
hunk below.
if (sched_feat(TTWU_QUEUE) && ttwu_queue_cond(cpu, wake_flags)) {
if (WARN_ON_ONCE(cpu == smp_processor_id()))
return false;
And in ttwu_queue_cond() hunk below, cpus_share_cache() returns false, even
though smp_processor_id() and cpu are same cpu. This is weird. Why the single
same cpu does not share the cache?
/*
* If the CPU does not share cache, then queue the task on the
* remote rqs wakelist to avoid accessing remote data.
*/
if (!cpus_share_cache(smp_processor_id(), cpu))
return true;
In cpus_share_cache(), sd_llc_id is checked twice with the line below.
return per_cpu(sd_llc_id, this_cpu) == per_cpu(sd_llc_id, that_cpu);
When this_cpu == that_cpu, it is expected sd_llc_id is same. However, when CPU
hotplug is ongoing, scheduler domain destroy and rebuild happens and modifies
sd_llc_id value. Then, the two sd_llc_id references in the code can have
different values.
I think this cpus_share_cached() needs a fix assuming that sd_llc_id may
change. My idea is to add check this_cpu == that_cpu. Based on this idea, I
created a fix and the warning is avoided. I will post the patch for further
discussion and review.
--
Best Regards,
Shin'ichiro Kawasaki
> > >
> > > Thoughts are welcome.
> > >
> > > Hillf
> >
> > Hillf, thank you very much for the comments, and sorry about this late reply.
> >
> > I walked through related functions to understand your comments and, but I have
> > to say that I still don't have enough background knowledge to provide valuable
> > comments back to you. I understand that the waker and the wakee are on same CPU,
> > and it is weird that p->on_cpu is true. This looks indicating that the task
> > scheduler failing to control task status on task migration triggered by CPU
> > hotplugs, but as far as I read comments in kernel/sched/core.c, CPU hotplug and
> > task migration are folded into the design and implementation.
> >
> > The blktests test case block/008 runs I/Os to a test target block device 30
> > seconds. During this I/O, it repeats offlining CPUs and onlining CPUs: when
> > there are N CPUs are available, it offlines N-1 CPUs to have only one online
> > CPU, then onlines all CPUs again. It repeats this online and offline until I/O
> > workload completes. When the only one CPU is online, the waker and the wakee can
> > be on the same CPU. Or, one of the waker or the wakee might have been migrated
> > from other CPUs to the only one online CPU. But still it is not clear for me why
> > it results in the WARNING.
> >
> > Now I'm trying to recreate the failure. By repeating test cases in "block
> > group" on the kernel v5.13-rc5, I was able to recreate the failure. It took 3 to
> > 5 hours to recreate it. The test target block device used was a null_blk with
> > rather unique configuration (zoned device with zone capacity smaller than zone
> > size). I will try to confirm the failure recreation with latest kernel version
> > and other block devices.
>
> I tried some device setups, and found that dm-linear device on null_blk
> recreates the warning consistently. In case anyone wishes to recreate it, let
> me share the bash script below which I used. I tried it several times on the
> kernel v5.13, and all tries recreated the warning. With my system (nproc is 8),
> it took from 3 to 6 hours to recreate.
>
> --------------------------------------------------------------------------------
> #!/bin/bash
>
> # create a null_blk device
> declare sysfs=/sys/kernel/config/nullb/nullb0
> modprobe null_blk nr_devices=0
> mkdir "${sysfs}"
> echo 1024 > "${sysfs}"/size
> echo 1 > "${sysfs}"/memory_backed
> echo 1 > "${sysfs}"/power
> sleep 1
>
> # create a dm-linear device on the null_blk device
> echo "0 $((0x2000 * 4)) linear /dev/nullb0 0" | dmsetup create test
> sleep 1
>
> # run blktests, block/008 many times
> git clone https://github.com/osandov/blktests.git
> cd blktests
> echo "TEST_DEVS=( /dev/mapper/test )" > config
> for ((i=0;i<1000;i++)); do
> echo $i;
> if ! ./check block/008; then
> break;
> fi
> done
>
> --
> Best Regards,
> Shin'ichiro Kawasaki
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2021-10-29 0:54 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-06-09 6:53 WARNING at blktests block/008 in ttwu_queue_wakelist() Shinichiro Kawasaki
2021-06-09 6:55 ` Damien Le Moal
2021-07-09 14:50 ` Bart Van Assche
[not found] ` <20210610083200.3832-1-hdanton@sina.com>
2021-06-28 4:43 ` Shinichiro Kawasaki
2021-07-09 3:57 ` Shinichiro Kawasaki
2021-10-29 0:54 ` Shinichiro Kawasaki
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).