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

[Paul E. McKenney]

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?

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