| Message ID | 20221022124525.2080-4-thunder.leizhen@huawei.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | rcu: Add RCU stall diagnosis information | expand |
On Sat, Oct 22, 2022 at 08:45:25PM +0800, Zhen Lei wrote: > In some extreme cases, such as the I/O pressure test, the CPU usage may > be 100%, causing RCU stall. In this case, the printed information about > current is not useful. Displays the number and usage of hard interrupts, > soft interrupts, and context switches that are generated within half of > the CPU stall timeout, can help us make a general judgment. In other > cases, we can preliminarily determine whether an infinite loop occurs > when local_irq, local_bh or preempt is disabled. > > For example: > rcu: INFO: rcu_preempt self-detected stall on CPU > rcu: 0-....: (1250 ticks this GP) <omitted> > rcu: hardirqs softirqs csw/system > rcu: number: 624 45 0 > rcu: cputime: 69 1 2425 ==> 2500(ms) > > The example above shows that the number of hard and soft interrupts is > small, there is zero context switching, and the system takes up a lot of > time. We can quickly conclude that the current task is infinitely looped > with preempt_disable(). > > The impact on system performance is negligible because snapshot is > recorded only one time after 1/2 CPU stall timeout. > > Signed-off-by: Zhen Lei <thunder.leizhen@huawei.com> > --- > kernel/rcu/tree.c | 16 ++++++++++++++++ > kernel/rcu/tree.h | 11 +++++++++++ > kernel/rcu/tree_stall.h | 28 ++++++++++++++++++++++++++++ > 3 files changed, 55 insertions(+) > > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c > index 6bb8e72bc8151ef..56c49a3117e7a81 100644 > --- a/kernel/rcu/tree.c > +++ b/kernel/rcu/tree.c > @@ -931,6 +931,22 @@ static int rcu_implicit_dynticks_qs(struct rcu_data *rdp) > rdp->rcu_iw_gp_seq = rnp->gp_seq; > irq_work_queue_on(&rdp->rcu_iw, rdp->cpu); > } > + > + if (rdp->snap_record.gp_seq != rdp->gp_seq) { > + u64 *cpustat; > + struct rcu_snap_record *r; > + > + cpustat = kcpustat_cpu(rdp->cpu).cpustat; > + > + r = &rdp->snap_record; > + r->cputime_irq = cpustat[CPUTIME_IRQ]; > + r->cputime_softirq = cpustat[CPUTIME_SOFTIRQ]; > + r->cputime_system = cpustat[CPUTIME_SYSTEM]; > + r->nr_hardirqs = kstat_cpu_irqs_sum(rdp->cpu); > + r->nr_softirqs = kstat_cpu_softirqs_sum(rdp->cpu); > + r->nr_csw = nr_context_switches_cpu(rdp->cpu); > + r->gp_seq = rdp->gp_seq; This needs to be optional. Yes, it is normally rarely executed, but people who don't want the additional information should not pay the price for it. > + } > } > > return 0; > diff --git a/kernel/rcu/tree.h b/kernel/rcu/tree.h > index d4a97e40ea9c3e2..fb3121d15cca6f8 100644 > --- a/kernel/rcu/tree.h > +++ b/kernel/rcu/tree.h > @@ -158,6 +158,16 @@ union rcu_noqs { > u16 s; /* Set of bits, aggregate OR here. */ > }; > > +struct rcu_snap_record { > + unsigned long gp_seq; > + u64 cputime_irq; > + u64 cputime_softirq; > + u64 cputime_system; > + unsigned int nr_hardirqs; > + unsigned int nr_softirqs; > + unsigned long long nr_csw; > +}; Please add a comment saying what this is and what it is used for. > + > /* Per-CPU data for read-copy update. */ > struct rcu_data { > /* 1) quiescent-state and grace-period handling : */ > @@ -262,6 +272,7 @@ struct rcu_data { > short rcu_onl_gp_flags; /* ->gp_flags at last online. */ > unsigned long last_fqs_resched; /* Time of last rcu_resched(). */ > unsigned long last_sched_clock; /* Jiffies of last rcu_sched_clock_irq(). */ > + struct rcu_snap_record snap_record; And here as well, please. > int cpu; > }; > diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h > index 5653560573e22d6..f8c9d0284d116a8 100644 > --- a/kernel/rcu/tree_stall.h > +++ b/kernel/rcu/tree_stall.h > @@ -428,6 +428,32 @@ static bool rcu_is_rcuc_kthread_starving(struct rcu_data *rdp, unsigned long *jp > return j > 2 * HZ; > } > > +static void print_cpu_stat_info(int cpu) > +{ > + u64 *cpustat; > + unsigned long half_timeout; > + struct rcu_snap_record *r; Let's please follow convention and call it "rsrp" rather than just "r". > + struct rcu_data *rdp = per_cpu_ptr(&rcu_data, cpu); > + > + r = &rdp->snap_record; > + if (r->gp_seq != rdp->gp_seq) > + return; > + > + cpustat = kcpustat_cpu(cpu).cpustat; > + half_timeout = rcu_jiffies_till_stall_check() / 2; > + > + pr_err(" hardirqs softirqs csw/system\n"); > + pr_err(" number: %8d %10d %12lld\n", > + kstat_cpu_irqs_sum(cpu) - r->nr_hardirqs, > + kstat_cpu_softirqs_sum(cpu) - r->nr_softirqs, > + nr_context_switches_cpu(cpu) - r->nr_csw); > + pr_err("cputime: %8lld %10lld %12lld ==> %lld(ms)\n", > + div_u64(cpustat[CPUTIME_IRQ] - r->cputime_irq, NSEC_PER_MSEC), > + div_u64(cpustat[CPUTIME_SOFTIRQ] - r->cputime_softirq, NSEC_PER_MSEC), > + div_u64(cpustat[CPUTIME_SYSTEM] - r->cputime_system, NSEC_PER_MSEC), > + jiffies64_to_msecs(half_timeout)); > +} > + > /* > * Print out diagnostic information for the specified stalled CPU. > * > @@ -484,6 +510,8 @@ static void print_cpu_stall_info(int cpu) > data_race(rcu_state.n_force_qs) - rcu_state.n_force_qs_gpstart, > rcuc_starved ? buf : "", > falsepositive ? " (false positive?)" : ""); > + > + print_cpu_stat_info(cpu); Again, please make this conditional. One way to do that is with a Kconfig option. Another is with a kernel boot parameter, as is done wtih module_param() elsewhere in tree_stall.h. Or if the parsing needs to be fancy (it shouldn't) using kernel_param_ops as is done in tree.c. Distros tend to like kernel boot parameters, while people dealing with large numbers of devices tend to like Kconfig options. Choose wisely. ;-) Please make this initially default-off. If enough people enable it for long enough, we can later switch it to default-on and maybe even later to unconditional. But let's start carefully. Thanx, Paul > } > > /* Complain about starvation of grace-period kthread. */ > -- > 2.25.1 >
On 2022/10/28 1:33, Paul E. McKenney wrote: > On Sat, Oct 22, 2022 at 08:45:25PM +0800, Zhen Lei wrote: >> In some extreme cases, such as the I/O pressure test, the CPU usage may >> be 100%, causing RCU stall. In this case, the printed information about >> current is not useful. Displays the number and usage of hard interrupts, >> soft interrupts, and context switches that are generated within half of >> the CPU stall timeout, can help us make a general judgment. In other >> cases, we can preliminarily determine whether an infinite loop occurs >> when local_irq, local_bh or preempt is disabled. >> >> For example: >> rcu: INFO: rcu_preempt self-detected stall on CPU >> rcu: 0-....: (1250 ticks this GP) <omitted> >> rcu: hardirqs softirqs csw/system >> rcu: number: 624 45 0 >> rcu: cputime: 69 1 2425 ==> 2500(ms) >> >> The example above shows that the number of hard and soft interrupts is >> small, there is zero context switching, and the system takes up a lot of >> time. We can quickly conclude that the current task is infinitely looped >> with preempt_disable(). >> >> The impact on system performance is negligible because snapshot is >> recorded only one time after 1/2 CPU stall timeout. >> >> Signed-off-by: Zhen Lei <thunder.leizhen@huawei.com> >> --- >> kernel/rcu/tree.c | 16 ++++++++++++++++ >> kernel/rcu/tree.h | 11 +++++++++++ >> kernel/rcu/tree_stall.h | 28 ++++++++++++++++++++++++++++ >> 3 files changed, 55 insertions(+) >> >> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c >> index 6bb8e72bc8151ef..56c49a3117e7a81 100644 >> --- a/kernel/rcu/tree.c >> +++ b/kernel/rcu/tree.c >> @@ -931,6 +931,22 @@ static int rcu_implicit_dynticks_qs(struct rcu_data *rdp) >> rdp->rcu_iw_gp_seq = rnp->gp_seq; >> irq_work_queue_on(&rdp->rcu_iw, rdp->cpu); >> } >> + >> + if (rdp->snap_record.gp_seq != rdp->gp_seq) { >> + u64 *cpustat; >> + struct rcu_snap_record *r; >> + >> + cpustat = kcpustat_cpu(rdp->cpu).cpustat; >> + >> + r = &rdp->snap_record; >> + r->cputime_irq = cpustat[CPUTIME_IRQ]; >> + r->cputime_softirq = cpustat[CPUTIME_SOFTIRQ]; >> + r->cputime_system = cpustat[CPUTIME_SYSTEM]; >> + r->nr_hardirqs = kstat_cpu_irqs_sum(rdp->cpu); >> + r->nr_softirqs = kstat_cpu_softirqs_sum(rdp->cpu); >> + r->nr_csw = nr_context_switches_cpu(rdp->cpu); >> + r->gp_seq = rdp->gp_seq; > > This needs to be optional. Yes, it is normally rarely executed, but > people who don't want the additional information should not pay the > price for it. > >> + } >> } >> >> return 0; >> diff --git a/kernel/rcu/tree.h b/kernel/rcu/tree.h >> index d4a97e40ea9c3e2..fb3121d15cca6f8 100644 >> --- a/kernel/rcu/tree.h >> +++ b/kernel/rcu/tree.h >> @@ -158,6 +158,16 @@ union rcu_noqs { >> u16 s; /* Set of bits, aggregate OR here. */ >> }; >> >> +struct rcu_snap_record { >> + unsigned long gp_seq; >> + u64 cputime_irq; >> + u64 cputime_softirq; >> + u64 cputime_system; >> + unsigned int nr_hardirqs; >> + unsigned int nr_softirqs; >> + unsigned long long nr_csw; >> +}; > > Please add a comment saying what this is and what it is used for. OK, I will do it. > >> + >> /* Per-CPU data for read-copy update. */ >> struct rcu_data { >> /* 1) quiescent-state and grace-period handling : */ >> @@ -262,6 +272,7 @@ struct rcu_data { >> short rcu_onl_gp_flags; /* ->gp_flags at last online. */ >> unsigned long last_fqs_resched; /* Time of last rcu_resched(). */ >> unsigned long last_sched_clock; /* Jiffies of last rcu_sched_clock_irq(). */ >> + struct rcu_snap_record snap_record; > > And here as well, please. OK > >> int cpu; >> }; >> diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h >> index 5653560573e22d6..f8c9d0284d116a8 100644 >> --- a/kernel/rcu/tree_stall.h >> +++ b/kernel/rcu/tree_stall.h >> @@ -428,6 +428,32 @@ static bool rcu_is_rcuc_kthread_starving(struct rcu_data *rdp, unsigned long *jp >> return j > 2 * HZ; >> } >> >> +static void print_cpu_stat_info(int cpu) >> +{ >> + u64 *cpustat; >> + unsigned long half_timeout; >> + struct rcu_snap_record *r; > > Let's please follow convention and call it "rsrp" rather than just "r". OK > >> + struct rcu_data *rdp = per_cpu_ptr(&rcu_data, cpu); >> + >> + r = &rdp->snap_record; >> + if (r->gp_seq != rdp->gp_seq) >> + return; >> + >> + cpustat = kcpustat_cpu(cpu).cpustat; >> + half_timeout = rcu_jiffies_till_stall_check() / 2; >> + >> + pr_err(" hardirqs softirqs csw/system\n"); >> + pr_err(" number: %8d %10d %12lld\n", >> + kstat_cpu_irqs_sum(cpu) - r->nr_hardirqs, >> + kstat_cpu_softirqs_sum(cpu) - r->nr_softirqs, >> + nr_context_switches_cpu(cpu) - r->nr_csw); >> + pr_err("cputime: %8lld %10lld %12lld ==> %lld(ms)\n", >> + div_u64(cpustat[CPUTIME_IRQ] - r->cputime_irq, NSEC_PER_MSEC), >> + div_u64(cpustat[CPUTIME_SOFTIRQ] - r->cputime_softirq, NSEC_PER_MSEC), >> + div_u64(cpustat[CPUTIME_SYSTEM] - r->cputime_system, NSEC_PER_MSEC), >> + jiffies64_to_msecs(half_timeout)); >> +} >> + >> /* >> * Print out diagnostic information for the specified stalled CPU. >> * >> @@ -484,6 +510,8 @@ static void print_cpu_stall_info(int cpu) >> data_race(rcu_state.n_force_qs) - rcu_state.n_force_qs_gpstart, >> rcuc_starved ? buf : "", >> falsepositive ? " (false positive?)" : ""); >> + >> + print_cpu_stat_info(cpu); > > Again, please make this conditional. One way to do that is with a > Kconfig option. Another is with a kernel boot parameter, as is done > wtih module_param() elsewhere in tree_stall.h. Or if the parsing needs > to be fancy (it shouldn't) using kernel_param_ops as is done in tree.c. > Distros tend to like kernel boot parameters, while people dealing with > large numbers of devices tend to like Kconfig options. Choose wisely. ;-) OK. I will add both Kconfig option and boot parameter, let the user choose freely. > > Please make this initially default-off. If enough people enable it for > long enough, we can later switch it to default-on and maybe even later > to unconditional. But let's start carefully. Right. You're so far-sighted. > > Thanx, Paul > >> } >> >> /* Complain about starvation of grace-period kthread. */ >> -- >> 2.25.1 >> > . >
On Fri, Oct 28, 2022 at 11:16:55AM +0800, Leizhen (ThunderTown) wrote: > > > On 2022/10/28 1:33, Paul E. McKenney wrote: > > On Sat, Oct 22, 2022 at 08:45:25PM +0800, Zhen Lei wrote: > >> In some extreme cases, such as the I/O pressure test, the CPU usage may > >> be 100%, causing RCU stall. In this case, the printed information about > >> current is not useful. Displays the number and usage of hard interrupts, > >> soft interrupts, and context switches that are generated within half of > >> the CPU stall timeout, can help us make a general judgment. In other > >> cases, we can preliminarily determine whether an infinite loop occurs > >> when local_irq, local_bh or preempt is disabled. > >> > >> For example: > >> rcu: INFO: rcu_preempt self-detected stall on CPU > >> rcu: 0-....: (1250 ticks this GP) <omitted> > >> rcu: hardirqs softirqs csw/system > >> rcu: number: 624 45 0 > >> rcu: cputime: 69 1 2425 ==> 2500(ms) > >> > >> The example above shows that the number of hard and soft interrupts is > >> small, there is zero context switching, and the system takes up a lot of > >> time. We can quickly conclude that the current task is infinitely looped > >> with preempt_disable(). > >> > >> The impact on system performance is negligible because snapshot is > >> recorded only one time after 1/2 CPU stall timeout. > >> > >> Signed-off-by: Zhen Lei <thunder.leizhen@huawei.com> > >> --- > >> kernel/rcu/tree.c | 16 ++++++++++++++++ > >> kernel/rcu/tree.h | 11 +++++++++++ > >> kernel/rcu/tree_stall.h | 28 ++++++++++++++++++++++++++++ > >> 3 files changed, 55 insertions(+) > >> > >> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c > >> index 6bb8e72bc8151ef..56c49a3117e7a81 100644 > >> --- a/kernel/rcu/tree.c > >> +++ b/kernel/rcu/tree.c > >> @@ -931,6 +931,22 @@ static int rcu_implicit_dynticks_qs(struct rcu_data *rdp) > >> rdp->rcu_iw_gp_seq = rnp->gp_seq; > >> irq_work_queue_on(&rdp->rcu_iw, rdp->cpu); > >> } > >> + > >> + if (rdp->snap_record.gp_seq != rdp->gp_seq) { > >> + u64 *cpustat; > >> + struct rcu_snap_record *r; > >> + > >> + cpustat = kcpustat_cpu(rdp->cpu).cpustat; > >> + > >> + r = &rdp->snap_record; > >> + r->cputime_irq = cpustat[CPUTIME_IRQ]; > >> + r->cputime_softirq = cpustat[CPUTIME_SOFTIRQ]; > >> + r->cputime_system = cpustat[CPUTIME_SYSTEM]; > >> + r->nr_hardirqs = kstat_cpu_irqs_sum(rdp->cpu); > >> + r->nr_softirqs = kstat_cpu_softirqs_sum(rdp->cpu); > >> + r->nr_csw = nr_context_switches_cpu(rdp->cpu); > >> + r->gp_seq = rdp->gp_seq; > > > > This needs to be optional. Yes, it is normally rarely executed, but > > people who don't want the additional information should not pay the > > price for it. > > > >> + } > >> } > >> > >> return 0; > >> diff --git a/kernel/rcu/tree.h b/kernel/rcu/tree.h > >> index d4a97e40ea9c3e2..fb3121d15cca6f8 100644 > >> --- a/kernel/rcu/tree.h > >> +++ b/kernel/rcu/tree.h > >> @@ -158,6 +158,16 @@ union rcu_noqs { > >> u16 s; /* Set of bits, aggregate OR here. */ > >> }; > >> > >> +struct rcu_snap_record { > >> + unsigned long gp_seq; > >> + u64 cputime_irq; > >> + u64 cputime_softirq; > >> + u64 cputime_system; > >> + unsigned int nr_hardirqs; > >> + unsigned int nr_softirqs; > >> + unsigned long long nr_csw; > >> +}; > > > > Please add a comment saying what this is and what it is used for. > > OK, I will do it. > > > > >> + > >> /* Per-CPU data for read-copy update. */ > >> struct rcu_data { > >> /* 1) quiescent-state and grace-period handling : */ > >> @@ -262,6 +272,7 @@ struct rcu_data { > >> short rcu_onl_gp_flags; /* ->gp_flags at last online. */ > >> unsigned long last_fqs_resched; /* Time of last rcu_resched(). */ > >> unsigned long last_sched_clock; /* Jiffies of last rcu_sched_clock_irq(). */ > >> + struct rcu_snap_record snap_record; > > > > And here as well, please. > > OK > > > > >> int cpu; > >> }; > >> diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h > >> index 5653560573e22d6..f8c9d0284d116a8 100644 > >> --- a/kernel/rcu/tree_stall.h > >> +++ b/kernel/rcu/tree_stall.h > >> @@ -428,6 +428,32 @@ static bool rcu_is_rcuc_kthread_starving(struct rcu_data *rdp, unsigned long *jp > >> return j > 2 * HZ; > >> } > >> > >> +static void print_cpu_stat_info(int cpu) > >> +{ > >> + u64 *cpustat; > >> + unsigned long half_timeout; > >> + struct rcu_snap_record *r; > > > > Let's please follow convention and call it "rsrp" rather than just "r". > > OK > > > > >> + struct rcu_data *rdp = per_cpu_ptr(&rcu_data, cpu); > >> + > >> + r = &rdp->snap_record; > >> + if (r->gp_seq != rdp->gp_seq) > >> + return; > >> + > >> + cpustat = kcpustat_cpu(cpu).cpustat; > >> + half_timeout = rcu_jiffies_till_stall_check() / 2; > >> + > >> + pr_err(" hardirqs softirqs csw/system\n"); > >> + pr_err(" number: %8d %10d %12lld\n", > >> + kstat_cpu_irqs_sum(cpu) - r->nr_hardirqs, > >> + kstat_cpu_softirqs_sum(cpu) - r->nr_softirqs, > >> + nr_context_switches_cpu(cpu) - r->nr_csw); > >> + pr_err("cputime: %8lld %10lld %12lld ==> %lld(ms)\n", > >> + div_u64(cpustat[CPUTIME_IRQ] - r->cputime_irq, NSEC_PER_MSEC), > >> + div_u64(cpustat[CPUTIME_SOFTIRQ] - r->cputime_softirq, NSEC_PER_MSEC), > >> + div_u64(cpustat[CPUTIME_SYSTEM] - r->cputime_system, NSEC_PER_MSEC), > >> + jiffies64_to_msecs(half_timeout)); > >> +} > >> + > >> /* > >> * Print out diagnostic information for the specified stalled CPU. > >> * > >> @@ -484,6 +510,8 @@ static void print_cpu_stall_info(int cpu) > >> data_race(rcu_state.n_force_qs) - rcu_state.n_force_qs_gpstart, > >> rcuc_starved ? buf : "", > >> falsepositive ? " (false positive?)" : ""); > >> + > >> + print_cpu_stat_info(cpu); > > > > Again, please make this conditional. One way to do that is with a > > Kconfig option. Another is with a kernel boot parameter, as is done > > wtih module_param() elsewhere in tree_stall.h. Or if the parsing needs > > to be fancy (it shouldn't) using kernel_param_ops as is done in tree.c. > > Distros tend to like kernel boot parameters, while people dealing with > > large numbers of devices tend to like Kconfig options. Choose wisely. ;-) > > OK. I will add both Kconfig option and boot parameter, let the user > choose freely. Works for me! ;-) Thanx, Paul
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c index 6bb8e72bc8151ef..56c49a3117e7a81 100644 --- a/kernel/rcu/tree.c +++ b/kernel/rcu/tree.c @@ -931,6 +931,22 @@ static int rcu_implicit_dynticks_qs(struct rcu_data *rdp) rdp->rcu_iw_gp_seq = rnp->gp_seq; irq_work_queue_on(&rdp->rcu_iw, rdp->cpu); } + + if (rdp->snap_record.gp_seq != rdp->gp_seq) { + u64 *cpustat; + struct rcu_snap_record *r; + + cpustat = kcpustat_cpu(rdp->cpu).cpustat; + + r = &rdp->snap_record; + r->cputime_irq = cpustat[CPUTIME_IRQ]; + r->cputime_softirq = cpustat[CPUTIME_SOFTIRQ]; + r->cputime_system = cpustat[CPUTIME_SYSTEM]; + r->nr_hardirqs = kstat_cpu_irqs_sum(rdp->cpu); + r->nr_softirqs = kstat_cpu_softirqs_sum(rdp->cpu); + r->nr_csw = nr_context_switches_cpu(rdp->cpu); + r->gp_seq = rdp->gp_seq; + } } return 0; diff --git a/kernel/rcu/tree.h b/kernel/rcu/tree.h index d4a97e40ea9c3e2..fb3121d15cca6f8 100644 --- a/kernel/rcu/tree.h +++ b/kernel/rcu/tree.h @@ -158,6 +158,16 @@ union rcu_noqs { u16 s; /* Set of bits, aggregate OR here. */ }; +struct rcu_snap_record { + unsigned long gp_seq; + u64 cputime_irq; + u64 cputime_softirq; + u64 cputime_system; + unsigned int nr_hardirqs; + unsigned int nr_softirqs; + unsigned long long nr_csw; +}; + /* Per-CPU data for read-copy update. */ struct rcu_data { /* 1) quiescent-state and grace-period handling : */ @@ -262,6 +272,7 @@ struct rcu_data { short rcu_onl_gp_flags; /* ->gp_flags at last online. */ unsigned long last_fqs_resched; /* Time of last rcu_resched(). */ unsigned long last_sched_clock; /* Jiffies of last rcu_sched_clock_irq(). */ + struct rcu_snap_record snap_record; int cpu; }; diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h index 5653560573e22d6..f8c9d0284d116a8 100644 --- a/kernel/rcu/tree_stall.h +++ b/kernel/rcu/tree_stall.h @@ -428,6 +428,32 @@ static bool rcu_is_rcuc_kthread_starving(struct rcu_data *rdp, unsigned long *jp return j > 2 * HZ; } +static void print_cpu_stat_info(int cpu) +{ + u64 *cpustat; + unsigned long half_timeout; + struct rcu_snap_record *r; + struct rcu_data *rdp = per_cpu_ptr(&rcu_data, cpu); + + r = &rdp->snap_record; + if (r->gp_seq != rdp->gp_seq) + return; + + cpustat = kcpustat_cpu(cpu).cpustat; + half_timeout = rcu_jiffies_till_stall_check() / 2; + + pr_err(" hardirqs softirqs csw/system\n"); + pr_err(" number: %8d %10d %12lld\n", + kstat_cpu_irqs_sum(cpu) - r->nr_hardirqs, + kstat_cpu_softirqs_sum(cpu) - r->nr_softirqs, + nr_context_switches_cpu(cpu) - r->nr_csw); + pr_err("cputime: %8lld %10lld %12lld ==> %lld(ms)\n", + div_u64(cpustat[CPUTIME_IRQ] - r->cputime_irq, NSEC_PER_MSEC), + div_u64(cpustat[CPUTIME_SOFTIRQ] - r->cputime_softirq, NSEC_PER_MSEC), + div_u64(cpustat[CPUTIME_SYSTEM] - r->cputime_system, NSEC_PER_MSEC), + jiffies64_to_msecs(half_timeout)); +} + /* * Print out diagnostic information for the specified stalled CPU. * @@ -484,6 +510,8 @@ static void print_cpu_stall_info(int cpu) data_race(rcu_state.n_force_qs) - rcu_state.n_force_qs_gpstart, rcuc_starved ? buf : "", falsepositive ? " (false positive?)" : ""); + + print_cpu_stat_info(cpu); } /* Complain about starvation of grace-period kthread. */
In some extreme cases, such as the I/O pressure test, the CPU usage may be 100%, causing RCU stall. In this case, the printed information about current is not useful. Displays the number and usage of hard interrupts, soft interrupts, and context switches that are generated within half of the CPU stall timeout, can help us make a general judgment. In other cases, we can preliminarily determine whether an infinite loop occurs when local_irq, local_bh or preempt is disabled. For example: rcu: INFO: rcu_preempt self-detected stall on CPU rcu: 0-....: (1250 ticks this GP) <omitted> rcu: hardirqs softirqs csw/system rcu: number: 624 45 0 rcu: cputime: 69 1 2425 ==> 2500(ms) The example above shows that the number of hard and soft interrupts is small, there is zero context switching, and the system takes up a lot of time. We can quickly conclude that the current task is infinitely looped with preempt_disable(). The impact on system performance is negligible because snapshot is recorded only one time after 1/2 CPU stall timeout. Signed-off-by: Zhen Lei <thunder.leizhen@huawei.com> --- kernel/rcu/tree.c | 16 ++++++++++++++++ kernel/rcu/tree.h | 11 +++++++++++ kernel/rcu/tree_stall.h | 28 ++++++++++++++++++++++++++++ 3 files changed, 55 insertions(+)