* 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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.