workqueue: race in mod_delayed_work_on?

I've got plenty warnings, bugs and oops around trivial use of mod_delayed_work in drivers/infiniband/core/addr.c

For example:

WARN_ON_ONCE(timer_pending(timer)) in __queue_delayed_work and
BUG_ON(timer_pending(timer) || !timer->function) in add_timer_on

<4>[471106.614256] ------------[ cut here ]------------
<4>[471106.614271] WARNING: CPU: 2 PID: 0 at kernel/workqueue.c:1428 __queue_delayed_work+0xdd/0x160()
<4>[471106.614274] Modules linked in: tcp_diag inet_diag bridge cls_cgroup sch_htb netconsole configfs 8021q mrp garp stp llc

intel_powerclamp coretemp kvm_intel kvm crc32_pclmul aesni_intel
ablk_helper cryptd lrw mgag200 psmouse ttm gf128mul serio_raw glue_helper aes_x86_64 drm_kms_helper drm gpio_ich microcode sysimgblt sysfillrect syscopyarea lpc_ich i7core_edac ioatdma edac_c
ore mlx4_ib ib_sa ib_mad ib_core ib_addr mlx4_en mlx4_core vxlan udp_tunnel ip6_udp_tunnel tcp_htcp ahci igb libahci dca i2c_algo_bit i2c_core ptp pps_core raid10 raid456 async_pq async_xor x
or async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 multipath linear [last unloaded: ipmi_msghandler]

<4>[471106.614339] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 3.18.25-28 #1
<4>[471106.614344] Hardware name: Supermicro X8DTU/X8DTU, BIOS 2.1c       08/03/2012
<4>[471106.614346]  0000000000000594 ffff880627c43c88 ffffffff816d08e3 0000000000000007
<4>[471106.614348]  0000000000000000 ffff880627c43cc8 ffffffff8106bb2c ffff880627c43cd8
<4>[471106.614350]  0000000000000080 ffff88061b0b2a00 0000000000000080 ffff88061b0b2a00
<4>[471106.614353] Call Trace:
<4>[471106.614354]  <IRQ>  [<ffffffff816d08e3>] dump_stack+0x4e/0x68
<4>[471106.614362]  [<ffffffff8106bb2c>] warn_slowpath_common+0x8c/0xc0
<4>[471106.614364]  [<ffffffff8106bb7a>] warn_slowpath_null+0x1a/0x20
<4>[471106.614367]  [<ffffffff8108235d>] __queue_delayed_work+0xdd/0x160
<4>[471106.614371]  [<ffffffff810829da>] mod_delayed_work_on+0x5a/0x80
<4>[471106.614375]  [<ffffffffa014028a>] set_timeout+0x3a/0x40 [ib_addr]
<4>[471106.614378]  [<ffffffffa01407af>] netevent_callback+0x2f/0x40 [ib_addr]
<4>[471106.614382]  [<ffffffff8108af7d>] notifier_call_chain+0x4d/0x70
<4>[471106.614384]  [<ffffffff8108afba>] __atomic_notifier_call_chain+0x1a/0x30
<4>[471106.614387]  [<ffffffff8108afe6>] atomic_notifier_call_chain+0x16/0x20
<4>[471106.614390]  [<ffffffff815d75fb>] call_netevent_notifiers+0x1b/0x20
<4>[471106.614393]  [<ffffffff815d9a7e>] neigh_update_notify+0x1e/0x40
<4>[471106.614395]  [<ffffffff815daebf>] neigh_timer_handler+0xdf/0x2a0
<4>[471106.614397]  [<ffffffff815dade0>] ? neigh_periodic_work+0x220/0x220
<4>[471106.614401]  [<ffffffff810bf43a>] call_timer_fn+0x3a/0x170
<4>[471106.614403]  [<ffffffff810bf67c>] ? cascade+0x7c/0xa0
<4>[471106.614405]  [<ffffffff810c100f>] run_timer_softirq+0x2df/0x340
<4>[471106.614409]  [<ffffffff810ce944>] ? clockevents_program_event+0x74/0x100
<4>[471106.614411]  [<ffffffff815dade0>] ? neigh_periodic_work+0x220/0x220
<4>[471106.614414]  [<ffffffff8106f7df>] __do_softirq+0xdf/0x2f0
<4>[471106.614417]  [<ffffffff8106fc66>] irq_exit+0x86/0xb0
<4>[471106.614420]  [<ffffffff816db61a>] smp_apic_timer_interrupt+0x4a/0x60
<4>[471106.614423]  [<ffffffff816d96fd>] apic_timer_interrupt+0x6d/0x80
<4>[471106.614424]  <EOI>  [<ffffffff815796a1>] ? cpuidle_enter_state+0x71/0x1d0
<4>[471106.614430]  [<ffffffff8157968f>] ? cpuidle_enter_state+0x5f/0x1d0
<4>[471106.614433]  [<ffffffff815798c7>] cpuidle_enter+0x17/0x20
<4>[471106.614436]  [<ffffffff810a905f>] cpu_startup_entry+0x34f/0x3d0
<4>[471106.614438]  [<ffffffff810461fc>] start_secondary+0x14c/0x160
<4>[471106.614440] ---[ end trace 23e6f46f3ce04a60 ]---
<5>[471106.614443] ---[ now 2016-04-27 06:06:02+03 ]---
<4>[471106.617880] ------------[ cut here ]------------
<2>[471106.617905] kernel BUG at kernel/time/timer.c:963!
<4>[471106.617924] invalid opcode: 0000 [#1] SMP
<4>[471106.617942] Modules linked in: tcp_diag inet_diag bridge cls_cgroup sch_htb netconsole configfs 8021q mrp garp stp llc

intel_powerclamp coretemp kvm_intel kvm crc32_pclmul aesni_intel ablk_helper cryptd lrw mgag200 psmouse ttm gf128mul serio_raw glue_helper aes_x86_64 drm_kms_helper drm gpio_ich microcode sysimgblt sysfillrect syscopyarea lpc_ich i7core_edac ioatdma edac_core mlx4_ib ib_sa ib_mad ib_core ib_addr mlx4_en mlx4_core vxlan udp_tunnel ip6_udp_tunnel tcp_htcp ahci igb libahci dca i2c_algo_bit i2c_core ptp pps_core raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid1 raid0 multipath linear [last unloaded:
ipmi_msghandler]

<4>[471106.618265] CPU: 2 PID: 0 Comm: swapper/2 Tainted: G        W      3.18.25-28 #1
<4>[471106.618291] Hardware name: Supermicro X8DTU/X8DTU, BIOS 2.1c       08/03/2012
<4>[471106.618317] task: ffff88061e5a53c0 ti: ffff88061e5d0000 task.ti: ffff88061e5d0000
<4>[471106.618344] RIP: 0010:[<ffffffff810c09c9>]  [<ffffffff810c09c9>] add_timer_on+0xf9/0x100
<4>[471106.618377] RSP: 0018:ffff880627c43c98  EFLAGS: 00010086
<4>[471106.618398] RAX: 000000000000d480 RBX: ffffffffa0143060 RCX: 0000000107028001
<4>[471106.618423] RDX: ffff880627c40000 RSI: 0000000000000002 RDI: ffffffffa0143060
<4>[471106.618449] RBP: ffff880627c43cd8 R08: ffffffff81389c30 R09: ffff880115355600
<4>[471106.618474] R10: 0000000000000216 R11: 0000000000000003 R12: ffff88061e0d0000
<4>[471106.618500] R13: 0000000000000080 R14: ffff88061b0b2a00 R15: 0000000000000001
<4>[471106.618526] FS:  0000000000000000(0000) GS:ffff880627c40000(0000) knlGS:0000000000000000
<4>[471106.618555] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
<4>[471106.618576] CR2: 00007f418817a3d0 CR3: 0000000001c14000 CR4: 00000000000007e0
<4>[471106.618602] Stack:
<4>[471106.618611]  ffff880627c43cd8 0000000000000080 ffff88061b0b2a00 0000000000000002
<4>[471106.618643]  ffff88061b0b2a00 0000000000000080 ffff88061b0b2a00 0000000000000001
<4>[471106.618675]  ffff880627c43d08 ffffffff810822f6 0000000000000001 ffffffffa0143040
<4>[471106.618707] Call Trace:
<4>[471106.618718]  <IRQ>
<4>[471106.618727] <4>[471106.618736]  [<ffffffff810822f6>] __queue_delayed_work+0x76/0x160
<4>[471106.618758]  [<ffffffff810829da>] mod_delayed_work_on+0x5a/0x80
<4>[471106.618782]  [<ffffffffa014028a>] set_timeout+0x3a/0x40 [ib_addr]
<4>[471106.618807]  [<ffffffffa01407af>] netevent_callback+0x2f/0x40 [ib_addr]
<4>[471106.618832]  [<ffffffff8108af7d>] notifier_call_chain+0x4d/0x70
<4>[471106.618856]  [<ffffffff8108afba>] __atomic_notifier_call_chain+0x1a/0x30
<4>[471106.618881]  [<ffffffff8108afe6>] atomic_notifier_call_chain+0x16/0x20
<4>[471106.618906]  [<ffffffff815d75fb>] call_netevent_notifiers+0x1b/0x20
<4>[471106.618930]  [<ffffffff815d9a7e>] neigh_update_notify+0x1e/0x40
<4>[471106.618953]  [<ffffffff815daebf>] neigh_timer_handler+0xdf/0x2a0
<4>[471106.618976]  [<ffffffff815dade0>] ? neigh_periodic_work+0x220/0x220
<4>[471106.619000]  [<ffffffff810bf43a>] call_timer_fn+0x3a/0x170
<4>[471106.619021]  [<ffffffff810bf67c>] ? cascade+0x7c/0xa0
<4>[471106.619041]  [<ffffffff810c100f>] run_timer_softirq+0x2df/0x340
<4>[471106.619064]  [<ffffffff810ce944>] ? clockevents_program_event+0x74/0x100
<4>[471106.619090]  [<ffffffff815dade0>] ? neigh_periodic_work+0x220/0x220
<4>[471106.619115]  [<ffffffff8106f7df>] __do_softirq+0xdf/0x2f0
<4>[471106.619943]  [<ffffffff8106fc66>] irq_exit+0x86/0xb0
<4>[471106.620758]  [<ffffffff816db61a>] smp_apic_timer_interrupt+0x4a/0x60
<4>[471106.621578]  [<ffffffff816d96fd>] apic_timer_interrupt+0x6d/0x80
<4>[471106.622386]  <EOI>
<4>[471106.622396] <4>[471106.623190]  [<ffffffff815796a1>] ? cpuidle_enter_state+0x71/0x1d0
<4>[471106.623997]  [<ffffffff8157968f>] ? cpuidle_enter_state+0x5f/0x1d0
<4>[471106.624783]  [<ffffffff815798c7>] cpuidle_enter+0x17/0x20
<4>[471106.625544]  [<ffffffff810a905f>] cpu_startup_entry+0x34f/0x3d0
<4>[471106.626282]  [<ffffffff810461fc>] start_secondary+0x14c/0x160
<4>[471106.626996] Code: fa 49 83 c5 10 48 89 de ff d1 48 8b 55 c8 4c 89 e8 4c 29 f0 48 8b 4c 02 f0 48 85 c9 75 dc 65 ff 0c 25 a0 b7 00 00
e9 79 ff ff ff <0f> 0b 0f 1f 44 00 00 66 66 66 66 90 55 48 89 e5 41 55 41 54 53
<1>[471106.628532] RIP  [<ffffffff810c09c9>] add_timer_on+0xf9/0x100
<4>[471106.629244]  RSP <ffff880627c43c98>
<5>[471106.629946] ---[ now 2016-04-27 06:06:02+03 ]---
<4>[471106.630695] ---[ end trace 23e6f46f3ce04a61 ]---

WARN_ON_ONCE(!work_pending(work)) in set_work_data

<4>[235668.529480] ------------[ cut here ]------------
<4>[235668.529491] WARNING: CPU: 3 PID: 0 at kernel/workqueue.c:597 __queue_work+0x2b6/0x3d0()
<4>[235668.529493] Modules linked in: ip6t_REJECT nf_reject_ipv6 xt_tcpudp ip6table_filter ip6_tables x_tables bridge cls_cgroup sch_htb

netconsole configfs 8021q mrp garp stp llc kvm_amd kvm
microcode amd64_edac_mod edac_core edac_mce_amd mgag200 psmouse ttm serio_raw sp5100_tco drm_kms_helper drm k10temp i2c_piix4 sysimgblt sysfillrect syscopyarea mlx4_ib ib_sa ib_mad ib_core i
b_addr mlx4_en mlx4_core vxlan udp_tunnel ip6_udp_tunnel tcp_htcp raid10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov igb dca i2c_algo_bit i2c_core ptp pps_core ahci libahci
raid6_pq async_tx raid1 raid0 multipath linear [last unloaded: ipmi_msghandler]

<4>[235668.529542] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G W 3.18.25-28 #1
<4>[235668.529544] Hardware name: Supermicro H8DGU/H8DGU, BIOS 1.3 07/12/11
<4>[235668.529546] 0000000000000255 ffff88040fcc3d78 ffffffff816d08e3 0000000000000007
<4>[235668.529548] 0000000000000000 ffff88040fcc3db8 ffffffff8106bb2c ffff88040fcc3da8
<4>[235668.529551] ffff8800df94ad00 ffffffffa00d7040 ffff8800df94ad60 ffff88040f811000
<4>[235668.529553] Call Trace:
<4>[235668.529555] <IRQ> [<ffffffff816d08e3>] dump_stack+0x4e/0x68
<4>[235668.529563] [<ffffffff8106bb2c>] warn_slowpath_common+0x8c/0xc0
<4>[235668.529567] [<ffffffff8106bb7a>] warn_slowpath_null+0x1a/0x20
<4>[235668.529569] [<ffffffff81082146>] __queue_work+0x2b6/0x3d0
<4>[235668.529572] [<ffffffff81082260>] ? __queue_work+0x3d0/0x3d0
<4>[235668.529575] [<ffffffff81082278>] delayed_work_timer_fn+0x18/0x20
<4>[235668.529579] [<ffffffff810bf43a>] call_timer_fn+0x3a/0x170
<4>[235668.529582] [<ffffffff810c0f34>] run_timer_softirq+0x204/0x340
<4>[235668.529586] [<ffffffff810ce944>] ? clockevents_program_event+0x74/0x100
<4>[235668.529588] [<ffffffff81082260>] ? __queue_work+0x3d0/0x3d0
<4>[235668.529591] [<ffffffff8106f7df>] __do_softirq+0xdf/0x2f0
<4>[235668.529593] [<ffffffff8106fc66>] irq_exit+0x86/0xb0
<4>[235668.529597] [<ffffffff816db61a>] smp_apic_timer_interrupt+0x4a/0x60
<4>[235668.529600] [<ffffffff816d96fd>] apic_timer_interrupt+0x6d/0x80
<4>[235668.529601] <EOI> [<ffffffff8101e0a9>] ? sched_clock+0x9/0x10
<4>[235668.529607] [<ffffffff81055246>] ? native_safe_halt+0x6/0x10
<4>[235668.529610] [<ffffffff8101f153>] default_idle+0x23/0x100
<4>[235668.529613] [<ffffffff8101faff>] arch_cpu_idle+0xf/0x20
<4>[235668.529616] [<ffffffff810a8fea>] cpu_startup_entry+0x2da/0x3d0
<4>[235668.529619] [<ffffffff810ce352>] ? clockevents_register_device+0xe2/0x140
<4>[235668.529622] [<ffffffff810461fc>] start_secondary+0x14c/0x160
<4>[235668.529624] ---[ end trace cbf3ac778a6035e6 ]---

Quoted 1 line · Konstantin Khlebnikov

I've got plenty warnings, bugs and oops around trivial use of mod_delayed_work in drivers/infiniband/core/addr.c

Looks like problem in mod_delayed_work_on was hidden because add_timer is equal to mod_timer

but Sasha accidentally backported 874bbfe600a660cba9c776b3957b1ce393151b76 (workqueue: make sure delayed work run in local cpu) into 3.18.25

I don't see reason why that commit could break delayed work, most likely it highlighted some other problem.

Hello,

Quoted 4 lines · Konstantin Khlebnikov

Quoted 1 line · Konstantin Khlebnikov

I've got plenty warnings, bugs and oops around trivial use of mod_delayed_work in drivers/infiniband/core/addr.c

Looks like problem in mod_delayed_work_on was hidden because add_timer is equal to mod_timer

The timer usages are gated behind PENDING bit, so whether add_timer() is equal to mod_timer() shouldn't matter.

Quoted 6 lines

but Sasha accidentally backported 874bbfe600a660cba9c776b3957b1ce393151b76 (workqueue: make sure delayed work run in local cpu) into 3.18.25

I don't see reason why that commit could break delayed work, most likely it highlighted some other problem.

What are you running? Can you reproduce the issue on upstream kernel?

Quoted 4 lines · Tejun Heo

Hello,

Quoted 1 line · Konstantin Khlebnikov

On 10.05.2016 11:21, Konstantin Khlebnikov wrote:

Quoted 6 lines

Quoted 3 lines

Quoted 1 line

I've got plenty warnings, bugs and oops around trivial use of mod_delayed_work in drivers/infiniband/core/addr.c

Looks like problem in mod_delayed_work_on was hidden because add_timer is equal to mod_timer

The timer usages are gated behind PENDING bit, so whether add_timer() is equal to mod_timer() shouldn't matter.

Hmm... this looks little bit more complicated than one bit.

Quoted 10 lines

Quoted 7 lines

but Sasha accidentally backported 874bbfe600a660cba9c776b3957b1ce393151b76 (workqueue: make sure delayed work run in local cpu) into 3.18.25

I don't see reason why that commit could break delayed work, most likely it highlighted some other problem.

What are you running? Can you reproduce the issue on upstream kernel?

This is slight patched 3.18.y. Looks like this started when we upgraded kernel to 3.18.25 and somebody have loaded module ib_addr (ip in infiniband or something) which actually unused because these machines have no infiniband at all. But this code is poked from ethernet arp sometimes. So, it crashes somewhere from time to time. I'll try to stresstest this piece.

Quoted 7 lines · Konstantin Khlebnikov

Quoted 6 lines · Tejun Heo

Hello,

Quoted 3 lines · Konstantin Khlebnikov

Quoted 1 line · Konstantin Khlebnikov

I've got plenty warnings, bugs and oops around trivial use of mod_delayed_work in drivers/infiniband/core/addr.c

Quoted 6 lines

Quoted 4 lines

Quoted 1 line

Looks like problem in mod_delayed_work_on was hidden because add_timer is equal to mod_timer

The timer usages are gated behind PENDING bit, so whether add_timer() is equal to mod_timer() shouldn't matter.

Hmm... this looks little bit more complicated than one bit.

Yep, problem was here - both timer and work can be active at the same time.

So try_to_grab_pending can return success for two coRecentncurrent callers:
first get del_timer, second removes work from workqueue. After that both call add timer and one of them either catch BUG_ON or corrupt timer list.

I see two possible fixes: always remove timer and work in try_to_grab_pending but this must be carefully synchronized. This will make it slower for sure. Or always use mod_timer in __queue_delayed_work() - both callers will modify timer, but here is no mod_timer_on().

Quoted 16 lines

Quoted 10 lines

Quoted 7 lines

but Sasha accidentally backported 874bbfe600a660cba9c776b3957b1ce393151b76 (workqueue: make sure delayed work run in local cpu) into 3.18.25

I don't see reason why that commit could break delayed work, most likely it highlighted some other problem.

What are you running? Can you reproduce the issue on upstream kernel?

This is slight patched 3.18.y. Looks like this started when we upgraded kernel to 3.18.25 and somebody have loaded module ib_addr (ip in infiniband or something) which actually unused because these machines have no infiniband at all. But this code is poked from ethernet arp sometimes. So, it crashes somewhere from time to time. I'll try to stresstest this piece.

Quoted 10 lines · Konstantin Khlebnikov

Quoted 9 lines · Konstantin Khlebnikov

Quoted 8 lines · Tejun Heo

Hello,

Quoted 4 lines · Konstantin Khlebnikov

Quoted 1 line · Konstantin Khlebnikov

I've got plenty warnings, bugs and oops around trivial use of mod_delayed_work in drivers/infiniband/core/addr.c

Looks like problem in mod_delayed_work_on was hidden because add_timer is equal to mod_timer

Quoted 6 lines

Quoted 4 lines

Quoted 2 lines

The timer usages are gated behind PENDING bit, so whether add_timer() is equal to mod_timer() shouldn't matter.

Hmm... this looks little bit more complicated than one bit.

Yep, problem was here - both timer and work can be active at the same time.

Nope, this is impossible. This will be a bug itself.

Quoted 17 lines

So try_to_grab_pending can return success for two coRecentncurrent callers:
first get del_timer, second removes work from workqueue. After that both call add timer and one of them either catch BUG_ON or corrupt timer list.

I see two possible fixes: always remove timer and work in try_to_grab_pending but this must be carefully synchronized. This will make it slower for sure. Or always use mod_timer in __queue_delayed_work() - both callers will modify timer, but here is no mod_timer_on().

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

but Sasha accidentally backported 874bbfe600a660cba9c776b3957b1ce393151b76 (workqueue: make sure delayed work run in local cpu) into 3.18.25

I don't see reason why that commit could break delayed work, most likely it highlighted some other problem.

Quoted 10 lines

Quoted 9 lines

Quoted 3 lines

What are you running? Can you reproduce the issue on upstream kernel?

This is slight patched 3.18.y. Looks like this started when we upgraded kernel to 3.18.25 and somebody have loaded module ib_addr (ip in infiniband or something) which actually unused because these machines have no infiniband at all. But this code is poked from ethernet arp sometimes. So, it crashes somewhere from time to time. I'll try to stresstest this piece.