Fixed
Created: Nov 21, 2016
Updated: Dec 9, 2019
Resolved Date: Dec 5, 2016
Found In Version: 6.0.0.31
Fix Version: 6.0.0.32
Severity: Severe
Applicable for: Wind River Linux 6
Component/s: Kernel
This issue is separated from OVP6-47. Focus on below warning message:
Disabling IRQ #16
BUG: sleeping function called from invalid context at /b/rbu-builder/daily/vmhost/19/build-project/bitbake_build/tmp/work/intel_x86_64-wrs-linux/linux-windriver/3.10-r0/linux/kernel/rtmutex.c:796
in_atomic(): 1, irqs_disabled(): 1, pid: 3, name: ksoftirqd/0
Preemption disabled at:[<ffffffff8196bbae>] do_IRQ+0x2e/0xc0
============================
below is the description of OVP6-47:
...
Customer use OVP6 RCPL20. They found an issue when passthrough USB host controller to the VM, the OVP6 host kernel will reported the following error.
If they don't passthrough the USB host controller to VM, this issue don't
happen.
Below is the log from customer:
----------------------------------------------------
Disabling IRQ #16
BUG: sleeping function called from invalid context at /b/rbu-builder/daily/vmhost/19/build-project/bitbake_build/tmp/work/intel_x86_64-wrs-linux/linux-windriver/3.10-r0/linux/kernel/rtmutex.c:796
in_atomic(): 1, irqs_disabled(): 1, pid: 3, name: ksoftirqd/0
Preemption disabled at:[<ffffffff8196bbae>] do_IRQ+0x2e/0xc0
Crash details:
------------[ cut here ]------------
kernel BUG at /b/rbu-builder/daily/vmhost/19/build-project/bitbake_build/tmp/work/intel_x86_64-wrs-linux/linux-windriver/3.10-r0/linux/kernel/rtmutex.c:875!
invalid opcode: 0000 [#1] PREEMPT SMP
Modules linked in: vhost_net macvtap kvm_intel kvm uio_fpga(O) uio pci_stub iptable_mangle ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT xt_tcpudp bridge stp llc ebtable_filter ebtables iptable_filter ip_tables x_tables nfsd aufs iTCO_wdt iTCO_vendor_support gpio_ich coretemp crct10dif_pclmul crct10dif_common aesni_intel aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd i2c_i801 lpc_ich e1000e acpi_cpufreq mperf processor i40e(O) [last unloaded: kvm]
CPU: 0 PID: 3 Comm: ksoftirqd/0 Tainted: G O 3.10.79-ovp-rt74-WR6.0.0.20_preempt-rt #1
task: ffff880ff5733000 ti: ffff880ff5744000 task.ti: ffff880ff5744000
RIP: 0010:[<ffffffff81968475>] [<ffffffff81968475>] rt_spin_lock_slowlock+0x7c/0x277
RSP: 0018:ffff88107fc03d40 EFLAGS: 00010046
RAX: ffff880ff5733000 RBX: ffffffff8208b300 RCX: 0000000000000001
RDX: 0000000000000000 RSI: ffff880ff5733000 RDI: ffffffff8208b300
RBP: ffff88107fc03de8 R08: ffff880ff5733001 R09: ffffffff8208b318
R10: ffff880ff5733001 R11: 0000000000000000 R12: ffffffff8208b300
R13: ffffffff81e530d8 R14: ffff88107fc03e48 R15: ffff880ff5745da0
FS: 0000000000000000(0000) GS:ffff88107fc00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ffe340a9f68 CR3: 0000000fe0fbb000 CR4: 00000000001427f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Stack:
ffffffff81cd2efb 000000000000000c ffff880ff5733000 ffffffff810052de
ffff88107fbfffc0 ffff88107fc03fc0 ffff88107fc03e18 ffff88107fc03db8
0000000000000000 ffffffff8208b300 ffffffff81e530d8 ffff88107fc03e48
Call Trace:
<IRQ>
[<ffffffff810052de>] ? show_stack_log_lvl+0xce/0x1c0
[<ffffffff81006725>] ? show_stack+0x25/0x50
[<ffffffff81968ec1>] rt_spin_lock+0x41/0x50
[<ffffffff81051727>] lock_timer_base.isra.37+0x37/0x60
[<ffffffff81051bd5>] mod_timer+0x75/0x290
[<ffffffff810d912b>] note_interrupt+0x20b/0x290
[<ffffffff810d66c6>] handle_irq_event_percpu+0x126/0x290
[<ffffffff810515a6>] ? run_timer_softirq+0x1b6/0x300
[<ffffffff810d6898>] handle_irq_event+0x68/0x90
[<ffffffff810d9d89>] handle_fasteoi_irq+0xc9/0x140
[<ffffffff81004efe>] handle_irq+0x1e/0x30
[<ffffffff8196bbcd>] do_IRQ+0x4d/0xc0
[<ffffffff8184db80>] ? tcp_write_timer_handler+0x1d0/0x1d0
[<ffffffff8196972a>] common_interrupt+0x6a/0x6a
<EOI>
[<ffffffff810515a6>] ? run_timer_softirq+0x1b6/0x300
[<ffffffff810515f5>] ? run_timer_softirq+0x205/0x300
[<ffffffff810495a2>] do_current_softirqs+0x182/0x340
[<ffffffff8104999a>] run_ksoftirqd+0x2a/0x40
[<ffffffff8106f4cc>] smpboot_thread_fn+0x1ec/0x360
[<ffffffff81967630>] ? schedule+0x30/0x90
[<ffffffff8106f2e0>] ? lg_local_unlock+0x30/0x30
[<ffffffff81067442>] kthread+0xb2/0xc0
[<ffffffff81067390>] ? kthread_worker_fn+0x1b0/0x1b0
[<ffffffff8196a138>] ret_from_fork+0x58/0x90
[<ffffffff81067390>] ? kthread_worker_fn+0x1b0/0x1b0
Code: ff ff ff 31 d2 b9 01 00 00 00 48 89 df e8 24 df 73 ff 85 c0 0f 85 b4 01 00 00 48 8b 43 18 48 83 e0 fe 48 39 85 68 ff ff ff 75 02 <0f> 0b 4c 8b b5 68 ff ff ff 4c 8d ad 70 ff ff ff 4d 8d a6 f8 06
RIP [<ffffffff81968475>] rt_spin_lock_slowlock+0x7c/0x277
RSP <ffff88107fc03d40>
Logs before the above crash:
irq 16: nobody cared (try booting with the "irqpoll" option)
CPU: 0 PID: 3 Comm: ksoftirqd/0 Tainted: G O 3.10.79-ovp-rt74-WR6.0.0.20_preempt-rt #1
0000000000000010 ffff88107fc03e50 ffffffff81962b69 ffff88107fc03e78
ffffffff810d8bdb ffff880ff4976c00 0000000000000010 0000000000000000
ffff88107fc03eb8 ffffffff810d90f0 ffff88107fc03e98 0000000000000000
Call Trace:
<IRQ> [<ffffffff81962b69>] dump_stack+0x19/0x1b
[<ffffffff810d8bdb>] __report_bad_irq+0x2b/0xd0
[<ffffffff810d90f0>] note_interrupt+0x1d0/0x290
[<ffffffff810d66c6>] handle_irq_event_percpu+0x126/0x290
[<ffffffff810515a6>] ? run_timer_softirq+0x1b6/0x300
[<ffffffff810d6898>] handle_irq_event+0x68/0x90
[<ffffffff810d9d89>] handle_fasteoi_irq+0xc9/0x140
[<ffffffff81004efe>] handle_irq+0x1e/0x30
[<ffffffff8196bbcd>] do_IRQ+0x4d/0xc0
[<ffffffff8184db80>] ? tcp_write_timer_handler+0x1d0/0x1d0
[<ffffffff8196972a>] common_interrupt+0x6a/0x6a
<EOI> [<ffffffff810515a6>] ? run_timer_softirq+0x1b6/0x300
[<ffffffff810515f5>] ? run_timer_softirq+0x205/0x300
[<ffffffff810495a2>] do_current_softirqs+0x182/0x340
[<ffffffff8104999a>] run_ksoftirqd+0x2a/0x40
[<ffffffff8106f4cc>] smpboot_thread_fn+0x1ec/0x360
[<ffffffff81967630>] ? schedule+0x30/0x90
[<ffffffff8106f2e0>] ? lg_local_unlock+0x30/0x30
[<ffffffff81067442>] kthread+0xb2/0xc0
[<ffffffff81067390>] ? kthread_worker_fn+0x1b0/0x1b0
[<ffffffff8196a138>] ret_from_fork+0x58/0x90
[<ffffffff81067390>] ? kthread_worker_fn+0x1b0/0x1b0
handlers:
[<ffffffff810d68c0>] irq_default_primary_handler threaded [<ffffffff81677710>] usb_hcd_irq
[<ffffffffa07c5e80>] kvm_assigned_dev_intx [kvm] threaded [<ffffffffa07c6340>] kvm_assigned_dev_thread_intx [kvm]
Disabling IRQ #16
BUG: sleeping function called from invalid context at /b/rbu-builder/daily/vmhost/19/build-project/bitbake_build/tmp/work/intel_x86_64-wrs-linux/linux-windriver/3.10-r0/linux/kernel/rtmutex.c:796
in_atomic(): 1, irqs_disabled(): 1, pid: 3, name: ksoftirqd/0
Preemption disabled at:[<ffffffff8196bbae>] do_IRQ+0x2e/0xc0
CPU: 0 PID: 3 Comm: ksoftirqd/0 Tainted: G O 3.10.79-ovp-rt74-WR6.0.0.20_preempt-rt #1
ffffffff8208b300 ffff88107fc03dd0 ffffffff81962b69 ffff88107fc03de8
ffffffff8107314f ffffffff8208b300 ffff88107fc03e00 ffffffff81968ea0
ffffffff8208b300 ffff88107fc03e30 ffffffff81051727 ffffffff81e530c0
Call Trace:
<IRQ> [<ffffffff81962b69>] dump_stack+0x19/0x1b
[<ffffffff8107314f>] __might_sleep+0xef/0x160
[<ffffffff81968ea0>] rt_spin_lock+0x20/0x50
[<ffffffff81051727>] lock_timer_base.isra.37+0x37/0x60
[<ffffffff81051bd5>] mod_timer+0x75/0x290
[<ffffffff810d912b>] note_interrupt+0x20b/0x290
[<ffffffff810d66c6>] handle_irq_event_percpu+0x126/0x290
[<ffffffff810515a6>] ? run_timer_softirq+0x1b6/0x300
[<ffffffff810d6898>] handle_irq_event+0x68/0x90
[<ffffffff810d9d89>] handle_fasteoi_irq+0xc9/0x140
[<ffffffff81004efe>] handle_irq+0x1e/0x30
[<ffffffff8196bbcd>] do_IRQ+0x4d/0xc0
[<ffffffff8184db80>] ? tcp_write_timer_handler+0x1d0/0x1d0
[<ffffffff8196972a>] common_interrupt+0x6a/0x6a
<EOI> [<ffffffff810515a6>] ? run_timer_softirq+0x1b6/0x300
[<ffffffff810515f5>] ? run_timer_softirq+0x205/0x300
[<ffffffff810495a2>] do_current_softirqs+0x182/0x340
[<ffffffff8104999a>] run_ksoftirqd+0x2a/0x40
[<ffffffff8106f4cc>] smpboot_thread_fn+0x1ec/0x360
[<ffffffff81967630>] ? schedule+0x30/0x90
[<ffffffff8106f2e0>] ? lg_local_unlock+0x30/0x30
[<ffffffff81067442>] kthread+0xb2/0xc0
[<ffffffff81067390>] ? kthread_worker_fn+0x1b0/0x1b0
[<ffffffff8196a138>] ret_from_fork+0x58/0x90
[<ffffffff81067390>] ? kthread_worker_fn+0x1b0/0x1b0
----------------------------------------------------
No.
In Preempt-RT kernel, add a little trick to make a fake "nobody cared irq" to let kernel goes into "note_interrupt" and call "mod_timer" in it. This issue can easily be reproduced.
