RE: [BUG] possible deadlock in __rcu_irq_enter_check_tick

From: Zhang, Qiang1
Date: Tue Oct 18 2022 - 22:40:36 EST

Next message: kernel test robot: "Re: [PATCH] sched: async unthrottling for cfs bandwidth"
Previous message: Zheng Hacker: "Re: [PATCH v3] misc: sgi-gru: fix use-after-free error in gru_set_context_option, gru_fault and gru_handle_user_call_os"
In reply to: Mark Rutland: "Re: [BUG] possible deadlock in __rcu_irq_enter_check_tick"
Next in thread: Yu Liao: "Re: [BUG] possible deadlock in __rcu_irq_enter_check_tick"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Tue, Oct 11, 2022 at 11:49:11PM -0700, Paul E. McKenney wrote:
> On Tue, Oct 11, 2022 at 09:18:11PM +0800, Yu Liao wrote:
> > Hello,
> >
> > When I run syzkaller, a deadlock problem occurs. The call stack is as follows:
> > [ 1088.244366][ C1] ======================================================
> > [ 1088.244838][ C1] WARNING: possible circular locking dependency detected
> > [ 1088.245313][ C1] 5.10.0-04424-ga472e3c833d3 #1 Not tainted
> > [ 1088.245745][ C1] ------------------------------------------------------
>
> It is quite possible that an unfortunate set of commits were
> backported to v5.10. Could you please bisect?
>
> > [ 1088.246214][ C1] syz-executor.2/932 is trying to acquire lock:
> > [ 1088.246628][ C1] ffffa0001440c418 (rcu_node_0){..-.}-{2:2}, at:
> > __rcu_irq_enter_check_tick+0x128/0x2f4
> > [ 1088.247330][ C1]
> > [ 1088.247330][ C1] but task is already holding lock:
> > [ 1088.247830][ C1] ffff000224d0c298 (&rq->lock){-.-.}-{2:2}, at:
> > try_to_wake_up+0x6e0/0xd40
> > [ 1088.248424][ C1]
> > [ 1088.248424][ C1] which lock already depends on the new lock.
> > [ 1088.248424][ C1]
> > [ 1088.249127][ C1]
> > [ 1088.249127][ C1] the existing dependency chain (in reverse order) is:
> > [ 1088.249726][ C1]
> > [ 1088.249726][ C1] -> #1 (&rq->lock){-.-.}-{2:2}:
> > [ 1088.250239][ C1] validate_chain+0x6dc/0xb0c
> > [ 1088.250591][ C1] __lock_acquire+0x498/0x940
> > [ 1088.250942][ C1] lock_acquire+0x228/0x580
> > [ 1088.251346][ C1] _raw_spin_lock_irqsave+0xc0/0x15c
> > [ 1088.251758][ C1] resched_cpu+0x5c/0x110
> > [ 1088.252091][ C1] rcu_implicit_dynticks_qs+0x2b0/0x5d0
> > [ 1088.252501][ C1] force_qs_rnp+0x244/0x39c
> > [ 1088.252847][ C1] rcu_gp_fqs_loop+0x2e4/0x440
> > [ 1088.253219][ C1] rcu_gp_kthread+0x1a4/0x240
> > [ 1088.253597][ C1] kthread+0x20c/0x260
> > [ 1088.253963][ C1] ret_from_fork+0x10/0x18
> > [ 1088.254389][ C1]
> > [ 1088.254389][ C1] -> #0 (rcu_node_0){..-.}-{2:2}:
> > [ 1088.255296][ C1] check_prev_add+0xe0/0x105c
> > [ 1088.256000][ C1] check_prevs_add+0x1c8/0x3d4
> > [ 1088.256693][ C1] validate_chain+0x6dc/0xb0c
> > [ 1088.257372][ C1] __lock_acquire+0x498/0x940
> > [ 1088.257731][ C1] lock_acquire+0x228/0x580
> > [ 1088.258079][ C1] _raw_spin_lock+0xa0/0x120
> > [ 1088.258425][ C1] __rcu_irq_enter_check_tick+0x128/0x2f4
> > [ 1088.258844][ C1] rcu_nmi_enter+0xc4/0xd0
>
> This is looking like we took an interrupt while holding an rq lock.
> Am I reading this correctly? If so, that is bad in and of itself.
>
>In this case it's not an interrupt; per the entry bits below:
>
> > [ 1088.259183][ C1] arm64_enter_el1_dbg+0xb0/0x160
> > [ 1088.259623][ C1] el1_dbg+0x28/0x50
> > [ 1088.260011][ C1] el1_sync_handler+0xf4/0x150
> > [ 1088.260481][ C1] el1_sync+0x74/0x100

>
>... this is a synchronous debug exception, which is one of:
>
> * A hardware single-step exception
> * A hardware watchpoint
> * A hardware breakpoint
> * A software breakpoint (i.e. a BRK instruction)
>
>... and we have to treat those as NMIs.

Hi Mark

As can be seen from the callstack, we are not treating the above as NMI,
The following code snippet can also be seen:

kernel-v5.10 kernel:

rcu_nmi_enter ()
{
..........
} else if (!in_nmi()) {
instrumentation_begin();
rcu_irq_enter_check_tick();
}

Maybe the following modification should be added:

--- a/arch/arm64/kernel/entry-common.c
+++ b/arch/arm64/kernel/entry-common.c
@@ -259,7 +259,7 @@ static void noinstr el1_inv(struct pt_regs *regs, unsigned long esr) static void noinstr arm64_enter_el1_dbg(struct pt_regs *regs) {
regs->lockdep_hardirqs = lockdep_hardirqs_enabled();
-
+ __nmi_enter();
lockdep_hardirqs_off(CALLER_ADDR0);
rcu_nmi_enter();

@@ -278,6 +278,7 @@ static void noinstr arm64_exit_el1_dbg(struct pt_regs *regs)
rcu_nmi_exit();
if (restore)
lockdep_hardirqs_on(CALLER_ADDR0);
+ __nmi_exit();
}

Thanks
Zqiang

>
>That could be a kprobe, or a WARN, etc.
>
>Thanks,
>Mark.
>
> > [ 1088.260800][ C1] update_irq_load_avg+0x5d8/0xaa0
> > [ 1088.261194][ C1] update_rq_clock_task+0xb8/0x2d0
> > [ 1088.261595][ C1] update_rq_clock+0x8c/0x120
> > [ 1088.261952][ C1] try_to_wake_up+0x70c/0xd40
> > [ 1088.262305][ C1] wake_up_process+0x1c/0x24
> > [ 1088.262652][ C1] wakeup_softirqd+0x58/0x64
> > [ 1088.263000][ C1] __do_softirq+0x6b8/0x95c
> > [ 1088.263345][ C1] irq_exit+0x27c/0x2d0
> > [ 1088.263674][ C1] __handle_domain_irq+0x100/0x184
> > [ 1088.264049][ C1] gic_handle_irq+0xc0/0x760
> > [ 1088.264394][ C1] el1_irq+0xb8/0x140
> > [ 1088.264709][ C1] _raw_spin_unlock_irqrestore+0x7c/0x130
> > [ 1088.265134][ C1] __aarch64_insn_write+0xc4/0x100
> > [ 1088.265516][ C1] aarch64_insn_patch_text_nosync+0x40/0xa0
> > [ 1088.265942][ C1] ftrace_make_nop+0x120/0x1a4
> > [ 1088.266300][ C1] __ftrace_replace_code+0xdc/0x160
> > [ 1088.266684][ C1] ftrace_replace_code+0x100/0x1a4
> > [ 1088.267063][ C1] ftrace_modify_all_code+0x1a8/0x260
> > [ 1088.267456][ C1] arch_ftrace_update_code+0x1c/0x2c
> > [ 1088.267847][ C1] ftrace_run_update_code+0x38/0xa4
> > [ 1088.268259][ C1] ftrace_shutdown.part.0+0x2dc/0x550
> > [ 1088.268682][ C1] unregister_ftrace_function+0x74/0xc0
> > [ 1088.269117][ C1] perf_ftrace_event_register+0x130/0x1a0
> > [ 1088.269559][ C1] perf_trace_destroy+0x68/0x9c
> > [ 1088.269938][ C1] tp_perf_event_destroy+0x1c/0x2c
> > [ 1088.270340][ C1] _free_event+0x2f4/0x670
> > [ 1088.270696][ C1] put_event+0x7c/0x90
> > [ 1088.271031][ C1] perf_event_release_kernel+0x3c0/0x450
> > [ 1088.271467][ C1] perf_release+0x24/0x34
> > [ 1088.271824][ C1] __fput+0x1dc/0x500
> > [ 1088.272155][ C1] ____fput+0x24/0x30
> > [ 1088.272471][ C1] task_work_run+0xf4/0x1ec
> > [ 1088.272811][ C1] do_notify_resume+0x378/0x410
> > [ 1088.273180][ C1] work_pending+0xc/0x198
> > [ 1088.273504][ C1]
> > [ 1088.273504][ C1] other info that might help us debug this:
> > [ 1088.273504][ C1]
> > [ 1088.274168][ C1] Possible unsafe locking scenario:
> > [ 1088.274168][ C1]
> > [ 1088.274658][ C1] CPU0 CPU1
> > [ 1088.275012][ C1] ---- ----
> > [ 1088.275367][ C1] lock(&rq->lock);
> > [ 1088.275646][ C1] lock(rcu_node_0);
> > [ 1088.276082][ C1] lock(&rq->lock);
> > [ 1088.276517][ C1] lock(rcu_node_0);
> > [ 1088.276797][ C1]
> > [ 1088.276797][ C1] *** DEADLOCK ***
> > [ 1088.276797][ C1]
> > [ 1088.277339][ C1] 4 locks held by syz-executor.2/932:
> > [ 1088.277696][ C1] #0: ffffa000145251e8 (event_mutex){+.+.}-{3:3}, at:
> > perf_trace_destroy+0x34/0x9c
> > [ 1088.278345][ C1] #1: ffffa000144fb5a8 (ftrace_lock){+.+.}-{3:3}, at:
> > unregister_ftrace_function+0x2c/0xc0
> > [ 1088.279034][ C1] #2: ffff0000c0e0c968 (&p->pi_lock){-.-.}-{2:2}, at:
> > try_to_wake_up+0xbc/0xd40
> > [ 1088.279672][ C1] #3: ffff000224d0c298 (&rq->lock){-.-.}-{2:2}, at:
> > try_to_wake_up+0x6e0/0xd40
> > [ 1088.280300][ C1]
> > [ 1088.280300][ C1] stack backtrace:
> > [ 1088.280706][ C1] CPU: 1 PID: 932 Comm: syz-executor.2 Not tainted
> > 5.10.0-04424-ga472e3c833d3 #1
> > [ 1088.281315][ C1] Hardware name: linux,dummy-virt (DT)
> > [ 1088.281679][ C1] Call trace:
> > [ 1088.281910][ C1] dump_backtrace+0x0/0x41c
> > [ 1088.282218][ C1] show_stack+0x30/0x40
> > [ 1088.282505][ C1] dump_stack+0x1fc/0x2c0
> > [ 1088.282807][ C1] print_circular_bug+0x1ec/0x284
> > [ 1088.283149][ C1] check_noncircular+0x1cc/0x1ec
> > [ 1088.283486][ C1] check_prev_add+0xe0/0x105c
> > [ 1088.283804][ C1] check_prevs_add+0x1c8/0x3d4
> > [ 1088.284126][ C1] validate_chain+0x6dc/0xb0c
> > [ 1088.284442][ C1] __lock_acquire+0x498/0x940
> > [ 1088.284764][ C1] lock_acquire+0x228/0x580
> > [ 1088.285072][ C1] _raw_spin_lock+0xa0/0x120
> > [ 1088.285392][ C1] __rcu_irq_enter_check_tick+0x128/0x2f4
> > [ 1088.285779][ C1] rcu_nmi_enter+0xc4/0xd0
> > [ 1088.286082][ C1] arm64_enter_el1_dbg+0xb0/0x160
> > [ 1088.286420][ C1] el1_dbg+0x28/0x50
> > [ 1088.286689][ C1] el1_sync_handler+0xf4/0x150
> > [ 1088.287010][ C1] el1_sync+0x74/0x100
> > [ 1088.287295][ C1] update_irq_load_avg+0x5d8/0xaa0
> > [ 1088.287640][ C1] update_rq_clock_task+0xb8/0x2d0
> > [ 1088.287988][ C1] update_rq_clock+0x8c/0x120
> > [ 1088.288309][ C1] try_to_wake_up+0x70c/0xd40
> > [ 1088.288629][ C1] wake_up_process+0x1c/0x24
> > [ 1088.288945][ C1] wakeup_softirqd+0x58/0x64
> > [ 1088.289271][ C1] __do_softirq+0x6b8/0x95c
> > [ 1088.289580][ C1] irq_exit+0x27c/0x2d0
> > [ 1088.289868][ C1] __handle_domain_irq+0x100/0x184
> > [ 1088.290211][ C1] gic_handle_irq+0xc0/0x760
> > [ 1088.290522][ C1] el1_irq+0xb8/0x140
> > [ 1088.290801][ C1] _raw_spin_unlock_irqrestore+0x7c/0x130
> > [ 1088.291188][ C1] __aarch64_insn_write+0xc4/0x100
> > [ 1088.291533][ C1] aarch64_insn_patch_text_nosync+0x40/0xa0
> > [ 1088.291928][ C1] ftrace_make_nop+0x120/0x1a4
> > [ 1088.292256][ C1] __ftrace_replace_code+0xdc/0x160
> > [ 1088.292613][ C1] ftrace_replace_code+0x100/0x1a4
> > [ 1088.292963][ C1] ftrace_modify_all_code+0x1a8/0x260
> > [ 1088.293335][ C1] arch_ftrace_update_code+0x1c/0x2c
> > [ 1088.293694][ C1] ftrace_run_update_code+0x38/0xa4
> > [ 1088.294048][ C1] ftrace_shutdown.part.0+0x2dc/0x550
> > [ 1088.294415][ C1] unregister_ftrace_function+0x74/0xc0
> > [ 1088.294787][ C1] perf_ftrace_event_register+0x130/0x1a0
> > [ 1088.295172][ C1] perf_trace_destroy+0x68/0x9c
> > [ 1088.295500][ C1] tp_perf_event_destroy+0x1c/0x2c
> > [ 1088.295850][ C1] _free_event+0x2f4/0x670
> > [ 1088.296154][ C1] put_event+0x7c/0x90
> > [ 1088.296439][ C1] perf_event_release_kernel+0x3c0/0x450
> > [ 1088.296820][ C1] perf_release+0x24/0x34
> > [ 1088.297125][ C1] __fput+0x1dc/0x500
> > [ 1088.297404][ C1] ____fput+0x24/0x30
> > [ 1088.297682][ C1] task_work_run+0xf4/0x1ec
> > [ 1088.297989][ C1] do_notify_resume+0x378/0x410
> > [ 1088.298316][ C1] work_pending+0xc/0x198
> >
> > I checked the code. The following scenarios may cause deadlock.
> >
> > static void ttwu_queue(struct task_struct *p, int cpu, int
> > wake_flags) {
> > struct rq *rq = cpu_rq(cpu);
> > struct rq_flags rf;
> >
> > if (ttwu_queue_wakelist(p, cpu, wake_flags))
> > return;
> >
> > rq_lock(rq, &rf);
> > update_rq_clock(rq);
> > ===> el1_dbg
> > ->rcu_nmi_enter
> > ->__rcu_irq_enter_check_tick
> > ->raw_spin_lock_rcu_node(rdp->mynode);
> > ttwu_do_activate(rq, p, wake_flags, &rf);
> > rq_unlock(rq, &rf);
> > }
> >
> > static void rcu_gp_fqs(bool first_time) {
> > struct rcu_node *rnp = rcu_get_root();
> >
> > WRITE_ONCE(rcu_state.gp_activity, jiffies);
> > WRITE_ONCE(rcu_state.n_force_qs, rcu_state.n_force_qs + 1);
> > if (first_time) {
> > /* Collect dyntick-idle snapshots. */
> > force_qs_rnp(dyntick_save_progress_counter);
> > } else {
> > /* Handle dyntick-idle and offline CPUs. */
> > force_qs_rnp(rcu_implicit_dynticks_qs);
> > ===>raw_spin_lock_irqsave_rcu_node(rnp, flags);
> > ===>rcu_implicit_dynticks_qs
> > ->resched_cpu
> > ->raw_spin_lock_irqsave(&rq->lock, flags);
> > }
> > /* Clear flag to prevent immediate re-entry. */
> > if (READ_ONCE(rcu_state.gp_flags) & RCU_GP_FLAG_FQS) {
> > raw_spin_lock_irq_rcu_node(rnp);
> > WRITE_ONCE(rcu_state.gp_flags,
> > READ_ONCE(rcu_state.gp_flags) & ~RCU_GP_FLAG_FQS);
> > raw_spin_unlock_irq_rcu_node(rnp);
> > }
> > }
> >

Next message: kernel test robot: "Re: [PATCH] sched: async unthrottling for cfs bandwidth"
Previous message: Zheng Hacker: "Re: [PATCH v3] misc: sgi-gru: fix use-after-free error in gru_set_context_option, gru_fault and gru_handle_user_call_os"
In reply to: Mark Rutland: "Re: [BUG] possible deadlock in __rcu_irq_enter_check_tick"
Next in thread: Yu Liao: "Re: [BUG] possible deadlock in __rcu_irq_enter_check_tick"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]