rcu: Add RCU stall diagnosis information

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 <[email protected]>

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;
 
 	long lazy_len;			/* Length of buffered lazy callbacks. */
 	int cpu;

kernel/rcu/tree_stall.h

@@ -211,8 +211,10 @@ static void rcu_stall_kick_kthreads(void)
  */
 static void rcu_iw_handler(struct irq_work *iwp)
 {
+	int cpu = smp_processor_id();
 	struct rcu_data *rdp;
 	struct rcu_node *rnp;
+	struct rcu_snap_record *r;
 
 	rdp = container_of(iwp, struct rcu_data, rcu_iw);
 	rnp = rdp->mynode;
@@ -222,6 +224,16 @@ static void rcu_iw_handler(struct irq_work *iwp)
 		rdp->rcu_iw_pending = false;
 	}
 	raw_spin_unlock_rcu_node(rnp);
+
+	r = &rdp->snap_record;
+	r->cputime_irq     = kcpustat_this_cpu->cpustat[CPUTIME_IRQ];
+	r->cputime_softirq = kcpustat_this_cpu->cpustat[CPUTIME_SOFTIRQ];
+	r->cputime_system  = kcpustat_this_cpu->cpustat[CPUTIME_SYSTEM];
+	r->nr_hardirqs = kstat_cpu_irqs_sum(cpu);
+	r->nr_softirqs = kstat_cpu_softirqs_sum(cpu);
+	r->nr_csw = nr_context_switches_cpu(cpu);
+	barrier();
+	r->gp_seq = rdp->gp_seq;
 }
 
 //////////////////////////////////////////////////////////////////////////////
@@ -428,6 +440,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_this_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 +522,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.  */