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);
