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 <[email protected]>
---
v1->v2:
rework rcuc_kthread_dump function
v2->v3:
merge this rcuc-stalled information into print_cpu_stall_info()
kernel/rcu/tree_stall.h | 46 ++++++++++++++++-------------------------
1 file changed, 18 insertions(+), 28 deletions(-)
diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h
index d7956c03edbd..3482e37d2e3e 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,8 @@ 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;
/*
* We could be printing a lot while holding a spinlock. Avoid
@@ -449,7 +463,8 @@ 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);
+ pr_err("\t%d-%c%c%c%c: (%lu %s) idle=%03x/%ld/%#lx softirq=%u/%u fqs=%ld rcuc=%ld jiffies(%s) %s\n",
cpu,
"O."[!!cpu_online(cpu)],
"o."[!!(rdp->grpmask & rdp->mynode->qsmaskinit)],
@@ -462,32 +477,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,
+ j, rcuc_starved ? "starved" : "",
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 +652,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);
--
2.25.1
On Sun, Apr 24, 2022 at 12:17:47PM +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 <[email protected]>
Much, much better, thank you!
A few more comments below.
Thanx, Paul
> ---
> v1->v2:
> rework rcuc_kthread_dump function
> v2->v3:
> merge this rcuc-stalled information into print_cpu_stall_info()
>
> kernel/rcu/tree_stall.h | 46 ++++++++++++++++-------------------------
> 1 file changed, 18 insertions(+), 28 deletions(-)
>
> diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h
> index d7956c03edbd..3482e37d2e3e 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);
Localizing this logic is a good improvement, thank you!
> if (jp)
> *jp = j;
> @@ -432,6 +444,8 @@ 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;
>
> /*
> * We could be printing a lot while holding a spinlock. Avoid
> @@ -449,7 +463,8 @@ 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);
> + pr_err("\t%d-%c%c%c%c: (%lu %s) idle=%03x/%ld/%#lx softirq=%u/%u fqs=%ld rcuc=%ld jiffies(%s) %s\n",
The trick here is to sprintf() to format the "rcuc=%ld jiffies" part of
the message, then just have "%s" instead of the "rcuc=%ld jiffies(%s)",
and then ...
> cpu,
> "O."[!!cpu_online(cpu)],
> "o."[!!(rdp->grpmask & rdp->mynode->qsmaskinit)],
> @@ -462,32 +477,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,
> + j, rcuc_starved ? "starved" : "",
... here have:
rcu_starved ? buf : "",
Where "buf" is the place you sprintf()ed into. This is especially
important for kernels that don't have rcuc kthreads in the first place.
We don't need the poor CPU-stalled systems administrator wasting time
wondering what an rcuc is an why anyone would care. ;-)
> 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 +652,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);
> --
> 2.25.1
>
Hi Zqiang,
url: https://github.com/intel-lab-lkp/linux/commits/Zqiang/rcu-Dump-all-rcuc-kthreads-status-for-CPUs-that-not-report-quiescent-state/20220424-121850
base: https://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu.git dev
config: i386-randconfig-m021 (https://download.01.org/0day-ci/archive/20220424/[email protected]/config)
compiler: gcc-11 (Debian 11.2.0-20) 11.2.0
If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <[email protected]>
Reported-by: Dan Carpenter <[email protected]>
smatch warnings:
kernel/rcu/tree_stall.h:467 print_cpu_stall_info() error: uninitialized symbol 'j'.
vim +/j +467 kernel/rcu/tree_stall.h
59b73a27681c58 Paul E. McKenney 2019-01-11 440 static void print_cpu_stall_info(int cpu)
59b73a27681c58 Paul E. McKenney 2019-01-11 441 {
59b73a27681c58 Paul E. McKenney 2019-01-11 442 unsigned long delta;
88375825171c7d Paul E. McKenney 2020-03-31 443 bool falsepositive;
59b73a27681c58 Paul E. McKenney 2019-01-11 444 struct rcu_data *rdp = per_cpu_ptr(&rcu_data, cpu);
59b73a27681c58 Paul E. McKenney 2019-01-11 445 char *ticks_title;
59b73a27681c58 Paul E. McKenney 2019-01-11 446 unsigned long ticks_value;
17d9de741a1aaf Zqiang 2022-04-24 447 bool rcuc_starved;
17d9de741a1aaf Zqiang 2022-04-24 448 unsigned long j;
59b73a27681c58 Paul E. McKenney 2019-01-11 449
59b73a27681c58 Paul E. McKenney 2019-01-11 450 /*
59b73a27681c58 Paul E. McKenney 2019-01-11 451 * We could be printing a lot while holding a spinlock. Avoid
59b73a27681c58 Paul E. McKenney 2019-01-11 452 * triggering hard lockup.
59b73a27681c58 Paul E. McKenney 2019-01-11 453 */
59b73a27681c58 Paul E. McKenney 2019-01-11 454 touch_nmi_watchdog();
59b73a27681c58 Paul E. McKenney 2019-01-11 455
59b73a27681c58 Paul E. McKenney 2019-01-11 456 ticks_value = rcu_seq_ctr(rcu_state.gp_seq - rdp->gp_seq);
59b73a27681c58 Paul E. McKenney 2019-01-11 457 if (ticks_value) {
59b73a27681c58 Paul E. McKenney 2019-01-11 458 ticks_title = "GPs behind";
59b73a27681c58 Paul E. McKenney 2019-01-11 459 } else {
59b73a27681c58 Paul E. McKenney 2019-01-11 460 ticks_title = "ticks this GP";
59b73a27681c58 Paul E. McKenney 2019-01-11 461 ticks_value = rdp->ticks_this_gp;
59b73a27681c58 Paul E. McKenney 2019-01-11 462 }
59b73a27681c58 Paul E. McKenney 2019-01-11 463 delta = rcu_seq_ctr(rdp->mynode->gp_seq - rdp->rcu_iw_gp_seq);
88375825171c7d Paul E. McKenney 2020-03-31 464 falsepositive = rcu_is_gp_kthread_starving(NULL) &&
88375825171c7d Paul E. McKenney 2020-03-31 465 rcu_dynticks_in_eqs(rcu_dynticks_snap(rdp));
17d9de741a1aaf Zqiang 2022-04-24 466 rcuc_starved = rcu_is_rcuc_kthread_starving(rdp, &j);
That tree has some new returns in rcu_is_rcuc_kthread_starving() where
*jp is not set.
17d9de741a1aaf Zqiang 2022-04-24 @467 pr_err("\t%d-%c%c%c%c: (%lu %s) idle=%03x/%ld/%#lx softirq=%u/%u fqs=%ld rcuc=%ld jiffies(%s) %s\n",
59b73a27681c58 Paul E. McKenney 2019-01-11 468 cpu,
59b73a27681c58 Paul E. McKenney 2019-01-11 469 "O."[!!cpu_online(cpu)],
59b73a27681c58 Paul E. McKenney 2019-01-11 470 "o."[!!(rdp->grpmask & rdp->mynode->qsmaskinit)],
59b73a27681c58 Paul E. McKenney 2019-01-11 471 "N."[!!(rdp->grpmask & rdp->mynode->qsmaskinitnext)],
59b73a27681c58 Paul E. McKenney 2019-01-11 472 !IS_ENABLED(CONFIG_IRQ_WORK) ? '?' :
59b73a27681c58 Paul E. McKenney 2019-01-11 473 rdp->rcu_iw_pending ? (int)min(delta, 9UL) + '0' :
59b73a27681c58 Paul E. McKenney 2019-01-11 474 "!."[!delta],
59b73a27681c58 Paul E. McKenney 2019-01-11 475 ticks_value, ticks_title,
59b73a27681c58 Paul E. McKenney 2019-01-11 476 rcu_dynticks_snap(rdp) & 0xfff,
59b73a27681c58 Paul E. McKenney 2019-01-11 477 rdp->dynticks_nesting, rdp->dynticks_nmi_nesting,
59b73a27681c58 Paul E. McKenney 2019-01-11 478 rdp->softirq_snap, kstat_softirqs_cpu(RCU_SOFTIRQ, cpu),
88375825171c7d Paul E. McKenney 2020-03-31 479 data_race(rcu_state.n_force_qs) - rcu_state.n_force_qs_gpstart,
17d9de741a1aaf Zqiang 2022-04-24 480 j, rcuc_starved ? "starved" : "",
88375825171c7d Paul E. McKenney 2020-03-31 481 falsepositive ? " (false positive?)" : "");
59b73a27681c58 Paul E. McKenney 2019-01-11 482 }
--
0-DAY CI Kernel Test Service
https://01.org/lkp