Subject: [lkp] [net] c4c75f963d: inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.

From: kernel test robot <[email-masked]>
Date: Thu, 1 Sep 2016 16:26:30 +0800

FYI, we noticed the following commit:

https://github.com/0day-ci/linux John-Fastabend/support-lockless-qdisc/20160824-044640
commit c4c75f963de7196385f3e3a80c03d89923b26ba7 ("net: sched: pfifo_fast use skb_array")

in testcase: boot

on test machine: qemu-system-i386 -enable-kvm -m 256M

caused below changes:

+--------------------------------------------------------------------------+------------+------------+
|                                                                          | d459d8932c | c4c75f963d |
+--------------------------------------------------------------------------+------------+------------+
| boot_successes                                                           | 6          | 3          |
| boot_failures                                                            | 4          | 7          |
| genirq:Flags_mismatch_irq##(serial)vs.#(goldfish_pdev_bus)               | 4          | 7          |
| message:genirq:Flags_mismatch_irq##(serial)vs.#(goldfish_pdev_bus)       | 0.0        | 0.0        |
| pattern:genirq:Flags_mismatch_irq##(serial)vs.#(goldfish_pdev_bus)       | 0          | 0          |
| invoked_oom-killer:gfp_mask=0x                                           | 3          | 3          |
| message:invoked_oom-killer:gfp_mask=0x                                   | 0.0        | 0.0        |
| pattern:invoked_oom-killer:gfp_mask=0x                                   | 0          | 0          |
| Mem-Info                                                                 | 3          | 3          |
| message:Mem-Info                                                         | 0.0        | 0.0        |
| pattern:Mem-Info                                                         | 0          | 0          |
| page_allocation_failure:order:#,mode:#(GFP_KERNEL|__GFP_NORETRY)         | 1          | 2          |
| message:page_allocation_failure:order:#,mode:#(GFP_KERNEL|__GFP_NORETRY) | 0.0        | 0.0        |
| pattern:page_allocation_failure:order:#,mode:#(GFP_KERNEL|__GFP_NORETRY) | 0          | 0          |
| warn_alloc_failed+0x                                                     | 1          | 2          |
| message:warn_alloc_failed+0x                                             | 0.0        | 0.0        |
| pattern:warn_alloc_failed+0x                                             | 0          | 0          |
| BUG:kernel_reboot-without-warning_in_test_stage                          | 1          | 1          |
| message:BUG:kernel_reboot-without-warning_in_test_stage                  | 0          | 0          |
| pattern:BUG:kernel_reboot-without-warning_in_test_stage                  | 0          | 0          |
| inconsistent{SOFTIRQ-ON-W}->{IN-SOFTIRQ-W}usage                          | 0          | 6          |
| message:inconsistent{SOFTIRQ-ON-W}->{IN-SOFTIRQ-W}usage                  | 0          | 0.0        |
| pattern:inconsistent{SOFTIRQ-ON-W}->{IN-SOFTIRQ-W}usage                  | 0          | 0.0        |
| calltrace:SyS_ioctl                                                      | 0          | 6          |
| message:calltrace:SyS_ioctl                                              | 0          | 0.0        |
| pattern:calltrace:SyS_ioctl                                              | 0          | 0          |
| calltrace:schedule_timeout                                               | 0          | 1          |
| message:calltrace:schedule_timeout                                       | 0          | 0.0        |
| pattern:calltrace:schedule_timeout                                       | 0          | 0          |
| calltrace:SyS_execve                                                     | 0          | 1          |
| message:calltrace:SyS_execve                                             | 0          | 0.0        |
| pattern:calltrace:SyS_execve                                             | 0          | 0          |
+--------------------------------------------------------------------------+------------+------------+

[   38.736548] =================================
[   38.738214] [ INFO: inconsistent lock state ]
[   38.739821] 4.8.0-rc2-00595-gc4c75f9 #1 Tainted: G S             
[   38.741866] ---------------------------------
[   38.743472] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
[   38.745526] seq/980 [HC0[0]:SC1[3]:HE1:SE0] takes:
[   38.747262]  (&(&r->consumer_lock)->rlock){+.?...}, at: [<c1f97d4f>] pfifo_fast_dequeue+0x42/0x10a
[   38.751394] {SOFTIRQ-ON-W} state was registered at:
[   38.753420]   [<c108e5bc>] __lock_acquire+0x34e/0x1568
[   38.755723]   [<c1090460>] lock_acquire+0x119/0x19e
[   38.757963]   [<c213bc25>] _raw_spin_lock+0x2d/0x5d
[   38.760217]   [<c1f97bd5>] pfifo_fast_reset+0x26/0xaf
[   38.762489]   [<c1f987a9>] qdisc_reset+0x1b/0xd3
[   38.764644]   [<c1f98f07>] dev_deactivate_many+0x265/0x30c
[   38.767059]   [<c1f71f84>] __dev_close_many+0x6e/0xa3
[   38.769319]   [<c1f71fe2>] __dev_close+0x29/0x3a
[   38.771465]   [<c1f76f97>] __dev_change_flags+0x98/0x125
[   38.773810]   [<c1f77046>] dev_change_flags+0x22/0x4f
[   38.776040]   [<c1f8c15f>] dev_ifsioc+0xdc/0x2ce
[   38.778184]   [<c1f8ca15>] dev_ioctl+0x5c7/0x63b
[   38.780310]   [<c1f5da99>] sock_ioctl+0x19e/0x1a8
[   38.783151]   [<c1163c64>] vfs_ioctl+0x1c/0x26
[   38.785214]   [<c11648d6>] do_vfs_ioctl+0x65d/0x6cf
[   38.787411]   [<c1164979>] SyS_ioctl+0x31/0x4a
[   38.789485]   [<c1001441>] do_int80_syscall_32+0x53/0xee
[   38.791812]   [<c213c8cf>] restore_all+0x0/0xf
[   38.793904] irq event stamp: 2076
[   38.795470] hardirqs last  enabled at (2076): [<c1053e19>] __local_bh_enable_ip+0x9f/0xb8
[   38.799794] hardirqs last disabled at (2075): [<c1053dcd>] __local_bh_enable_ip+0x53/0xb8
[   38.803442] softirqs last  enabled at (0): [<c104cd30>] copy_process+0x2af/0x14a9
[   38.807020] softirqs last disabled at (2067): [<c10164b0>] do_softirq_own_stack+0x28/0x2e
[   38.810579] 
[   38.810579] other info that might help us debug this:
[   38.813514]  Possible unsafe locking scenario:
[   38.813514] 
[   38.816283]        CPU0
[   38.817553]        ----
[   38.818870]   lock(&(&r->consumer_lock)->rlock);
[   38.821150]   <Interrupt>
[   38.822490]     lock(&(&r->consumer_lock)->rlock);
[   38.824842] 
[   38.824842]  *** DEADLOCK ***
[   38.824842] 
[   38.827961] 3 locks held by seq/980:
[   38.829604]  #0:  (((&port->ip4_own_query.timer))){+.-...}, at: [<c10afd01>] call_timer_fn+0x0/0x2b7
[   38.834182]  #1:  (&(&br->multicast_lock)->rlock){+.-...}, at: [<c205b3f9>] br_ip4_multicast_port_query_expired+0x1c/0x52
[   38.840020]  #2:  (rcu_read_lock_bh){......}, at: [<c1f7441c>] __dev_queue_xmit+0x4e/0x746
[   38.844392] 
[   38.844392] stack backtrace:
[   38.846691] CPU: 0 PID: 980 Comm: seq Tainted: G S              4.8.0-rc2-00595-gc4c75f9 #1
[   38.850180] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Debian-1.8.2-1 04/01/2014
[   38.853855]  00000000 00000002 cf5dfd28 c1450dcd c3189840 ca183280 cf5dfd48 c108c978
[   38.858487]  c2665225 c2665118 c26661d5 ca183868 00000004 00000006 cf5dfd70 c108cc4a
[   38.863137]  00000004 ca17dea4 c108c02c 00000006 ca183280 ca7a6a34 00000001 ca183868
[   38.868506] Call Trace:
[   38.869808]  [<c1450dcd>] dump_stack+0x75/0xa9
[   38.871679]  [<c108c978>] print_usage_bug+0x223/0x22f
[   38.873744]  [<c108cc4a>] mark_lock+0x2c6/0x4f9
[   38.875691]  [<c108c02c>] ? print_irq_inversion_bug+0x196/0x196
[   38.878055]  [<c108e549>] __lock_acquire+0x2db/0x1568
[   38.880145]  [<c1036d5d>] ? kvm_clock_read+0x1f/0x30
[   38.882209]  [<c1036d83>] ? kvm_sched_clock_read+0x9/0x18
[   38.884403]  [<c1090460>] lock_acquire+0x119/0x19e
[   38.886426]  [<c1f97d4f>] ? pfifo_fast_dequeue+0x42/0x10a
[   38.888629]  [<c213bc25>] _raw_spin_lock+0x2d/0x5d
[   38.890638]  [<c1f97d4f>] ? pfifo_fast_dequeue+0x42/0x10a
[   38.893545]  [<c1f97d4f>] pfifo_fast_dequeue+0x42/0x10a
[   38.895645]  [<c1f98400>] __qdisc_run+0x14b/0x29a
[   38.897618]  [<c1f74717>] __dev_queue_xmit+0x349/0x746
[   38.899749]  [<c1f74b23>] dev_queue_xmit+0xf/0x11
[   38.901752]  [<c20524af>] br_dev_queue_push_xmit+0x115/0x125
[   38.904028]  [<c205b2b8>] __br_multicast_send_query+0x1fc/0x28c
[   38.906418]  [<c108b207>] ? save_trace+0x39/0x8e
[   38.908400]  [<c205239a>] ? br_fdb_external_learn_del+0xd4/0xd4
[   38.910738]  [<c205b3b0>] br_multicast_send_query+0x68/0x95
[   38.912984]  [<c2130008>] ? switchdev_port_obj_add_now+0x16/0xac
[   38.915345]  [<c205b423>] br_ip4_multicast_port_query_expired+0x46/0x52
[   38.917878]  [<c205b3dd>] ? br_multicast_send_query+0x95/0x95
[   38.920174]  [<c10afe0b>] call_timer_fn+0x10a/0x2b7
[   38.922204]  [<c205b3dd>] ? br_multicast_send_query+0x95/0x95
[   38.924497]  [<c10b010f>] expire_timers+0x157/0x1b7
[   38.926510]  [<c10b0239>] run_timer_softirq+0x5a/0xd6
[   38.928565]  [<c10538f8>] ? _local_bh_enable+0x40/0x40
[   38.930688]  [<c1053a71>] __do_softirq+0x179/0x3b3
[   38.932725]  [<c10538f8>] ? _local_bh_enable+0x40/0x40
[   38.935557]  [<c10164b0>] do_softirq_own_stack+0x28/0x2e
[   38.937691]  <IRQ>  [<c1053ece>] irq_exit+0x42/0x8f
[   38.939887]  [<c1030a5b>] smp_apic_timer_interrupt+0x38/0x42
[   38.942157]  [<c213d332>] apic_timer_interrupt+0x32/0x40
[   38.944340]  [<c10906a3>] ? lock_release+0x1be/0x4cd
[   38.947117]  [<c1089866>] up_read+0x1b/0x2e
[   38.948899]  [<c1039720>] __do_page_fault+0x325/0x3d1
[   38.950994]  [<c1039ade>] trace_do_page_fault+0x182/0x22c
[   38.953173]  [<c1036ae9>] ? kvm_read_and_reset_pf_reason+0x28/0x28
[   38.955607]  [<c1036b11>] do_async_page_fault+0x28/0x50
[   38.957777]  [<c213d79f>] error_code+0x5f/0x70
[   38.959670]  [<c1036ae9>] ? kvm_read_and_reset_pf_reason+0x28/0x28

Thanks,
Xiaolong