Hello Steffen & Workqueue People, As Jason wrote about here a few weeks ago, we've been having issues with padata. After spending considerable time working to rule out the possibility that our code was doing something wrong, I've begun to debug padata and the workqueue subsystems. I've gotten some potentially useful backtraces and was hoping somebody here might read them and have an "ah ha!" moment.
We've been using the padata library for some high-throughput encryption/decryption workloads, and on a relatively weak CPU (Celeron J1800), we have run into list corruption that results in all workqueues getting stalled, and occasional panics. I can reproduce this fairly easily, albeit after several hours of load. Representative backtraces follow (the warnings come in sets). I have kernel .configs and extended netconsole output from several occurrences available upon request. WARNING: CPU: 1 PID: 0 at lib/list_debug.c:33 __list_add+0x89/0xb0 list_add corruption. prev->next should be next (ffff99f135016a90), but was ffffd34affc03b10. (prev=ffffd34affc03b10). CPU: 1 PID: 0 Comm: swapper/1 Tainted: G O 4.9.20+ #1 Call Trace: <IRQ> dump_stack+0x67/0x92 __warn+0xc6/0xe0 warn_slowpath_fmt+0x5a/0x80 __list_add+0x89/0xb0 insert_work+0x3c/0xc0 __queue_work+0x18a/0x600 queue_work_on+0x33/0x70 padata_do_parallel+0x14f/0x240 ? padata_index_to_cpu+0x50/0x50 ? packet_receive+0x140/0x140 [wireguard] packet_consume_data+0x1b9/0x2b0 [wireguard] ? packet_create_data+0x6b0/0x6b0 [wireguard] ? get_partial_node.isra.72+0x47/0x250 ? skb_prepare_header+0xd5/0x3f0 [wireguard] ? packet_receive+0x140/0x140 [wireguard] packet_receive+0x79/0x140 [wireguard] ? __udp4_lib_lookup+0x147/0x2d0 receive+0x1a/0x30 [wireguard] udp_queue_rcv_skb+0x34a/0x5b0 __udp4_lib_rcv+0x468/0xb40 ? ip_local_deliver_finish+0x21/0x370 udp_rcv+0x15/0x20 ip_local_deliver_finish+0xb7/0x370 ? ip_local_deliver_finish+0x21/0x370 ip_local_deliver+0x1e6/0x230 ? ip_local_deliver+0x62/0x230 ? ip_rcv_finish+0x670/0x670 ip_rcv_finish+0x1ae/0x670 ip_rcv+0x366/0x4d0 ? ip_rcv+0x26a/0x4d0 ? inet_del_offload+0x40/0x40 __netif_receive_skb_core+0xae1/0xc80 ? inet_del_offload+0x40/0x40 ? netif_receive_skb_internal+0x29/0x200 __netif_receive_skb+0x18/0x60 netif_receive_skb_internal+0x7b/0x200 ? netif_receive_skb_internal+0x29/0x200 netif_receive_skb+0xcd/0x130 br_pass_frame_up+0x2b1/0x2c0 ? br_pass_frame_up+0xad/0x2c0 ? br_allowed_ingress+0x38a/0x5d0 ? br_allowed_ingress+0x1f5/0x5d0 br_handle_frame_finish+0x28f/0x5a0 ? br_handle_frame+0x1c1/0x5e0 br_handle_frame+0x2c5/0x5e0 ? br_handle_frame+0x1c1/0x5e0 ? vlan_do_receive+0x37/0x380 ? br_handle_frame_finish+0x5a0/0x5a0 __netif_receive_skb_core+0x1e6/0xc80 ? netif_receive_skb_internal+0x29/0x200 __netif_receive_skb+0x18/0x60 netif_receive_skb_internal+0x7b/0x200 ? netif_receive_skb_internal+0x29/0x200 napi_gro_receive+0x148/0x200 igb_poll+0x67b/0xdb0 ? net_rx_action+0xe5/0x450 net_rx_action+0x224/0x450 __do_softirq+0x1a9/0x4a0 irq_exit+0xbe/0xd0 do_IRQ+0x65/0x110 common_interrupt+0x89/0x89 <EOI> This add looks to be racing with a deletion of the last item in the list, because in the actual list prev->next = prev. WARNING: CPU: 1 PID: 0 at lib/list_debug.c:36 __list_add+0xac/0xb0 list_add double add: new=ffffd34affc03b10, prev=ffffd34affc03b10, next=ffff99f135016a90. CPU: 1 PID: 0 Comm: swapper/1 Tainted: G W O 4.9.20+ #1 Call Trace: <IRQ> dump_stack+0x67/0x92 __warn+0xc6/0xe0 warn_slowpath_fmt+0x5a/0x80 __list_add+0xac/0xb0 insert_work+0x3c/0xc0 __queue_work+0x18a/0x600 queue_work_on+0x33/0x70 padata_do_parallel+0x14f/0x240 ? padata_index_to_cpu+0x50/0x50 ? packet_receive+0x140/0x140 [wireguard] packet_consume_data+0x1b9/0x2b0 [wireguard] ? packet_create_data+0x6b0/0x6b0 [wireguard] ? get_partial_node.isra.72+0x47/0x250 ? skb_prepare_header+0xd5/0x3f0 [wireguard] ? packet_receive+0x140/0x140 [wireguard] packet_receive+0x79/0x140 [wireguard] ? __udp4_lib_lookup+0x147/0x2d0 receive+0x1a/0x30 [wireguard] udp_queue_rcv_skb+0x34a/0x5b0 __udp4_lib_rcv+0x468/0xb40 ? ip_local_deliver_finish+0x21/0x370 udp_rcv+0x15/0x20 ip_local_deliver_finish+0xb7/0x370 ? ip_local_deliver_finish+0x21/0x370 ip_local_deliver+0x1e6/0x230 ? ip_local_deliver+0x62/0x230 ? ip_rcv_finish+0x670/0x670 ip_rcv_finish+0x1ae/0x670 ip_rcv+0x366/0x4d0 ? ip_rcv+0x26a/0x4d0 ? inet_del_offload+0x40/0x40 __netif_receive_skb_core+0xae1/0xc80 ? inet_del_offload+0x40/0x40 ? netif_receive_skb_internal+0x29/0x200 __netif_receive_skb+0x18/0x60 netif_receive_skb_internal+0x7b/0x200 ? netif_receive_skb_internal+0x29/0x200 netif_receive_skb+0xcd/0x130 br_pass_frame_up+0x2b1/0x2c0 ? br_pass_frame_up+0xad/0x2c0 ? br_allowed_ingress+0x38a/0x5d0 ? br_allowed_ingress+0x1f5/0x5d0 br_handle_frame_finish+0x28f/0x5a0 ? br_handle_frame+0x1c1/0x5e0 br_handle_frame+0x2c5/0x5e0 ? br_handle_frame+0x1c1/0x5e0 ? vlan_do_receive+0x37/0x380 ? br_handle_frame_finish+0x5a0/0x5a0 __netif_receive_skb_core+0x1e6/0xc80 ? netif_receive_skb_internal+0x29/0x200 __netif_receive_skb+0x18/0x60 netif_receive_skb_internal+0x7b/0x200 ? netif_receive_skb_internal+0x29/0x200 napi_gro_receive+0x148/0x200 igb_poll+0x67b/0xdb0 ? net_rx_action+0xe5/0x450 net_rx_action+0x224/0x450 __do_softirq+0x1a9/0x4a0 irq_exit+0xbe/0xd0 do_IRQ+0x65/0x110 common_interrupt+0x89/0x89 <EOI> And finally: WARNING: CPU: 0 PID: 0 at lib/list_debug.c:33 __list_add+0x89/0xb0 list_add corruption. prev->next should be next (ffff99f135016a90), but was ffffd34affc03b10. (prev=ffffd34affc03b10). CPU: 0 PID: 0 Comm: swapper/0 Tainted: G W O 4.9.20+ #1 Call Trace: <IRQ> dump_stack+0x67/0x92 __warn+0xc6/0xe0 warn_slowpath_fmt+0x5a/0x80 __list_add+0x89/0xb0 insert_work+0x3c/0xc0 __queue_work+0x18a/0x600 ? execute_in_process_context+0x90/0x90 delayed_work_timer_fn+0x19/0x20 call_timer_fn+0xa8/0x340 ? process_timeout+0x10/0x10 ? execute_in_process_context+0x90/0x90 run_timer_softirq+0x1bf/0x6b0 ? ktime_get+0x91/0x120 ? clockevents_program_event+0x42/0x120 ? clockevents_program_event+0x7d/0x120 __do_softirq+0x1a9/0x4a0 irq_exit+0xbe/0xd0 smp_apic_timer_interrupt+0x3d/0x50 apic_timer_interrupt+0x89/0x90 <EOI> Note that this third warning is on the other CPU. All three warnings are immediately consecutive in the kernel logs (within 1 second). Looking at the workqueue code and documentation, it should be fine to call queue_work_on() on an already-queued work item, as padata is doing. I've also triggered a related warning in the workqueue code a few times: WARNING at kernel/workqueue.c:1440 __queue_work+0x1d6/0x450 CPU: 1 PID: 1013 Comm: kworker/1:2 Tainted: G W O 4.9.17 #1 Call Trace: dump_stack+0x4d/0x65 __warn+0xc6/0xe0 warn_slowpath_null+0x18/0x20 __queue_work+0x1d6/0x450 queue_work_on+0x14/0x30 padata_reorder+0xb2/0x160 padata_do_serial+0x51/0x60 timers_uninit_peer+0x275/0xa20 [wireguard] padata_parallel_worker+0x77/0xa0 process_one_work+0x154/0x410 worker_thread+0x46/0x470 ? process_one_work+0x410/0x410 kthread+0xc5/0xe0 ? kthread_park+0x60/0x60 ? kthread_park+0x60/0x60 ret_from_fork+0x22/0x30 FWIW I'm also sometimes seeing similar list corruption in the padata queues, usually in padata_reorder(), as well as with lists in the timer subsystem relating to padata's reorder timer. Lockdep does not complain about anything, and I've manually checked the locking all three subsystems to no avail, so I suspect this may ultimately be a deeper synchronization or memory corruption issue. If you have any immediate ideas, I'd be very grateful. If not, we'll keep debugging, of course. Thanks for any insight, Samuel
