Re: [PATCH v4] rcu: Dump all rcuc kthreads status for CPUs that not report quiescent state

From: Paul E. McKenney
Date: Tue Apr 26 2022 - 12:15:56 EST

On Tue, Apr 26, 2022 at 02:38:20PM +0000, Zhang, Qiang1 wrote:
>
> On Tue, Apr 26, 2022 at 06:44:46AM +0000, Zhang, Qiang1 wrote:
> >
> > On Mon, Apr 25, 2022 at 09:04:04AM +0800, Zqiang wrote:
> > > If the rcutree.use_softirq is configured, when RCU Stall event
> > > happened, dump status of all rcuc kthreads who due to starvation
> > > prevented grace period ends on CPUs that not report quiescent state.
> > >
> > > Signed-off-by: Zqiang <qiang1.zhang@xxxxxxxxx>
> > > ---
> > > v1->v2:
> > > rework rcuc_kthread_dump function
> > > v2->v3:
> > > merge this rcuc-stalled information into print_cpu_stall_info()
> > > v3->v4:
> > > print rcuc info only when rcuc kthread is starved
> > >
> > > kernel/rcu/tree_stall.h | 49
> > > ++++++++++++++++++-----------------------
> > > 1 file changed, 21 insertions(+), 28 deletions(-)
> >
> > >I have queued this for testing and further review, thank you!
> > >
> > >I did the usual wordsmithing, plus I got rid of a couple of space characters that are extraneous in the common case (one of yours and one pre-existing instance).
> > >
> > >Could you please generate an actual stall of this type? You might need to add a delay to the rcuc code, but other than that, please see the rcutorture blog series [1] and in particular the post on forcing stall warnings [2].
> > >
> > > Thanx, Paul
> > >
> > >[1] https://paulmck.livejournal.com/61432.html
> > >[2] https://paulmck.livejournal.com/58077.html
> >
> > I followed the instructions, add " rcutorture.stall_cpu=22
> > rcutorture.fwd_progress=0" and " rcutree.use_softirq=0"to bootargs, can trigger RCU CPU stall warning:
> >
> > root@qemux86-64:/# dmesg
> > [ 37.556435] rcu: INFO: rcu_preempt self-detected stall on CPU
> > [ 37.556437] rcu: 3-....: (1 GPs behind) idle=269/1/0x4000000000000000 softirq=0/0 fqs=5631 rcuc=26004 jiffies(starved)
> > [ 37.556440] (t=26000 jiffies g=3589 q=35403)
> > [ 37.556441] NMI backtrace for cpu 3
> > [ 37.556442] CPU: 3 PID: 117 Comm: rcu_torture_sta Tainted: G L 5.17.0-yoctodev-standard #16 7fe7533e7466875b0801ac148f921afcf57d38bc
> > [ 37.556443] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
> > [ 37.556444] Call Trace:
> > [ 37.556445] <IRQ>
> > [ 37.556446] dump_stack_lvl+0x5b/0x82
> > [ 37.556449] dump_stack+0x10/0x12
> > [ 37.556451] nmi_cpu_backtrace.cold+0x32/0x8a
> > [ 37.556452] ? lapic_can_unplug_cpu+0x80/0x80
> > [ 37.556454] nmi_trigger_cpumask_backtrace+0xce/0xe0
> > [ 37.556456] arch_trigger_cpumask_backtrace+0x19/0x20
> > [ 37.556458] rcu_dump_cpu_stacks+0xcd/0x140
> > [ 37.556460] rcu_sched_clock_irq.cold+0x7a/0x3ba
> > [ 37.556463] ? debug_smp_processor_id+0x17/0x20
> > [ 37.556466] update_process_times+0x9b/0xd0
> > [ 37.556467] tick_sched_handle.isra.0+0x25/0x50
> > [ 37.556469] tick_sched_timer+0x79/0x90
> > [ 37.556470] ? tick_sched_do_timer+0x60/0x60
> > [ 37.556471] __hrtimer_run_queues+0x1d1/0x4c0
> > [ 37.556473] hrtimer_interrupt+0x114/0x230
> > [ 37.556475] ? rcu_read_lock_held_common+0x12/0x50
> > [ 37.556489] __sysvec_apic_timer_interrupt+0xa4/0x280
> > [ 37.556491] sysvec_apic_timer_interrupt+0x95/0xc0
> > [ 37.556492] </IRQ>
>
> >Excellent, thank you!!!
> >
> >Now could you please do the same thing for a use_softirq kernel to verify that it prints correctly when that message is not supposed to be shown?
>
> The use_softirq is not set zero, log follow:
>
> rcu: INFO: rcu_preempt self-detected stall on CPU
> [ 32.388910] rcu: 3-....: (20847 ticks this GP) idle=733/1/0x4000000000000000 softirq=4565/4565 fqs=4655
> [ 32.388913] (t=21000 jiffies g=8113 q=12547)
> [ 32.388914] NMI backtrace for cpu 3
> [ 32.388914] CPU: 3 PID: 73 Comm: rcu_torture_sta Tainted: G L 5.17.0-yoctodev-standard #2 05f26dfea00beb93d9714ba8d61bb77646676403
> [ 32.388915] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
> [ 32.388916] Call Trace:
> [ 32.388916] <IRQ>
> [ 32.388917] dump_stack_lvl+0x5b/0x82

Again excellent, and again, thank you!

Thanx, Paul

> Thanks
> Zqiang
>
> >
> > Thanx, Paul
>
> > Thanks
> > Zqiang
> >
> > >
> > ----------------------------------------------------------------------
> > --
> >
> > commit 66226e2acda8b31b60137b1ae71244df68541a01
> > Author: Zqiang <qiang1.zhang@xxxxxxxxx>
> > Date: Mon Apr 25 09:04:04 2022 +0800
> >
> > rcu: Dump all rcuc kthreads status for CPUs that not report
> > quiescent state
> >
> > If the rcutree.use_softirq kernel boot parameter is disabled, then it is
> > possible that a RCU CPU stall is due to the rcuc kthreads being starved of
> > CPU time. There is currently no easy way to infer this from the RCU CPU
> > stall warning output. This commit therefore adds a string of the form "
> > rcuc=%ld jiffies(starved)" to a given CPU's output if the corresponding
> > rcuc kthread has been starved for more than two seconds.
> >
> > [ paulmck: Eliminate extraneous space characters. ]
> >
> > Signed-off-by: Zqiang <qiang1.zhang@xxxxxxxxx>
> > Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>
> >
> > diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h index
> > d7956c03edbd4..0a25a4ea6eef8 100644
> > --- a/kernel/rcu/tree_stall.h
> > +++ b/kernel/rcu/tree_stall.h
> > @@ -407,7 +407,19 @@ static bool rcu_is_gp_kthread_starving(unsigned
> > long *jp)
> >
> > static bool rcu_is_rcuc_kthread_starving(struct rcu_data *rdp, unsigned long *jp) {
> > - unsigned long j = jiffies - READ_ONCE(rdp->rcuc_activity);
> > + int cpu;
> > + struct task_struct *rcuc;
> > + unsigned long j;
> > +
> > + rcuc = rdp->rcu_cpu_kthread_task;
> > + if (!rcuc)
> > + return false;
> > +
> > + cpu = task_cpu(rcuc);
> > + if (cpu_is_offline(cpu) || idle_cpu(cpu))
> > + return false;
> > +
> > + j = jiffies - READ_ONCE(rdp->rcuc_activity);
> >
> > if (jp)
> > *jp = j;
> > @@ -432,6 +444,9 @@ static void print_cpu_stall_info(int cpu)
> > struct rcu_data *rdp = per_cpu_ptr(&rcu_data, cpu);
> > char *ticks_title;
> > unsigned long ticks_value;
> > + bool rcuc_starved;
> > + unsigned long j;
> > + char buf[32];
> >
> > /*
> > * We could be printing a lot while holding a spinlock. Avoid @@ -449,7 +464,10 @@ static void print_cpu_stall_info(int cpu)
> > delta = rcu_seq_ctr(rdp->mynode->gp_seq - rdp->rcu_iw_gp_seq);
> > falsepositive = rcu_is_gp_kthread_starving(NULL) &&
> > rcu_dynticks_in_eqs(rcu_dynticks_snap(rdp));
> > - pr_err("\t%d-%c%c%c%c: (%lu %s) idle=%03x/%ld/%#lx softirq=%u/%u fqs=%ld %s\n",
> > + rcuc_starved = rcu_is_rcuc_kthread_starving(rdp, &j);
> > + if (rcuc_starved)
> > + sprintf(buf, " rcuc=%ld jiffies(starved)", j);
> > + pr_err("\t%d-%c%c%c%c: (%lu %s) idle=%03x/%ld/%#lx softirq=%u/%u
> > +fqs=%ld%s%s\n",
> > cpu,
> > "O."[!!cpu_online(cpu)],
> > "o."[!!(rdp->grpmask & rdp->mynode->qsmaskinit)], @@ -462,32 +480,10 @@ static void print_cpu_stall_info(int cpu)
> > rdp->dynticks_nesting, rdp->dynticks_nmi_nesting,
> > rdp->softirq_snap, kstat_softirqs_cpu(RCU_SOFTIRQ, cpu),
> > data_race(rcu_state.n_force_qs) -
> > rcu_state.n_force_qs_gpstart,
> > + rcuc_starved ? buf : "",
> > falsepositive ? " (false positive?)" : ""); }
> >
> > -static void rcuc_kthread_dump(struct rcu_data *rdp) -{
> > - int cpu;
> > - unsigned long j;
> > - struct task_struct *rcuc;
> > -
> > - rcuc = rdp->rcu_cpu_kthread_task;
> > - if (!rcuc)
> > - return;
> > -
> > - cpu = task_cpu(rcuc);
> > - if (cpu_is_offline(cpu) || idle_cpu(cpu))
> > - return;
> > -
> > - if (!rcu_is_rcuc_kthread_starving(rdp, &j))
> > - return;
> > -
> > - pr_err("%s kthread starved for %ld jiffies\n", rcuc->comm, j);
> > - sched_show_task(rcuc);
> > - if (!trigger_single_cpu_backtrace(cpu))
> > - dump_cpu_task(cpu);
> > -}
> > -
> > /* Complain about starvation of grace-period kthread. */ static
> > void rcu_check_gp_kthread_starvation(void)
> > {
> > @@ -659,9 +655,6 @@ static void print_cpu_stall(unsigned long gps)
> > rcu_check_gp_kthread_expired_fqs_timer();
> > rcu_check_gp_kthread_starvation();
> >
> > - if (!use_softirq)
> > - rcuc_kthread_dump(rdp);
> > -
> > rcu_dump_cpu_stacks();
> >
> > raw_spin_lock_irqsave_rcu_node(rnp, flags);