workqueue: race in mod_delayed_work_on?
From: Konstantin Khlebnikov
Date: Tue May 10 2016 - 04:21:50 EST
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 ]---
--
Konstantin