When the watchdog determines that the current soft lockup is due
to an interrupt storm based on CPU utilization, reporting the
most frequent interrupts could be good enough for further
troubleshooting.

Below is an example of interrupt storm. The call tree does not
provide useful information, but we can analyze which interrupt
caused the soft lockup by comparing the counts of interrupts.

[ 2987.488075] watchdog: BUG: soft lockup - CPU#9 stuck for 23s! [kworker/9:1:214]
[ 2987.488607] CPU#9 Utilization every 4s during lockup:
[ 2987.488941]  #1:   0% system,          0% softirq,   100% hardirq,     0% idle
[ 2987.489357]  #2:   0% system,          0% softirq,   100% hardirq,     0% idle
[ 2987.489771]  #3:   0% system,          0% softirq,   100% hardirq,     0% idle
[ 2987.490186]  #4:   0% system,          0% softirq,   100% hardirq,     0% idle
[ 2987.490601]  #5:   0% system,          0% softirq,   100% hardirq,     0% idle
[ 2987.491034] CPU#9 Detect HardIRQ Time exceeds 50%. Most frequent HardIRQs:
[ 2987.491493]  #1: 330985      irq#7(IPI)
[ 2987.491743]  #2: 5000        irq#10(arch_timer)
[ 2987.492039]  #3: 9           irq#91(nvme0q2)
[ 2987.492318]  #4: 3           irq#118(virtio1-output.12)
...
[ 2987.492728] Call trace:
[ 2987.492729]  __do_softirq+0xa8/0x364

Signed-off-by: Bitao Hu <yaoma@linux.alibaba.com>
---
 kernel/watchdog.c | 153 ++++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 149 insertions(+), 4 deletions(-)

diff --git a/kernel/watchdog.c b/kernel/watchdog.c
index 380b60074f1d..e9e98ce5ff40 100644
--- a/kernel/watchdog.c
+++ b/kernel/watchdog.c
@@ -12,22 +12,25 @@
 
 #define pr_fmt(fmt) "watchdog: " fmt
 
-#include <linux/mm.h>
 #include <linux/cpu.h>
-#include <linux/nmi.h>
 #include <linux/init.h>
+#include <linux/irq.h>
+#include <linux/irqdesc.h>
 #include <linux/kernel_stat.h>
+#include <linux/kvm_para.h>
 #include <linux/math64.h>
+#include <linux/mm.h>
 #include <linux/module.h>
+#include <linux/nmi.h>
+#include <linux/stop_machine.h>
 #include <linux/sysctl.h>
 #include <linux/tick.h>
+
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/isolation.h>
-#include <linux/stop_machine.h>
 
 #include <asm/irq_regs.h>
-#include <linux/kvm_para.h>
 
 static DEFINE_MUTEX(watchdog_mutex);
 
@@ -412,13 +415,142 @@ static void print_cpustat(void)
 	}
 }
 
+#define HARDIRQ_PERCENT_THRESH		50
+#define NUM_HARDIRQ_REPORT		5
+static DEFINE_PER_CPU(u32 *, hardirq_counts);
+static DEFINE_PER_CPU(int, actual_nr_irqs);
+struct irq_counts {
+	int irq;
+	u32 counts;
+};
+
+/* Tabulate the most frequent interrupts. */
+static void tabulate_irq_count(struct irq_counts *irq_counts, int irq, u32 counts, int rank)
+{
+	int i;
+	struct irq_counts new_count = {irq, counts};
+
+	for (i = 0; i < rank; i++) {
+		if (counts > irq_counts[i].counts)
+			swap(new_count, irq_counts[i]);
+	}
+}
+
+/*
+ * If the hardirq time exceeds HARDIRQ_PERCENT_THRESH% of the sample_period,
+ * then the cause of softlockup might be interrupt storm. In this case, it
+ * would be useful to start interrupt counting.
+ */
+static bool need_counting_irqs(void)
+{
+	u8 util;
+	int tail = __this_cpu_read(cpustat_tail);
+
+	tail = (tail + NUM_HARDIRQ_REPORT - 1) % NUM_HARDIRQ_REPORT;
+	util = __this_cpu_read(cpustat_util[tail][STATS_HARDIRQ]);
+	return util > HARDIRQ_PERCENT_THRESH;
+}
+
+static void start_counting_irqs(void)
+{
+	int i;
+	int local_nr_irqs;
+	struct irq_desc *desc;
+	u32 *counts = __this_cpu_read(hardirq_counts);
+
+	if (!counts) {
+		/*
+		 * nr_irqs has the potential to grow at runtime. We should read
+		 * it and store locally to avoid array out-of-bounds access.
+		 */
+		local_nr_irqs = READ_ONCE(nr_irqs);
+		counts = kcalloc(local_nr_irqs, sizeof(u32), GFP_ATOMIC);
+		if (!counts)
+			return;
+		for (i = 0; i < local_nr_irqs; i++) {
+			desc = irq_to_desc(i);
+			if (!desc)
+				continue;
+			counts[i] = desc->kstat_irqs ?
+				*this_cpu_ptr(desc->kstat_irqs) : 0;
+		}
+		__this_cpu_write(actual_nr_irqs, local_nr_irqs);
+		__this_cpu_write(hardirq_counts, counts);
+	}
+}
+
+static void stop_counting_irqs(void)
+{
+	kfree(__this_cpu_read(hardirq_counts));
+	__this_cpu_write(hardirq_counts, NULL);
+}
+
+static void print_irq_counts(void)
+{
+	int i;
+	struct irq_desc *desc;
+	u32 counts_diff;
+	int local_nr_irqs = __this_cpu_read(actual_nr_irqs);
+	u32 *counts = __this_cpu_read(hardirq_counts);
+	struct irq_counts irq_counts_sorted[NUM_HARDIRQ_REPORT] = {
+		{-1, 0}, {-1, 0}, {-1, 0}, {-1, 0},
+	};
+
+	if (counts) {
+		for_each_irq_desc(i, desc) {
+			/*
+			 * We need to bounds-check in case someone on a different CPU
+			 * expanded nr_irqs.
+			 */
+			if (desc->kstat_irqs) {
+				counts_diff = *this_cpu_ptr(desc->kstat_irqs);
+				if (i < local_nr_irqs)
+					counts_diff -= counts[i];
+			} else {
+				counts_diff = 0;
+			}
+			tabulate_irq_count(irq_counts_sorted, i, counts_diff,
+					   NUM_HARDIRQ_REPORT);
+		}
+		/*
+		 * We do not want the "watchdog: " prefix on every line,
+		 * hence we use "printk" instead of "pr_crit".
+		 */
+		printk(KERN_CRIT "CPU#%d Detect HardIRQ Time exceeds %d%%. Most frequent HardIRQs:\n",
+		       smp_processor_id(), HARDIRQ_PERCENT_THRESH);
+		for (i = 0; i < NUM_HARDIRQ_REPORT; i++) {
+			if (irq_counts_sorted[i].irq == -1)
+				break;
+			desc = irq_to_desc(irq_counts_sorted[i].irq);
+			if (desc && desc->action)
+				printk(KERN_CRIT "\t#%u: %-10u\tirq#%d(%s)\n",
+				       i + 1, irq_counts_sorted[i].counts,
+				       irq_counts_sorted[i].irq, desc->action->name);
+			else
+				printk(KERN_CRIT "\t#%u: %-10u\tirq#%d\n",
+				       i + 1, irq_counts_sorted[i].counts,
+				       irq_counts_sorted[i].irq);
+		}
+		/*
+		 * If the hardirq time is less than HARDIRQ_PERCENT_THRESH% in the last
+		 * sample_period, then we suspect the interrupt storm might be subsiding.
+		 */
+		if (!need_counting_irqs())
+			stop_counting_irqs();
+	}
+}
+
 static void report_cpu_status(void)
 {
 	print_cpustat();
+	print_irq_counts();
 }
 #else
 static inline void update_cpustat(void) { }
 static inline void report_cpu_status(void) { }
+static inline bool need_counting_irqs(void) { return false; }
+static inline void start_counting_irqs(void) { }
+static inline void stop_counting_irqs(void) { }
 #endif
 
 /*
@@ -522,6 +654,18 @@ static int is_softlockup(unsigned long touch_ts,
 			 unsigned long now)
 {
 	if ((watchdog_enabled & WATCHDOG_SOFTOCKUP_ENABLED) && watchdog_thresh) {
+		/*
+		 * If period_ts has not been updated during a sample_period, then
+		 * in the subsequent few sample_periods, period_ts might also not
+		 * be updated, which could indicate a potential softlockup. In
+		 * this case, if we suspect the cause of the potential softlockup
+		 * might be interrupt storm, then we need to count the interrupts
+		 * to find which interrupt is storming.
+		 */
+		if (time_after_eq(now, period_ts + get_softlockup_thresh() / 5) &&
+		    need_counting_irqs())
+			start_counting_irqs();
+
 		/* Warn about unreasonable delays. */
 		if (time_after(now, period_ts + get_softlockup_thresh()))
 			return now - touch_ts;
@@ -544,6 +688,7 @@ static DEFINE_PER_CPU(struct cpu_stop_work, softlockup_stop_work);
 static int softlockup_fn(void *data)
 {
 	update_touch_ts();
+	stop_counting_irqs();
 	complete(this_cpu_ptr(&softlockup_completion));
 
 	return 0;
-- 
2.37.1 (Apple Git-137.1)

Looks good！

Reviewed-by: Liu Song <liusong@linux.alibaba.com>

在 2024/2/8 20:54, Bitao Hu 写道:
> When the watchdog determines that the current soft lockup is due
> to an interrupt storm based on CPU utilization, reporting the
> most frequent interrupts could be good enough for further
> troubleshooting.
>
> Below is an example of interrupt storm. The call tree does not
> provide useful information, but we can analyze which interrupt
> caused the soft lockup by comparing the counts of interrupts.
>
> [ 2987.488075] watchdog: BUG: soft lockup - CPU#9 stuck for 23s! [kworker/9:1:214]
> [ 2987.488607] CPU#9 Utilization every 4s during lockup:
> [ 2987.488941]  #1:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.489357]  #2:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.489771]  #3:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.490186]  #4:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.490601]  #5:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.491034] CPU#9 Detect HardIRQ Time exceeds 50%. Most frequent HardIRQs:
> [ 2987.491493]  #1: 330985      irq#7(IPI)
> [ 2987.491743]  #2: 5000        irq#10(arch_timer)
> [ 2987.492039]  #3: 9           irq#91(nvme0q2)
> [ 2987.492318]  #4: 3           irq#118(virtio1-output.12)
> ...
> [ 2987.492728] Call trace:
> [ 2987.492729]  __do_softirq+0xa8/0x364
>
> Signed-off-by: Bitao Hu <yaoma@linux.alibaba.com>
> ---
>   kernel/watchdog.c | 153 ++++++++++++++++++++++++++++++++++++++++++++--
>   1 file changed, 149 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/watchdog.c b/kernel/watchdog.c
> index 380b60074f1d..e9e98ce5ff40 100644
> --- a/kernel/watchdog.c
> +++ b/kernel/watchdog.c
> @@ -12,22 +12,25 @@
>   
>   #define pr_fmt(fmt) "watchdog: " fmt
>   
> -#include <linux/mm.h>
>   #include <linux/cpu.h>
> -#include <linux/nmi.h>
>   #include <linux/init.h>
> +#include <linux/irq.h>
> +#include <linux/irqdesc.h>
>   #include <linux/kernel_stat.h>
> +#include <linux/kvm_para.h>
>   #include <linux/math64.h>
> +#include <linux/mm.h>
>   #include <linux/module.h>
> +#include <linux/nmi.h>
> +#include <linux/stop_machine.h>
>   #include <linux/sysctl.h>
>   #include <linux/tick.h>
> +
>   #include <linux/sched/clock.h>
>   #include <linux/sched/debug.h>
>   #include <linux/sched/isolation.h>
> -#include <linux/stop_machine.h>
>   
>   #include <asm/irq_regs.h>
> -#include <linux/kvm_para.h>
>   
>   static DEFINE_MUTEX(watchdog_mutex);
>   
> @@ -412,13 +415,142 @@ static void print_cpustat(void)
>   	}
>   }
>   
> +#define HARDIRQ_PERCENT_THRESH		50
> +#define NUM_HARDIRQ_REPORT		5
> +static DEFINE_PER_CPU(u32 *, hardirq_counts);
> +static DEFINE_PER_CPU(int, actual_nr_irqs);
> +struct irq_counts {
> +	int irq;
> +	u32 counts;
> +};
> +
> +/* Tabulate the most frequent interrupts. */
> +static void tabulate_irq_count(struct irq_counts *irq_counts, int irq, u32 counts, int rank)
> +{
> +	int i;
> +	struct irq_counts new_count = {irq, counts};
> +
> +	for (i = 0; i < rank; i++) {
> +		if (counts > irq_counts[i].counts)
> +			swap(new_count, irq_counts[i]);
> +	}
> +}
> +
> +/*
> + * If the hardirq time exceeds HARDIRQ_PERCENT_THRESH% of the sample_period,
> + * then the cause of softlockup might be interrupt storm. In this case, it
> + * would be useful to start interrupt counting.
> + */
> +static bool need_counting_irqs(void)
> +{
> +	u8 util;
> +	int tail = __this_cpu_read(cpustat_tail);
> +
> +	tail = (tail + NUM_HARDIRQ_REPORT - 1) % NUM_HARDIRQ_REPORT;
> +	util = __this_cpu_read(cpustat_util[tail][STATS_HARDIRQ]);
> +	return util > HARDIRQ_PERCENT_THRESH;
> +}
> +
> +static void start_counting_irqs(void)
> +{
> +	int i;
> +	int local_nr_irqs;
> +	struct irq_desc *desc;
> +	u32 *counts = __this_cpu_read(hardirq_counts);
> +
> +	if (!counts) {
> +		/*
> +		 * nr_irqs has the potential to grow at runtime. We should read
> +		 * it and store locally to avoid array out-of-bounds access.
> +		 */
> +		local_nr_irqs = READ_ONCE(nr_irqs);
> +		counts = kcalloc(local_nr_irqs, sizeof(u32), GFP_ATOMIC);
> +		if (!counts)
> +			return;
> +		for (i = 0; i < local_nr_irqs; i++) {
> +			desc = irq_to_desc(i);
> +			if (!desc)
> +				continue;
> +			counts[i] = desc->kstat_irqs ?
> +				*this_cpu_ptr(desc->kstat_irqs) : 0;
> +		}
> +		__this_cpu_write(actual_nr_irqs, local_nr_irqs);
> +		__this_cpu_write(hardirq_counts, counts);
> +	}
> +}
> +
> +static void stop_counting_irqs(void)
> +{
> +	kfree(__this_cpu_read(hardirq_counts));
> +	__this_cpu_write(hardirq_counts, NULL);
> +}
> +
> +static void print_irq_counts(void)
> +{
> +	int i;
> +	struct irq_desc *desc;
> +	u32 counts_diff;
> +	int local_nr_irqs = __this_cpu_read(actual_nr_irqs);
> +	u32 *counts = __this_cpu_read(hardirq_counts);
> +	struct irq_counts irq_counts_sorted[NUM_HARDIRQ_REPORT] = {
> +		{-1, 0}, {-1, 0}, {-1, 0}, {-1, 0},
> +	};
> +
> +	if (counts) {
> +		for_each_irq_desc(i, desc) {
> +			/*
> +			 * We need to bounds-check in case someone on a different CPU
> +			 * expanded nr_irqs.
> +			 */
> +			if (desc->kstat_irqs) {
> +				counts_diff = *this_cpu_ptr(desc->kstat_irqs);
> +				if (i < local_nr_irqs)
> +					counts_diff -= counts[i];
> +			} else {
> +				counts_diff = 0;
> +			}
> +			tabulate_irq_count(irq_counts_sorted, i, counts_diff,
> +					   NUM_HARDIRQ_REPORT);
> +		}
> +		/*
> +		 * We do not want the "watchdog: " prefix on every line,
> +		 * hence we use "printk" instead of "pr_crit".
> +		 */
> +		printk(KERN_CRIT "CPU#%d Detect HardIRQ Time exceeds %d%%. Most frequent HardIRQs:\n",
> +		       smp_processor_id(), HARDIRQ_PERCENT_THRESH);
> +		for (i = 0; i < NUM_HARDIRQ_REPORT; i++) {
> +			if (irq_counts_sorted[i].irq == -1)
> +				break;
> +			desc = irq_to_desc(irq_counts_sorted[i].irq);
> +			if (desc && desc->action)
> +				printk(KERN_CRIT "\t#%u: %-10u\tirq#%d(%s)\n",
> +				       i + 1, irq_counts_sorted[i].counts,
> +				       irq_counts_sorted[i].irq, desc->action->name);
> +			else
> +				printk(KERN_CRIT "\t#%u: %-10u\tirq#%d\n",
> +				       i + 1, irq_counts_sorted[i].counts,
> +				       irq_counts_sorted[i].irq);
> +		}
> +		/*
> +		 * If the hardirq time is less than HARDIRQ_PERCENT_THRESH% in the last
> +		 * sample_period, then we suspect the interrupt storm might be subsiding.
> +		 */
> +		if (!need_counting_irqs())
> +			stop_counting_irqs();
> +	}
> +}
> +
>   static void report_cpu_status(void)
>   {
>   	print_cpustat();
> +	print_irq_counts();
>   }
>   #else
>   static inline void update_cpustat(void) { }
>   static inline void report_cpu_status(void) { }
> +static inline bool need_counting_irqs(void) { return false; }
> +static inline void start_counting_irqs(void) { }
> +static inline void stop_counting_irqs(void) { }
>   #endif
>   
>   /*
> @@ -522,6 +654,18 @@ static int is_softlockup(unsigned long touch_ts,
>   			 unsigned long now)
>   {
>   	if ((watchdog_enabled & WATCHDOG_SOFTOCKUP_ENABLED) && watchdog_thresh) {
> +		/*
> +		 * If period_ts has not been updated during a sample_period, then
> +		 * in the subsequent few sample_periods, period_ts might also not
> +		 * be updated, which could indicate a potential softlockup. In
> +		 * this case, if we suspect the cause of the potential softlockup
> +		 * might be interrupt storm, then we need to count the interrupts
> +		 * to find which interrupt is storming.
> +		 */
> +		if (time_after_eq(now, period_ts + get_softlockup_thresh() / 5) &&
> +		    need_counting_irqs())
> +			start_counting_irqs();
> +
>   		/* Warn about unreasonable delays. */
>   		if (time_after(now, period_ts + get_softlockup_thresh()))
>   			return now - touch_ts;
> @@ -544,6 +688,7 @@ static DEFINE_PER_CPU(struct cpu_stop_work, softlockup_stop_work);
>   static int softlockup_fn(void *data)
>   {
>   	update_touch_ts();
> +	stop_counting_irqs();
>   	complete(this_cpu_ptr(&softlockup_completion));
>   
>   	return 0;

On Thu 2024-02-08 20:54:26, Bitao Hu wrote:
> When the watchdog determines that the current soft lockup is due
> to an interrupt storm based on CPU utilization, reporting the
> most frequent interrupts could be good enough for further
> troubleshooting.
> 
> Below is an example of interrupt storm. The call tree does not
> provide useful information, but we can analyze which interrupt
> caused the soft lockup by comparing the counts of interrupts.
> 
> [ 2987.488075] watchdog: BUG: soft lockup - CPU#9 stuck for 23s! [kworker/9:1:214]
> [ 2987.488607] CPU#9 Utilization every 4s during lockup:
> [ 2987.488941]  #1:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.489357]  #2:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.489771]  #3:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.490186]  #4:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.490601]  #5:   0% system,          0% softirq,   100% hardirq,     0% idle
> [ 2987.491034] CPU#9 Detect HardIRQ Time exceeds 50%. Most frequent HardIRQs:
> [ 2987.491493]  #1: 330985      irq#7(IPI)
> [ 2987.491743]  #2: 5000        irq#10(arch_timer)
> [ 2987.492039]  #3: 9           irq#91(nvme0q2)
> [ 2987.492318]  #4: 3           irq#118(virtio1-output.12)

Nit: It might looks slightly better if it prints the last 5 HardIRQs ;-)
     Maybe this version already does.

> --- a/kernel/watchdog.c
> +++ b/kernel/watchdog.c
> @@ -412,13 +415,142 @@ static void print_cpustat(void)
>  	}
>  }
>  
> +#define HARDIRQ_PERCENT_THRESH		50
> +#define NUM_HARDIRQ_REPORT		5

It actually creates array for 5 IRQ entries.

> +static DEFINE_PER_CPU(u32 *, hardirq_counts);
> +static DEFINE_PER_CPU(int, actual_nr_irqs);
> +struct irq_counts {
> +	int irq;
> +	u32 counts;
> +};
> +
> +static void print_irq_counts(void)
> +{
> +	int i;
> +	struct irq_desc *desc;
> +	u32 counts_diff;
> +	int local_nr_irqs = __this_cpu_read(actual_nr_irqs);
> +	u32 *counts = __this_cpu_read(hardirq_counts);
> +	struct irq_counts irq_counts_sorted[NUM_HARDIRQ_REPORT] = {
> +		{-1, 0}, {-1, 0}, {-1, 0}, {-1, 0},
> +	};
> +
> +	if (counts) {
> +		for_each_irq_desc(i, desc) {

I would use:

		for (i = 0; i < local_nr_irqs; i++) {

It does not make sense to process IRQs where "counts_diff = 0;"

> +

> +			/*
> +			 * We need to bounds-check in case someone on a different CPU
> +			 * expanded nr_irqs.
> +			 */
> +			if (desc->kstat_irqs) {
> +				counts_diff = *this_cpu_ptr(desc->kstat_irqs);
> +				if (i < local_nr_irqs)
> +					counts_diff -= counts[i];
> +			} else {
> +				counts_diff = 0;

And it would allow to remove this branch.

> +			}
> +			tabulate_irq_count(irq_counts_sorted, i, counts_diff,
> +					   NUM_HARDIRQ_REPORT);
> +		}

Please, add an empty line here.

Empty lines helps to read the code. For example, they help to make
clear that a top-level comment describes a particular block of code.
Or they helps to see where { } blocks end.

Long blobs of core are hard to read for me. Maybe, I suffer with some
level of dislexia but I know many more people who prefer this.

Heh, I would personally add empty lines on several other locations.

> +		/*
> +		 * We do not want the "watchdog: " prefix on every line,
> +		 * hence we use "printk" instead of "pr_crit".
> +		 */
> +		printk(KERN_CRIT "CPU#%d Detect HardIRQ Time exceeds %d%%. Most frequent HardIRQs:\n",
> +		       smp_processor_id(), HARDIRQ_PERCENT_THRESH);

for example here

> +		for (i = 0; i < NUM_HARDIRQ_REPORT; i++) {
> +			if (irq_counts_sorted[i].irq == -1)
> +				break;

here

> +			desc = irq_to_desc(irq_counts_sorted[i].irq);
> +			if (desc && desc->action)
> +				printk(KERN_CRIT "\t#%u: %-10u\tirq#%d(%s)\n",
> +				       i + 1, irq_counts_sorted[i].counts,
> +				       irq_counts_sorted[i].irq, desc->action->name);
> +			else
> +				printk(KERN_CRIT "\t#%u: %-10u\tirq#%d\n",
> +				       i + 1, irq_counts_sorted[i].counts,
> +				       irq_counts_sorted[i].irq);
> +		}

end here ;-)

> +		/*
> +		 * If the hardirq time is less than HARDIRQ_PERCENT_THRESH% in the last
> +		 * sample_period, then we suspect the interrupt storm might be subsiding.
> +		 */
> +		if (!need_counting_irqs())
> +			stop_counting_irqs();
> +	}
> +}
> +
> @@ -522,6 +654,18 @@ static int is_softlockup(unsigned long touch_ts,
>  			 unsigned long now)
>  {
>  	if ((watchdog_enabled & WATCHDOG_SOFTOCKUP_ENABLED) && watchdog_thresh) {
> +		/*
> +		 * If period_ts has not been updated during a sample_period, then
> +		 * in the subsequent few sample_periods, period_ts might also not
> +		 * be updated, which could indicate a potential softlockup. In
> +		 * this case, if we suspect the cause of the potential softlockup
> +		 * might be interrupt storm, then we need to count the interrupts
> +		 * to find which interrupt is storming.
> +		 */
> +		if (time_after_eq(now, period_ts + get_softlockup_thresh() / 5) &&

(get_softlockup_thresh() / 5) might be replaced by sample_period.

Also it looks to strict. I would allow some small delay, e.g. 1 ms.

> +		    need_counting_irqs())
> +			start_counting_irqs();
> +
>  		/* Warn about unreasonable delays. */
>  		if (time_after(now, period_ts + get_softlockup_thresh()))
>  			return now - touch_ts;

Great work!

Best Regards,
Petr

Hi,

On 2024/2/9 22:39, Petr Mladek wrote:
> On Thu 2024-02-08 20:54:26, Bitao Hu wrote:
>> When the watchdog determines that the current soft lockup is due
>> to an interrupt storm based on CPU utilization, reporting the
>> most frequent interrupts could be good enough for further
>> troubleshooting.
>>
>> Below is an example of interrupt storm. The call tree does not
>> provide useful information, but we can analyze which interrupt
>> caused the soft lockup by comparing the counts of interrupts.
>>
>> [ 2987.488075] watchdog: BUG: soft lockup - CPU#9 stuck for 23s! [kworker/9:1:214]
>> [ 2987.488607] CPU#9 Utilization every 4s during lockup:
>> [ 2987.488941]  #1:   0% system,          0% softirq,   100% hardirq,     0% idle
>> [ 2987.489357]  #2:   0% system,          0% softirq,   100% hardirq,     0% idle
>> [ 2987.489771]  #3:   0% system,          0% softirq,   100% hardirq,     0% idle
>> [ 2987.490186]  #4:   0% system,          0% softirq,   100% hardirq,     0% idle
>> [ 2987.490601]  #5:   0% system,          0% softirq,   100% hardirq,     0% idle
>> [ 2987.491034] CPU#9 Detect HardIRQ Time exceeds 50%. Most frequent HardIRQs:
>> [ 2987.491493]  #1: 330985      irq#7(IPI)
>> [ 2987.491743]  #2: 5000        irq#10(arch_timer)
>> [ 2987.492039]  #3: 9           irq#91(nvme0q2)
>> [ 2987.492318]  #4: 3           irq#118(virtio1-output.12)
> 
> Nit: It might looks slightly better if it prints the last 5 HardIRQs ;-)
>       Maybe this version already does.
Yes, it can print the last 5 HardIRQs. And I ignore those HardIRQs with
a count of zero, so it can print between 1 to 5 HardIRQs.
> 
>> --- a/kernel/watchdog.c
>> +++ b/kernel/watchdog.c
>> @@ -412,13 +415,142 @@ static void print_cpustat(void)
>>   	}
>>   }
>>   
>> +#define HARDIRQ_PERCENT_THRESH		50
>> +#define NUM_HARDIRQ_REPORT		5
> 
> It actually creates array for 5 IRQ entries.
> 
>> +static DEFINE_PER_CPU(u32 *, hardirq_counts);
>> +static DEFINE_PER_CPU(int, actual_nr_irqs);
>> +struct irq_counts {
>> +	int irq;
>> +	u32 counts;
>> +};
>> +
>> +static void print_irq_counts(void)
>> +{
>> +	int i;
>> +	struct irq_desc *desc;
>> +	u32 counts_diff;
>> +	int local_nr_irqs = __this_cpu_read(actual_nr_irqs);
>> +	u32 *counts = __this_cpu_read(hardirq_counts);
>> +	struct irq_counts irq_counts_sorted[NUM_HARDIRQ_REPORT] = {
>> +		{-1, 0}, {-1, 0}, {-1, 0}, {-1, 0},
>> +	};
>> +
>> +	if (counts) {
>> +		for_each_irq_desc(i, desc) {
> 
> I would use:
> 
> 		for (i = 0; i < local_nr_irqs; i++) {
The number of HardIRQs has the potential to grow at runtime. And I
want to count these newly added HardIRQs. Therefore, I use
"for_each_irq_desc" here.

> It does not make sense to process IRQs where "counts_diff = 0;"
> 
>> +
> 
>> +			/*
>> +			 * We need to bounds-check in case someone on a different CPU
>> +			 * expanded nr_irqs.
>> +			 */
>> +			if (desc->kstat_irqs) {
>> +				counts_diff = *this_cpu_ptr(desc->kstat_irqs);
>> +				if (i < local_nr_irqs)
>> +					counts_diff -= counts[i];
>> +			} else {
>> +				counts_diff = 0;
> 
> And it would allow to remove this branch.
Agree.
> 
>> +			}
>> +			tabulate_irq_count(irq_counts_sorted, i, counts_diff,
>> +					   NUM_HARDIRQ_REPORT);
>> +		}
> 
> Please, add an empty line here.
> 
> Empty lines helps to read the code. For example, they help to make
> clear that a top-level comment describes a particular block of code.
> Or they helps to see where { } blocks end.
> 
> Long blobs of core are hard to read for me. Maybe, I suffer with some
> level of dislexia but I know many more people who prefer this.
> 
> Heh, I would personally add empty lines on several other locations.
> 
>> +		/*
>> +		 * We do not want the "watchdog: " prefix on every line,
>> +		 * hence we use "printk" instead of "pr_crit".
>> +		 */
>> +		printk(KERN_CRIT "CPU#%d Detect HardIRQ Time exceeds %d%%. Most frequent HardIRQs:\n",
>> +		       smp_processor_id(), HARDIRQ_PERCENT_THRESH);
> 
> for example here
> 
>> +		for (i = 0; i < NUM_HARDIRQ_REPORT; i++) {
>> +			if (irq_counts_sorted[i].irq == -1)
>> +				break;
> 
> here
> 
>> +			desc = irq_to_desc(irq_counts_sorted[i].irq);
>> +			if (desc && desc->action)
>> +				printk(KERN_CRIT "\t#%u: %-10u\tirq#%d(%s)\n",
>> +				       i + 1, irq_counts_sorted[i].counts,
>> +				       irq_counts_sorted[i].irq, desc->action->name);
>> +			else
>> +				printk(KERN_CRIT "\t#%u: %-10u\tirq#%d\n",
>> +				       i + 1, irq_counts_sorted[i].counts,
>> +				       irq_counts_sorted[i].irq);
>> +		}
> 
> end here ;-)
> 
>> +		/*
>> +		 * If the hardirq time is less than HARDIRQ_PERCENT_THRESH% in the last
>> +		 * sample_period, then we suspect the interrupt storm might be subsiding.
>> +		 */
>> +		if (!need_counting_irqs())
>> +			stop_counting_irqs();
>> +	}
>> +}
OK, I will add empty lines for easier readability.
>> +
>> @@ -522,6 +654,18 @@ static int is_softlockup(unsigned long touch_ts,
>>   			 unsigned long now)
>>   {
>>   	if ((watchdog_enabled & WATCHDOG_SOFTOCKUP_ENABLED) && watchdog_thresh) {
>> +		/*
>> +		 * If period_ts has not been updated during a sample_period, then
>> +		 * in the subsequent few sample_periods, period_ts might also not
>> +		 * be updated, which could indicate a potential softlockup. In
>> +		 * this case, if we suspect the cause of the potential softlockup
>> +		 * might be interrupt storm, then we need to count the interrupts
>> +		 * to find which interrupt is storming.
>> +		 */
>> +		if (time_after_eq(now, period_ts + get_softlockup_thresh() / 5) &&
> 
> (get_softlockup_thresh() / 5) might be replaced by sample_period.
> 
The "sample_period" is measured in nanoseconds and is represented
by a "u64" type. However, the "time_after_eq" here expects seconds
as a "u32" type, hence I refrained from using "sample_period" in
this instance.

> Also it looks to strict. I would allow some small delay, e.g. 1 ms.
This is second-level precision, and "now" is obtained by
"running_clock() >> 30LL", so it's not strict here.
> 
>> +		    need_counting_irqs())
>> +			start_counting_irqs();
>> +
>>   		/* Warn about unreasonable delays. */
>>   		if (time_after(now, period_ts + get_softlockup_thresh()))
>>   			return now - touch_ts;
> 
> Great work!
Thanks.

Best Regards,
Bitao

Hi,

On Thu, Feb 8, 2024 at 4:54 AM Bitao Hu <yaoma@linux.alibaba.com> wrote:
>
> +static void start_counting_irqs(void)
> +{
> +       int i;
> +       int local_nr_irqs;
> +       struct irq_desc *desc;
> +       u32 *counts = __this_cpu_read(hardirq_counts);
> +
> +       if (!counts) {
> +               /*
> +                * nr_irqs has the potential to grow at runtime. We should read
> +                * it and store locally to avoid array out-of-bounds access.
> +                */
> +               local_nr_irqs = READ_ONCE(nr_irqs);

nit: I don't think the READ_ONCE() is actually needed above. All that
matters is that you're consistently using the same local variable
("local_nr_irqs") for allocating the array, looping, and then storing.
No matter what optimizations might be happening and what else might be
happening on other CPUs, once you put it in a local variable the
compiler _must_ keep it consistent.

That being said, I don't think it really matters, so I'm not sure it's
worth spinning your series just for that.

In any case, this patch looks good to me now. Thanks!

Reviewed-by: Douglas Anderson <dianders@chromium.org>

On 2024/2/9 00:03, Doug Anderson wrote:
> Hi,
> 
> On Thu, Feb 8, 2024 at 4:54 AM Bitao Hu <yaoma@linux.alibaba.com> wrote:
>>
>> +static void start_counting_irqs(void)
>> +{
>> +       int i;
>> +       int local_nr_irqs;
>> +       struct irq_desc *desc;
>> +       u32 *counts = __this_cpu_read(hardirq_counts);
>> +
>> +       if (!counts) {
>> +               /*
>> +                * nr_irqs has the potential to grow at runtime. We should read
>> +                * it and store locally to avoid array out-of-bounds access.
>> +                */
>> +               local_nr_irqs = READ_ONCE(nr_irqs);
> 
> nit: I don't think the READ_ONCE() is actually needed above. All that
> matters is that you're consistently using the same local variable
> ("local_nr_irqs") for allocating the array, looping, and then storing.
> No matter what optimizations might be happening and what else might be
> happening on other CPUs, once you put it in a local variable the
> compiler _must_ keep it consistent.
Oh, yes, READ_ONCE() is not necessary here.
> 
> That being said, I don't think it really matters, so I'm not sure it's
> worth spinning your series just for that.
> 
> In any case, this patch looks good to me now. Thanks!
> 
> Reviewed-by: Douglas Anderson <dianders@chromium.org>