* Hung task in 4.9 using kvm 5.2 @ 2021-06-07 14:56 Christoph Mathys 2021-06-08 9:31 ` Ahmed S. Darwish 0 siblings, 1 reply; 6+ messages in thread From: Christoph Mathys @ 2021-06-07 14:56 UTC (permalink / raw) To: Linux RT Users Hello, When running kvm 5.2 on 4.9-rt (I've yet to verify if !RT is also affected), kvm gets stuck regulary requiring a reboot. I get the hung_task warning below. Any thoughts on how to avoid this problem? Thanks! Christoph [ 2704.403272] INFO: task kvm:18206 blocked for more than 120 seconds. [ 2704.403275] Tainted: G U 4.9.268-realtime-1-prove-rt179 #2 [ 2704.403276] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 2704.403278] kvm D 0 18206 12599 0x00000320 [ 2704.403281] 0000000000000086 ffff88087e268a00 ffff8801d2822840 ffffffff81e19500 [ 2704.403283] 0000000000000000 ffff88087e268a18 ffffc90019637a98 ffffffff81841438 [ 2704.403286] 0000000000000086 ffff8801d2822e38 ffff88087e268a18 ffff88087e268a00 [ 2704.403288] Call Trace: [ 2704.403293] [<ffffffff81841438>] ? __schedule+0x308/0x830 [ 2704.403295] [<ffffffff818419a9>] schedule+0x49/0xd0 [ 2704.403296] [<ffffffff8184334c>] __rt_mutex_slowlock+0x4c/0x190 [ 2704.403298] [<ffffffff81843882>] rt_mutex_slowlock_locked+0xa2/0x290 [ 2704.403300] [<ffffffff8184446b>] __down_read+0x7b/0xb0 [ 2704.403301] [<ffffffff81843070>] down_read+0x40/0x50 [ 2704.403304] [<ffffffff8129cf20>] ? ext4_direct_IO+0x2e0/0xa40 [ 2704.403305] [<ffffffff8129cf20>] ext4_direct_IO+0x2e0/0xa40 [ 2704.403308] [<ffffffff81174789>] generic_file_read_iter+0x3c9/0x7a0 [ 2704.403310] [<ffffffff81251fde>] aio_read+0xbe/0x140 [ 2704.403312] [<ffffffff8121c688>] ? __fget+0x118/0x1e0 [ 2704.403313] [<ffffffff8121c575>] ? __fget+0x5/0x1e0 [ 2704.403315] [<ffffffff8121c7ba>] ? __fdget+0x2a/0x70 [ 2704.403317] [<ffffffff81253802>] do_io_submit+0x602/0x680 [ 2704.403318] [<ffffffff81253387>] ? do_io_submit+0x187/0x680 [ 2704.403320] [<ffffffff81253890>] SyS_io_submit+0x10/0x20 [ 2704.403322] [<ffffffff81001e1b>] do_syscall_64+0x7b/0x160 [ 2704.403324] [<ffffffff81846983>] entry_SYSCALL_64_after_swapgs+0x5d/0xdb [ 2704.403325] INFO: lockdep is turned off. [ 2704.403327] INFO: task worker:18552 blocked for more than 120 seconds. [ 2704.403328] Tainted: G U 4.9.268-realtime-1-prove-rt179 #2 [ 2704.403329] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 2704.403330] worker D 0 18552 12599 0x00000320 [ 2704.403333] 0000000000000082 ffff88087e368a00 ffff8801d2b85080 ffff88086c0b0000 [ 2704.403335] 0000000000000000 ffff88087e368a18 ffffc9001cb63da0 ffffffff81841438 [ 2704.403338] 0000000081e08270 ffff8801d2b85678 ffff88087e368a18 ffff88087e368a00 [ 2704.403340] Call Trace: [ 2704.403341] [<ffffffff81841438>] ? __schedule+0x308/0x830 [ 2704.403343] [<ffffffff818419a9>] schedule+0x49/0xd0 [ 2704.403345] [<ffffffff81219097>] inode_dio_wait+0xa7/0xd0 [ 2704.403347] [<ffffffff810ad650>] ? wake_up_atomic_t+0x90/0x90 [ 2704.403349] [<ffffffff812cd670>] ext4_fallocate+0x480/0xe00 [ 2704.403351] [<ffffffff811f4deb>] vfs_fallocate+0x15b/0x250 [ 2704.403352] [<ffffffff811f6044>] SyS_fallocate+0x44/0x70 [ 2704.403354] [<ffffffff81001e1b>] do_syscall_64+0x7b/0x160 [ 2704.403355] [<ffffffff81846983>] entry_SYSCALL_64_after_swapgs+0x5d/0xdb [ 2704.403357] INFO: lockdep is turned off. ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Hung task in 4.9 using kvm 5.2 2021-06-07 14:56 Hung task in 4.9 using kvm 5.2 Christoph Mathys @ 2021-06-08 9:31 ` Ahmed S. Darwish 2021-06-08 20:32 ` Luis Goncalves 0 siblings, 1 reply; 6+ messages in thread From: Ahmed S. Darwish @ 2021-06-08 9:31 UTC (permalink / raw) To: Christoph Mathys; +Cc: Linux RT Users On Mon, Jun 07, 2021, Christoph Mathys wrote: > > When running kvm 5.2 on 4.9-rt (I've yet to verify if !RT is also > affected), kvm gets stuck regulary requiring a reboot. I get the > hung_task warning below. > > Any thoughts on how to avoid this problem? > Did you try running the same configuration with lockdep ON? Thanks, Ahmed Darwish ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Hung task in 4.9 using kvm 5.2 2021-06-08 9:31 ` Ahmed S. Darwish @ 2021-06-08 20:32 ` Luis Goncalves 2021-06-09 8:55 ` Christoph Mathys 0 siblings, 1 reply; 6+ messages in thread From: Luis Goncalves @ 2021-06-08 20:32 UTC (permalink / raw) To: Ahmed S. Darwish; +Cc: Christoph Mathys, Linux RT Users On Tue, Jun 8, 2021 at 6:31 AM Ahmed S. Darwish <a.darwish@linutronix.de> wrote: > > On Mon, Jun 07, 2021, Christoph Mathys wrote: > > > > When running kvm 5.2 on 4.9-rt (I've yet to verify if !RT is also > > affected), kvm gets stuck regulary requiring a reboot. I get the > > hung_task warning below. > > > > Any thoughts on how to avoid this problem? > > > > Did you try running the same configuration with lockdep ON? Along with Ahmed's suggestion, would you mind testing with v4.9.271-rt182? Also, is there any extra step to reproduce this problem or simply firing up a VM is enough to trigger the problem? Luis ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Hung task in 4.9 using kvm 5.2 2021-06-08 20:32 ` Luis Goncalves @ 2021-06-09 8:55 ` Christoph Mathys 2021-06-10 7:28 ` Christoph Mathys 0 siblings, 1 reply; 6+ messages in thread From: Christoph Mathys @ 2021-06-09 8:55 UTC (permalink / raw) To: Luis Goncalves, Ahmed S. Darwish; +Cc: Linux RT Users Hi, Thanks for taking the time! On 08.06.21 22:32, Luis Goncalves wrote: > Along with Ahmed's suggestion, would you mind testing with v4.9.271-rt182? Just tried with the new kernel and I'm still seeing the problem: [ 3073.054260] INFO: task kvm:8538 blocked for more than 120 seconds. [ 3073.054262] Tainted: G U 4.9.271-realtime-1-prove-rt182 #1 [ 3073.054262] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 3073.054263] kvm D 0 8538 6582 0x00000320 [ 3073.054266] 0000000000000086 ffff88087e468900 ffff8807b2d2d000 ffff88086c0b5000 [ 3073.054268] 000000000000464d ffff88087e468918 ffffc90015feba98 ffffffff8182c3f8 [ 3073.054269] 0000000015febb70 ffff8807b2d2d5f8 ffff88087e468918 ffff88087e468900 [ 3073.054271] Call Trace: [ 3073.054275] [<ffffffff8182c3f8>] ? __schedule+0x308/0x830 [ 3073.054277] [<ffffffff8182c969>] schedule+0x49/0xd0 [ 3073.054278] [<ffffffff8182e30c>] __rt_mutex_slowlock+0x4c/0x190 [ 3073.054279] [<ffffffff8182e842>] rt_mutex_slowlock_locked+0xa2/0x290 [ 3073.054281] [<ffffffff8182f42b>] __down_read+0x7b/0xb0 [ 3073.054282] [<ffffffff8182e030>] down_read+0x40/0x50 [ 3073.054284] [<ffffffff81288cd0>] ? ext4_direct_IO+0x2e0/0xa40 [ 3073.054286] [<ffffffff81288cd0>] ext4_direct_IO+0x2e0/0xa40 [ 3073.054288] [<ffffffff81174319>] generic_file_read_iter+0x3c9/0x7a0 [ 3073.054290] [<ffffffff810b69b1>] ? __lock_acquire+0x291/0x1760 [ 3073.054291] [<ffffffff8123de9e>] aio_read+0xbe/0x140 [ 3073.054293] [<ffffffff8120a888>] ? __fget+0x118/0x1e0 [ 3073.054294] [<ffffffff8120a775>] ? __fget+0x5/0x1e0 [ 3073.054295] [<ffffffff8120a9ba>] ? __fdget+0x2a/0x70 [ 3073.054296] [<ffffffff8123f6c2>] do_io_submit+0x602/0x680 [ 3073.054297] [<ffffffff8123f247>] ? do_io_submit+0x187/0x680 [ 3073.054298] [<ffffffff8123f750>] SyS_io_submit+0x10/0x20 [ 3073.054300] [<ffffffff81001e0b>] do_syscall_64+0x7b/0x160 [ 3073.054301] [<ffffffff81831943>] entry_SYSCALL_64_after_swapgs+0x5d/0xdb [ 3073.054302] Showing all locks held in the system: [ 3073.054307] 2 locks held by khungtaskd/89: [ 3073.054307] #0: (rcu_read_lock){......}, at: [<ffffffff81127d56>] watchdog+0xb6/0x5b0 [ 3073.054311] #1: (tasklist_lock){+.+...}, at: [<ffffffff817ff716>] debug_show_all_locks+0x48/0x161 [ 3073.054322] 1 lock held by in:imklog/839: [ 3073.054323] #0: (&f->f_pos_lock){+.+.+.}, at: [<ffffffff8120bc04>] __fdget_pos+0xa4/0xb0 [ 3073.054345] 1 lock held by in:imklog/6776: [ 3073.054346] #0: (&f->f_pos_lock){+.+.+.}, at: [<ffffffff8120bc04>] __fdget_pos+0xa4/0xb0 [ 3073.054351] 1 lock held by dmesg/8264: [ 3073.054351] #0: (&user->lock){+.+.+.}, at: [<ffffffff810c530b>] devkmsg_read+0x3b/0x2b0 [ 3073.054354] 1 lock held by kvm/8538: [ 3073.054355] #0: (&sb->s_type->i_mutex_key#11){++++++}, at: [<ffffffff81288cd0>] ext4_direct_IO+0x2e0/0xa40 [ 3073.054359] 2 locks held by worker/8909: [ 3073.054359] #0: (sb_writers#7){.+.+.+}, at: [<ffffffff811e31cf>] vfs_fallocate+0x13f/0x250 [ 3073.054362] #1: (&sb->s_type->i_mutex_key#11){++++++}, at: [<ffffffff812b93cb>] ext4_fallocate+0x43b/0xe00 [ 3073.054366] ============================================= [ 3073.054367] INFO: task worker:8909 blocked for more than 120 seconds. [ 3073.054368] Tainted: G U 4.9.271-realtime-1-prove-rt182 #1 [ 3073.054368] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 3073.054369] worker D 0 8909 6582 0x00000320 [ 3073.054370] 0000000000000082 ffff88087e368900 ffff8807bbb95000 ffff88086c0b0000 [ 3073.054372] 0000000000007417 ffff88087e368918 ffffc9001a62fda0 ffffffff8182c3f8 [ 3073.054374] 0000000081e0b810 ffff8807bbb955f8 ffff88087e368918 ffff88087e368900 [ 3073.054375] Call Trace: [ 3073.054377] [<ffffffff8182c3f8>] ? __schedule+0x308/0x830 [ 3073.054378] [<ffffffff8182c969>] schedule+0x49/0xd0 [ 3073.054379] [<ffffffff81207457>] inode_dio_wait+0xa7/0xd0 [ 3073.054380] [<ffffffff810ad450>] ? wake_up_atomic_t+0x90/0x90 [ 3073.054382] [<ffffffff812b9410>] ext4_fallocate+0x480/0xe00 [ 3073.054383] [<ffffffff811e31eb>] vfs_fallocate+0x15b/0x250 [ 3073.054384] [<ffffffff811e4444>] SyS_fallocate+0x44/0x70 [ 3073.054385] [<ffffffff81001e0b>] do_syscall_64+0x7b/0x160 [ 3073.054386] [<ffffffff81831943>] entry_SYSCALL_64_after_swapgs+0x5d/0xdb [ 3073.054387] Showing all locks held in the system: [ 3073.054389] 2 locks held by khungtaskd/89: [ 3073.054390] #0: (rcu_read_lock){......}, at: [<ffffffff81127d56>] watchdog+0xb6/0x5b0 [ 3073.054392] #1: (tasklist_lock){+.+...}, at: [<ffffffff817ff716>] debug_show_all_locks+0x48/0x161 [ 3073.054398] 1 lock held by in:imklog/839: [ 3073.054399] #0: (&f->f_pos_lock){+.+.+.}, at: [<ffffffff8120bc04>] __fdget_pos+0xa4/0xb0 [ 3073.054415] 1 lock held by in:imklog/6776: [ 3073.054415] #0: (&f->f_pos_lock){+.+.+.}, at: [<ffffffff8120bc04>] __fdget_pos+0xa4/0xb0 [ 3073.054419] 1 lock held by dmesg/8264: [ 3073.054419] #0: (&user->lock){+.+.+.}, at: [<ffffffff810c530b>] devkmsg_read+0x3b/0x2b0 [ 3073.054422] 1 lock held by kvm/8538: [ 3073.054422] #0: (&sb->s_type->i_mutex_key#11){++++++}, at: [<ffffffff81288cd0>] ext4_direct_IO+0x2e0/0xa40 [ 3073.054425] 2 locks held by worker/8909: [ 3073.054426] #0: (sb_writers#7){.+.+.+}, at: [<ffffffff811e31cf>] vfs_fallocate+0x13f/0x250 [ 3073.054428] #1: (&sb->s_type->i_mutex_key#11){++++++}, at: [<ffffffff812b93cb>] ext4_fallocate+0x43b/0xe00 [ 3073.054432] ============================================= > Also, is there any extra step to reproduce this problem or simply > firing up a VM is enough to trigger the problem? We are still trying to find a simple setup that triggers the problem, but no luck so far. It seems to happen when a lot of disk IO happens in the guest OS, but only with Windows. It is a Windows 7 guest running inside kvm running inside a Debian 11 Bullseye LXD container. The same test runs fine inside a Debian 8 Jessie LXD container. I can provide the kvm "cmdline" if this is any help... Christoph ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Hung task in 4.9 using kvm 5.2 2021-06-09 8:55 ` Christoph Mathys @ 2021-06-10 7:28 ` Christoph Mathys 2021-06-15 13:49 ` Christoph Mathys 0 siblings, 1 reply; 6+ messages in thread From: Christoph Mathys @ 2021-06-10 7:28 UTC (permalink / raw) To: Luis Goncalves, Ahmed S. Darwish; +Cc: Linux RT Users I think the "hung task" problem is caused by a combination of flags to the -blockdev argument of kvm: aio=native and cache.direct=true When I remove this two settings and just use the kvm default I'm no longer able to reproduce the problem. However, a bit later in the test, another problem occurs: Jun 09 17:23:28 hostname kernel: BUG: unable to handle kernel paging request at fffffffffffffe5a Jun 09 17:23:28 hostname kernel: IP: [<ffffffff811d6a27>] kmem_cache_alloc+0x77/0x290 Jun 09 17:23:28 hostname kernel: PGD 1e15067 Jun 09 17:23:28 hostname kernel: PUD 1e17067 Jun 09 17:23:28 hostname kernel: PMD 0 Jun 09 17:23:28 hostname kernel: Jun 09 17:23:28 hostname kernel: Oops: 0000 [#1] PREEMPT SMP Jun 09 17:23:28 hostname kernel: Modules linked in: cmac arc4 md4 nls_utf8 nft_meta nft_compat nft_chain_nat_ipv6 nf_tables_ipv6 nft_chain_nat_ipv4 nft_counter nf_tables_ipv4 nf_tables binfmt_misc veth ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 xt_comment nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype br_netfilter xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter overlay joydev snd_usb_audio snd_usbmidi_lib coretemp ghash_clmulni_intel aesni_intel snd_hda_codec_hdmi aes_x86_64 lrw gf128mul glue_helper ablk_helper snd_hda_codec_realtek cryptd snd_hda_codec_generic snd_hda_intel Jun 09 17:23:28 hostname kernel: snd_hda_codec snd_hda_core snd_hwdep snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi i915 snd_seq snd_seq_device drm_kms_helper snd_timer drm fb_sys_fops snd syscopyarea sysfillrect soundcore sysimgblt shpchp video mac_hid acpi_pad tpm_tis tpm_tis_core kvm_intel kvm irqbypass squashfs sch_fq_codel cifs fscache parport_pc ppdev lp parport ip_tables x_tables autofs4 btrfs xor raid6_pq hid_generic hid_cherry usbhid hid igb e1000e i2c_algo_bit nvme dca nvme_core ptp pps_core Jun 09 17:23:28 hostname kernel: CPU: 5 PID: 1137 Comm: RTController Tainted: G U 4.9.271-realtime-1-prove-rt182 #1 Jun 09 17:23:28 hostname kernel: Hardware name: Komax AG, Dierikon Komax-PC/KMX-Q170-24V, BIOS D05K1-1L 03/19/2018 Jun 09 17:23:28 hostname kernel: task: ffff8804fb908000 task.stack: ffffc90015fdc000 Jun 09 17:23:28 hostname kernel: RIP: 0010:[<ffffffff811d6a27>] [<ffffffff811d6a27>] kmem_cache_alloc+0x77/0x290 Jun 09 17:23:28 hostname kernel: RSP: 0018:ffffc90015fdfe40 EFLAGS: 00010286 Jun 09 17:23:28 hostname kernel: RAX: 0000000000000000 RBX: 0000000000000001 RCX: 0000000000368895 Jun 09 17:23:28 hostname kernel: RDX: 0000000000368885 RSI: 0000000000368885 RDI: 000000000006c190 Jun 09 17:23:28 hostname kernel: RBP: ffffc90015fdfe70 R08: ffff8804fb908000 R09: ffffc90015fdfda0 Jun 09 17:23:28 hostname kernel: R10: 0000000000000000 R11: 000000000000003d R12: ffff88087dc03900 Jun 09 17:23:28 hostname kernel: R13: ffffffff81238ff1 R14: fffffffffffffe5a R15: 00000000024000c0 Jun 09 17:23:28 hostname kernel: FS: 00007fca5bfff700(0000) GS:ffff88087e480000(0000) knlGS:0000000000000000 Jun 09 17:23:28 hostname kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Jun 09 17:23:28 hostname kernel: CR2: fffffffffffffe5a CR3: 00000005a6c74000 CR4: 0000000000362670 Jun 09 17:23:28 hostname kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Jun 09 17:23:28 hostname kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Jun 09 17:23:28 hostname kernel: Stack: Jun 09 17:23:28 hostname kernel: ffffffff8182ec6e 0000000000000001 ffff8805a787d341 ffff8805a787f440 Jun 09 17:23:28 hostname kernel: ffffffffffffffea ffff8805a787d340 ffffc90015fdff20 ffffffff81238ff1 Jun 09 17:23:28 hostname kernel: 0000000000000320 00000000000000e9 0000000000000000 0000000000000000 Jun 09 17:23:28 hostname kernel: Call Trace: Jun 09 17:23:28 hostname kernel: [<ffffffff8182ec6e>] ? rt_mutex_lock+0x5e/0x80 Jun 09 17:23:28 hostname kernel: [<ffffffff81238ff1>] SyS_epoll_ctl+0x2d1/0xcc0 Jun 09 17:23:28 hostname kernel: [<ffffffff81001e0b>] do_syscall_64+0x7b/0x160 Jun 09 17:23:28 hostname kernel: [<ffffffff81831943>] entry_SYSCALL_64_after_swapgs+0x5d/0xdb Jun 09 17:23:28 hostname kernel: Code: 70 08 48 39 f2 75 e7 48 83 78 10 00 4c 8b 30 0f 84 d7 00 00 00 4d 85 f6 0f 84 ce 00 00 00 49 63 44 24 20 49 8b 3c 24 48 8d 4a 10 <49> 8b 1c 06 4c 89 f0 65 48 0f c7 0f 0f 94 c0 84 c0 74 ac 49 63 Jun 09 17:23:28 hostname kernel: RIP [<ffffffff811d6a27>] kmem_cache_alloc+0x77/0x290 Jun 09 17:23:28 hostname kernel: RSP <ffffc90015fdfe40> Jun 09 17:23:28 hostname kernel: CR2: fffffffffffffe5a Jun 09 17:23:28 hostname kernel: ---[ end trace 0000000000000002 ]--- Jun 09 17:23:28 hostname kernel: BUG: unable to handle kernel paging request at ffff87faa787cafd Jun 09 17:23:28 hostname kernel: IP: [<ffffffff810d53c8>] rcu_cpu_kthread+0x2e8/0x690 Jun 09 17:23:28 hostname kernel: PGD 0 Jun 09 17:23:28 hostname kernel: Jun 09 17:23:28 hostname kernel: Oops: 0000 [#2] PREEMPT SMP Jun 09 17:23:28 hostname kernel: Modules linked in: cmac arc4 md4 nls_utf8 nft_meta nft_compat nft_chain_nat_ipv6 nf_tables_ipv6 nft_chain_nat_ipv4 nft_counter nf_tables_ipv4 nf_tables binfmt_misc veth ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 xt_comment nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype br_netfilter xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter overlay joydev snd_usb_audio snd_usbmidi_lib coretemp ghash_clmulni_intel aesni_intel snd_hda_codec_hdmi aes_x86_64 lrw gf128mul glue_helper ablk_helper snd_hda_codec_realtek cryptd snd_hda_codec_generic snd_hda_intel Jun 09 17:23:28 hostname kernel: snd_hda_codec snd_hda_core snd_hwdep snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi i915 snd_seq snd_seq_device drm_kms_helper snd_timer drm fb_sys_fops snd syscopyarea sysfillrect soundcore sysimgblt shpchp video mac_hid acpi_pad tpm_tis tpm_tis_core kvm_intel kvm irqbypass squashfs sch_fq_codel cifs fscache parport_pc ppdev lp parport ip_tables x_tables autofs4 btrfs xor raid6_pq hid_generic hid_cherry usbhid hid igb e1000e i2c_algo_bit nvme dca nvme_core ptp pps_core Jun 09 17:23:28 hostname kernel: CPU: 5 PID: 55 Comm: rcuc/5 Tainted: G UD 4.9.271-realtime-1-prove-rt182 #1 Jun 09 17:23:28 hostname kernel: Hardware name: Komax AG, Dierikon Komax-PC/KMX-Q170-24V, BIOS D05K1-1L 03/19/2018 Jun 09 17:23:28 hostname kernel: task: ffff88086c3a2800 task.stack: ffffc900113c8000 Jun 09 17:23:28 hostname kernel: RIP: 0010:[<ffffffff810d53c8>] [<ffffffff810d53c8>] rcu_cpu_kthread+0x2e8/0x690 Jun 09 17:23:28 hostname kernel: RSP: 0018:ffffc900113cbdb0 EFLAGS: 00010282 Jun 09 17:23:28 hostname kernel: RAX: ffff88086c3a2800 RBX: ffffffff812371a0 RCX: 0000000000000000 Jun 09 17:23:28 hostname kernel: RDX: ffffffff810d536e RSI: 0000000000000001 RDI: ffffffff81e67360 Jun 09 17:23:28 hostname kernel: RBP: ffffc900113cbe30 R08: 0000000000000000 R09: 0000000000000000 Jun 09 17:23:28 hostname kernel: R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000005 Jun 09 17:23:28 hostname kernel: R13: ffff88086c3a2800 R14: ffff87faa787cafd R15: ffff87faa787cafd Jun 09 17:23:28 hostname kernel: FS: 0000000000000000(0000) GS:ffff88087e480000(0000) knlGS:0000000000000000 Jun 09 17:23:28 hostname kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Jun 09 17:23:28 hostname kernel: CR2: ffff87faa787cafd CR3: 0000000572896000 CR4: 0000000000362670 Jun 09 17:23:28 hostname kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Jun 09 17:23:28 hostname kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Jun 09 17:23:28 hostname kernel: Stack: Jun 09 17:23:28 hostname kernel: ffffffff810d53c5 ffff88086c3a2800 ffff8807deff38c0 0000000a00000000 Jun 09 17:23:28 hostname kernel: ffff88087e4920bc ffff88087e4e9480 ffffffff81e67500 ffff88087e4920b4 Jun 09 17:23:28 hostname kernel: 0000000000000002 ffff88087e4e94b8 000000000000000a ffff88086c3a2800 Jun 09 17:23:28 hostname kernel: Call Trace: Jun 09 17:23:28 hostname kernel: [<ffffffff810d53c5>] ? rcu_cpu_kthread+0x2e5/0x690 Jun 09 17:23:28 hostname kernel: [<ffffffff8108ccf0>] ? smpboot_register_percpu_thread_cpumask+0xf0/0xf0 Jun 09 17:23:28 hostname kernel: [<ffffffff8108ce10>] smpboot_thread_fn+0x120/0x250 Jun 09 17:23:28 hostname kernel: [<ffffffff810884e0>] kthread+0xe0/0x100 Jun 09 17:23:28 hostname kernel: [<ffffffff81088400>] ? kthread_create_on_node+0x40/0x40 Jun 09 17:23:28 hostname kernel: [<ffffffff81831af9>] ret_from_fork+0x59/0x70 Jun 09 17:23:28 hostname kernel: Code: 8b 55 00 83 e2 08 0f 85 87 00 00 00 49 8b 55 00 f7 c2 00 00 04 00 75 7b 41 8b 85 a8 04 00 00 85 c0 75 70 4d 85 f6 74 6b 4d 89 f7 <4d> 8b 36 45 31 c9 45 31 c0 49 8b 5f 08 31 d2 31 f6 b9 02 00 00 Jun 09 17:23:28 hostname kernel: RIP [<ffffffff810d53c8>] rcu_cpu_kthread+0x2e8/0x690 Jun 09 17:23:28 hostname kernel: RSP <ffffc900113cbdb0> Jun 09 17:23:28 hostname kernel: CR2: ffff87faa787cafd Jun 09 17:23:28 hostname kernel: ---[ end trace 0000000000000003 ]--- Jun 09 17:23:28 hostname kernel: BUG: unable to handle kernel paging request at ffffffff81443890 Jun 09 17:23:28 hostname kernel: IP: [<ffffffff810b99d9>] queued_spin_lock_slowpath+0x149/0x190 Jun 09 17:23:28 hostname kernel: PGD 1e15067 Jun 09 17:23:28 hostname kernel: PUD 1e16063 Jun 09 17:23:28 hostname kernel: PMD 14000e1 Jun 09 17:23:28 hostname kernel: Jun 09 17:23:28 hostname kernel: Oops: 0003 [#3] PREEMPT SMP Jun 09 17:23:28 hostname kernel: Modules linked in: cmac arc4 md4 nls_utf8 nft_meta nft_compat nft_chain_nat_ipv6 nf_tables_ipv6 nft_chain_nat_ipv4 nft_counter nf_tables_ipv4 nf_tables binfmt_misc veth ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 xt_comment nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype br_netfilter xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter overlay joydev snd_usb_audio snd_usbmidi_lib coretemp ghash_clmulni_intel aesni_intel snd_hda_codec_hdmi aes_x86_64 lrw gf128mul glue_helper ablk_helper snd_hda_codec_realtek cryptd snd_hda_codec_generic snd_hda_intel Jun 09 17:23:28 hostname kernel: snd_hda_codec snd_hda_core snd_hwdep snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi i915 snd_seq snd_seq_device drm_kms_helper snd_timer drm fb_sys_fops snd syscopyarea sysfillrect soundcore sysimgblt shpchp video mac_hid acpi_pad tpm_tis tpm_tis_core kvm_intel kvm irqbypass squashfs sch_fq_codel cifs fscache parport_pc ppdev lp parport ip_tables x_tables autofs4 btrfs xor raid6_pq hid_generic hid_cherry usbhid hid igb e1000e i2c_algo_bit nvme dca nvme_core ptp pps_core Jun 09 17:23:28 hostname kernel: CPU: 5 PID: 55 Comm: rcuc/5 Tainted: G UD 4.9.271-realtime-1-prove-rt182 #1 Jun 09 17:23:28 hostname kernel: Hardware name: Komax AG, Dierikon Komax-PC/KMX-Q170-24V, BIOS D05K1-1L 03/19/2018 Jun 09 17:23:28 hostname kernel: task: ffff88086c3a2800 task.stack: ffffc900113c8000 Jun 09 17:23:28 hostname kernel: RIP: 0010:[<ffffffff810b99d9>] [<ffffffff810b99d9>] queued_spin_lock_slowpath+0x149/0x190 Jun 09 17:23:28 hostname kernel: RSP: 0018:ffffc900113cbe28 EFLAGS: 00010086 Jun 09 17:23:28 hostname kernel: RAX: ffffffff81443890 RBX: ffffc900113cbee0 RCX: ffff88087e4e9440 Jun 09 17:23:28 hostname kernel: RDX: 0000000000002040 RSI: 0000000000180000 RDI: ffffc900113cbee0 Jun 09 17:23:28 hostname kernel: RBP: ffffc900113cbe28 R08: 0000000000000000 R09: 0000000000000001 Jun 09 17:23:28 hostname kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffffc900113cbee0 Jun 09 17:23:28 hostname kernel: R13: 0000000000000286 R14: 0000000000000001 R15: 0000000000000001 Jun 09 17:23:28 hostname kernel: FS: 0000000000000000(0000) GS:ffff88087e480000(0000) knlGS:0000000000000000 Jun 09 17:23:28 hostname kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Jun 09 17:23:28 hostname kernel: CR2: ffffffff81443890 CR3: 00000005a6d9a000 CR4: 0000000000362670 Jun 09 17:23:28 hostname kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Jun 09 17:23:28 hostname kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Jun 09 17:23:28 hostname kernel: Stack: Jun 09 17:23:28 hostname kernel: ffffc900113cbe40 ffffffff810bb72d ffffc900113cbed8 ffffc900113cbe68 Jun 09 17:23:28 hostname kernel: ffffffff81830b2d ffffffff810adc4d ffffc900113cbee0 ffff88086c3a2ff8 Jun 09 17:23:28 hostname kernel: ffffc900113cbe90 ffffffff810adc4d ffff88086c3a2800 ffff88086c3a2800 Jun 09 17:23:28 hostname kernel: Call Trace: Jun 09 17:23:28 hostname kernel: [<ffffffff810bb72d>] do_raw_spin_lock+0x9d/0xa0 Jun 09 17:23:28 hostname kernel: [<ffffffff81830b2d>] _raw_spin_lock_irqsave+0x4d/0x60 Jun 09 17:23:28 hostname kernel: [<ffffffff810adc4d>] ? complete+0x1d/0x40 Jun 09 17:23:28 hostname kernel: [<ffffffff810adc4d>] complete+0x1d/0x40 Jun 09 17:23:28 hostname kernel: [<ffffffff8105cfd4>] mm_release+0x84/0xe0 Jun 09 17:23:28 hostname kernel: [<ffffffff8105dc13>] exit_mm_release+0x23/0x30 Jun 09 17:23:28 hostname kernel: [<ffffffff81832ea7>] ? rewind_stack_do_exit+0x17/0x20 Jun 09 17:23:28 hostname kernel: Code: 01 00 00 74 ef 40 30 f6 e9 ed fe ff ff c1 ea 12 83 e0 03 83 ea 01 48 c1 e0 04 48 63 d2 48 05 40 94 06 00 48 03 04 d5 20 c4 cd 81 <48> 89 08 8b 41 08 85 c0 75 09 f3 90 8b 41 08 85 c0 74 f7 48 8b Jun 09 17:23:28 hostname kernel: RIP [<ffffffff810b99d9>] queued_spin_lock_slowpath+0x149/0x190 Jun 09 17:23:28 hostname kernel: RSP <ffffc900113cbe28> Jun 09 17:23:28 hostname kernel: CR2: ffffffff81443890 Jun 09 17:23:28 hostname kernel: ---[ end trace 0000000000000004 ]--- Jun 09 17:23:28 hostname kernel: note: rcuc/5[55] exited with preempt_count 1 Jun 09 17:23:28 hostname kernel: Fixing recursive fault but reboot is needed! Jun 09 17:23:28 hostname kernel: ------------[ cut here ]------------ Jun 09 17:23:28 hostname kernel: kernel BUG at kernel/locking/rtmutex.c:1070! Jun 09 17:23:28 hostname kernel: invalid opcode: 0000 [#4] PREEMPT SMP Jun 09 17:23:28 hostname kernel: Modules linked in: cmac arc4 md4 nls_utf8 nft_meta nft_compat nft_chain_nat_ipv6 nf_tables_ipv6 nft_chain_nat_ipv4 nft_counter nf_tables_ipv4 nf_tables binfmt_misc veth ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 xt_comment nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype br_netfilter xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT nf_reject_ipv4 xt_tcpudp bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter overlay joydev snd_usb_audio snd_usbmidi_lib coretemp ghash_clmulni_intel aesni_intel snd_hda_codec_hdmi aes_x86_64 lrw gf128mul glue_helper ablk_helper snd_hda_codec_realtek cryptd snd_hda_codec_generic snd_hda_intel Jun 09 17:23:28 hostname kernel: snd_hda_codec snd_hda_core snd_hwdep snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi i915 snd_seq snd_seq_device drm_kms_helper snd_timer drm fb_sys_fops snd syscopyarea sysfillrect soundcore sysimgblt shpchp video mac_hid acpi_pad tpm_tis tpm_tis_core kvm_intel kvm irqbypass squashfs sch_fq_codel cifs fscache parport_pc ppdev lp parport ip_tables x_tables autofs4 btrfs xor raid6_pq hid_generic hid_cherry usbhid hid igb e1000e i2c_algo_bit nvme dca nvme_core ptp pps_core Jun 09 17:23:28 hostname kernel: CPU: 5 PID: 55 Comm: rcuc/5 Tainted: G UD 4.9.271-realtime-1-prove-rt182 #1 Jun 09 17:23:28 hostname kernel: Hardware name: Komax AG, Dierikon Komax-PC/KMX-Q170-24V, BIOS D05K1-1L 03/19/2018 Jun 09 17:23:28 hostname kernel: task: ffff88086c3a2800 task.stack: ffffc900113c8000 Jun 09 17:23:28 hostname kernel: RIP: 0010:[<ffffffff8182e775>] [<ffffffff8182e775>] rt_spin_lock_slowlock+0x325/0x350 Jun 09 17:23:28 hostname kernel: RSP: 0018:ffffc900113cbdd8 EFLAGS: 00010046 Jun 09 17:23:28 hostname kernel: RAX: ffff88086c3a2800 RBX: ffff88086c3a2ff8 RCX: 0000000000000001 Jun 09 17:23:28 hostname kernel: RDX: 0000000000000000 RSI: ffff88086c3a2800 RDI: ffff88086c3a2ff8 Jun 09 17:23:28 hostname kernel: RBP: ffffc900113cbe90 R08: 0000000000000000 R09: 0000000000000001 Jun 09 17:23:28 hostname kernel: R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000282 Jun 09 17:23:28 hostname kernel: R13: ffffc900113cbdf8 R14: ffff88086c3a2800 R15: 0000000000000000 Jun 09 17:23:28 hostname kernel: FS: 0000000000000000(0000) GS:ffff88087e480000(0000) knlGS:0000000000000000 Jun 09 17:23:28 hostname kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Jun 09 17:23:28 hostname kernel: CR2: ffffffff81443890 CR3: 00000004e72d0000 CR4: 0000000000362670 Jun 09 17:23:28 hostname kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Jun 09 17:23:28 hostname kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Jun 09 17:23:28 hostname kernel: Stack: Jun 09 17:23:28 hostname kernel: ffff88086c3a2800 0000000000000282 ffff8808013a39f0 0000000000000282 Jun 09 17:23:28 hostname kernel: ffffc900113cbdf8 1111111111111111 1111111111111111 ffffc900113cbe10 Jun 09 17:23:28 hostname kernel: 1111111111111111 1111111111111111 0000000000000000 1111111111111111 Jun 09 17:23:28 hostname kernel: Call Trace: Jun 09 17:23:28 hostname kernel: [<ffffffff81831043>] rt_spin_lock+0x23/0x50 Jun 09 17:23:28 hostname kernel: [<ffffffff8120b35c>] exit_files+0x2c/0x50 Jun 09 17:23:28 hostname kernel: [<ffffffff81065034>] do_exit+0x2d4/0xb10 Jun 09 17:23:28 hostname kernel: [<ffffffff81832ea7>] rewind_stack_do_exit+0x17/0x20 Jun 09 17:23:28 hostname kernel: Code: c0 0f 85 f9 fe ff ff 48 c7 c2 68 1c c2 81 be 80 03 00 00 48 c7 c7 60 17 c2 81 c6 05 7e ab 71 00 01 e8 50 6c 88 ff e9 d5 fe ff ff <0f> 0b 0f 0b 48 8b 43 40 48 3b 58 38 0f 85 31 ff ff ff 4c 39 e8 Jun 09 17:23:28 hostname kernel: RIP [<ffffffff8182e775>] rt_spin_lock_slowlock+0x325/0x350 Jun 09 17:23:28 hostname kernel: RSP <ffffc900113cbdd8> Jun 09 17:23:29 hostname kernel: ---[ end trace 0000000000000005 ]--- Jun 09 17:23:29 hostname kernel: note: rcuc/5[55] exited with preempt_count 1 Jun 09 17:23:29 hostname kernel: Fixing recursive fault but reboot is needed! ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Hung task in 4.9 using kvm 5.2 2021-06-10 7:28 ` Christoph Mathys @ 2021-06-15 13:49 ` Christoph Mathys 0 siblings, 0 replies; 6+ messages in thread From: Christoph Mathys @ 2021-06-15 13:49 UTC (permalink / raw) To: Luis Goncalves, Ahmed S. Darwish; +Cc: Linux RT Users I'm unable to reproduce "BUG: unable to handle kernel paging request" when I use 4.9.178-rt131, so I'm inclined to think that it got introduced somewhere along the way to 4.9.271-rt182. The problem with "hung task" is also gone when I don't force qemu 5.2 to use cache.direct=true and aio=native. Qemu 2.1 from Debian Jessie does not trigger this problem on the same system. Christoph ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2021-06-15 13:49 UTC | newest] Thread overview: 6+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2021-06-07 14:56 Hung task in 4.9 using kvm 5.2 Christoph Mathys 2021-06-08 9:31 ` Ahmed S. Darwish 2021-06-08 20:32 ` Luis Goncalves 2021-06-09 8:55 ` Christoph Mathys 2021-06-10 7:28 ` Christoph Mathys 2021-06-15 13:49 ` Christoph Mathys
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox