[PATCH][v2] rtnetlink: add rtnl_lock debug log

* [PATCH][v2] rtnetlink: add rtnl_lock debug log
@ 2021-05-08  8:57 Rocco Yue
  2021-05-09  9:42 ` Andy Shevchenko
  2021-05-11 18:54 ` Aw: " Frank Wunderlich
  0 siblings, 2 replies; 4+ messages in thread
From: Rocco Yue @ 2021-05-08  8:57 UTC (permalink / raw)
  To: David S . Miller, Jakub Kicinski, Matthias Brugger,
	Andrew Morton, Masahiro Yamada, Nick Desaulniers,
	Andy Shevchenko, peterz
  Cc: Tetsuo Handa, Peter Enderborg, Thomas Gleixner,
	Anshuman Khandual, Vitor Massaru Iha, Sedat Dilek, Wei Yang,
	Cong Wang, Di Zhu, Stephen Hemminger, Francis Laniel,
	Roopa Prabhu, Andrii Nakryiko, linux-kernel, netdev,
	linux-arm-kernel, linux-mediatek, wsd_upsream, Rocco Yue

We often encounter system hangs caused by certain process
holding rtnl_lock for a long time. Even if there is a lock
detection mechanism in Linux, it is a bit troublesome and
affects the system performance. We hope to add a lightweight
debugging mechanism for detecting rtnl_lock.

Up to now, we have discovered and solved some potential bugs
through this lightweight rtnl_lock debugging mechanism, which
is helpful for us.

When you say Y for RTNL_LOCK_DEBUG, then the kernel will detect
if any function hold rtnl_lock too long and some key information
will be printed out to help locate the problem.

i.e: from the following logs, we can clearly know that the pid=2206
RfxSender_4 process holds rtnl_lock for a long time, causing the
system to hang. And we can also speculate that the delay operation
may be performed in devinet_ioctl(), resulting in rtnl_lock was
not released in time.

<6>[   40.191481][    C6] rtnetlink: -- rtnl_print_btrace start --
<6>[   40.191494][    C6] rtnetlink: RfxSender_4[2206][R] hold rtnl_lock
more than 2 sec, start time: 38181400013
<4>[   40.191510][    C6]  devinet_ioctl+0x1fc/0x75c
<4>[   40.191517][    C6]  inet_ioctl+0xb8/0x1f8
<4>[   40.191527][    C6]  sock_do_ioctl+0x70/0x2ac
<4>[   40.191533][    C6]  sock_ioctl+0x5dc/0xa74
<4>[   40.191541][    C6]  __arm64_sys_ioctl+0x178/0x1fc
<4>[   40.191548][    C6]  el0_svc_common+0xc0/0x24c
<4>[   40.191555][    C6]  el0_svc+0x28/0x88
<4>[   40.191560][    C6]  el0_sync_handler+0x8c/0xf0
<4>[   40.191566][    C6]  el0_sync+0x198/0x1c0
<6>[   40.191571][    C6] Call trace:
<6>[   40.191586][    C6]  rtnl_print_btrace+0xf0/0x124
<6>[   40.191595][    C6]  call_timer_fn+0x5c/0x3b4
<6>[   40.191602][    C6]  expire_timers+0xe0/0x49c
<6>[   40.191609][    C6]  __run_timers+0x34c/0x48c
<6>[   40.191616][    C6]  run_timer_softirq+0x28/0x58
<6>[   40.191621][    C6]  efi_header_end+0x168/0x690
<6>[   40.191628][    C6]  __irq_exit_rcu+0x108/0x124
<6>[   40.191635][    C6]  __handle_domain_irq+0x130/0x1b4
<6>[   40.191643][    C6]  gic_handle_irq.29882+0x6c/0x2d8
<6>[   40.191648][    C6]  el1_irq+0xdc/0x1c0
<6>[   40.191656][    C6]  __delay+0xc0/0x180
<6>[   40.191663][    C6]  devinet_ioctl+0x21c/0x75c
<6>[   40.191668][    C6]  inet_ioctl+0xb8/0x1f8
<6>[   40.191675][    C6]  sock_do_ioctl+0x70/0x2ac
<6>[   40.191682][    C6]  sock_ioctl+0x5dc/0xa74
<6>[   40.191688][    C6]  __arm64_sys_ioctl+0x178/0x1fc
<6>[   40.191694][    C6]  el0_svc_common+0xc0/0x24c
<6>[   40.191699][    C6]  el0_svc+0x28/0x88
<6>[   40.191705][    C6]  el0_sync_handler+0x8c/0xf0
<6>[   40.191710][    C6]  el0_sync+0x198/0x1c0
<6>[   40.191715][    C6] rtnetlink: -- rtnl_print_btrace end --

<6>[   42.181879][ T2206] rtnetlink: rtnl_lock is held by [2206] from
[38181400013] to [42181875177]

Signed-off-by: Rocco Yue <rocco.yue@mediatek.com>
---
 lib/Kconfig.debug    | 10 ++++++
 net/core/rtnetlink.c | 85 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 95 insertions(+)

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 678c13967580..f1a722e16bee 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -2027,6 +2027,16 @@ config KCOV_IRQ_AREA_SIZE
 	  soft interrupts. This specifies the size of those areas in the
 	  number of unsigned long words.
 
+config RTNL_LOCK_DEBUG
+	bool "rtnl_lock debugging, deadlock detection"
+	depends on STACKTRACE_SUPPORT
+	select STACKTRACE
+	help
+	  If you say Y here then the kernel will detect whether any function
+	  hold rtnl_lock too long and some key information will be printed
+	  out to help locate the problem.
+	  If unsure, say N.
+
 menuconfig RUNTIME_TESTING_MENU
 	bool "Runtime Testing"
 	def_bool y
diff --git a/net/core/rtnetlink.c b/net/core/rtnetlink.c
index 714d5fa38546..4f81086e5a42 100644
--- a/net/core/rtnetlink.c
+++ b/net/core/rtnetlink.c
@@ -12,6 +12,8 @@
  *	Vitaly E. Lavrov		RTA_OK arithmetics was wrong.
  */
 
+#define pr_fmt(fmt) "rtnetlink: " fmt
+
 #include <linux/bitops.h>
 #include <linux/errno.h>
 #include <linux/module.h>
@@ -57,6 +59,81 @@
 #define RTNL_MAX_TYPE		50
 #define RTNL_SLAVE_MAX_TYPE	40
 
+#ifdef CONFIG_RTNL_LOCK_DEBUG
+
+#include <linux/sched/debug.h>
+#include <linux/stacktrace.h>
+
+/* Debug log and btrace will be printed when the rtnl_lock
+ * is held for more than RTNL_LOCK_MAX_HOLD_TIME seconds
+ */
+#define RTNL_LOCK_MAX_HOLD_TIME 2
+
+#define RTNL_LOCK_MAX_TRACE     10    /* stack trace length */
+
+struct rtnl_debug_btrace_t {
+	struct task_struct *task;
+	int pid;
+	unsigned long long start_time;
+	unsigned long long end_time;
+	unsigned long addrs[RTNL_LOCK_MAX_TRACE];
+	unsigned int  nr_entries;
+};
+
+static struct rtnl_debug_btrace_t rtnl_instance;
+
+static void rtnl_print_btrace(struct timer_list *unused);
+static DEFINE_TIMER(rtnl_chk_timer, rtnl_print_btrace);
+
+/* Save stack trace to the given array of RTNL_LOCK_MAX_TRACE size.
+ */
+static int __save_stack_trace(unsigned long *trace)
+{
+	return stack_trace_save(trace, RTNL_LOCK_MAX_TRACE, 0);
+}
+
+static void rtnl_get_btrace(struct task_struct *who)
+{
+	unsigned long expires;
+
+	rtnl_instance.task = who;
+	rtnl_instance.pid = who->pid;
+	rtnl_instance.start_time = sched_clock();
+	rtnl_instance.end_time = 0;
+	rtnl_instance.nr_entries = __save_stack_trace(rtnl_instance.addrs);
+
+	expires = jiffies + RTNL_LOCK_MAX_HOLD_TIME * HZ;
+	mod_timer(&rtnl_chk_timer, expires);
+}
+
+static void rtnl_print_btrace(struct timer_list *unused)
+{
+	pr_info("-- %s start --\n", __func__);
+	pr_info("%s[%d][%c] hold rtnl_lock more than %d sec, start time: %llu\n",
+		rtnl_instance.task->comm,
+		rtnl_instance.pid,
+		task_state_to_char(rtnl_instance.task),
+		RTNL_LOCK_MAX_HOLD_TIME,
+		rtnl_instance.start_time);
+	stack_trace_print(rtnl_instance.addrs, rtnl_instance.nr_entries, 0);
+	show_stack(rtnl_instance.task, NULL, KERN_INFO);
+	pr_info("-- %s end --\n", __func__);
+}
+
+static void rtnl_relase_btrace(void)
+{
+	rtnl_instance.end_time = sched_clock();
+	del_timer_sync(&rtnl_chk_timer);
+
+	if (rtnl_instance.end_time - rtnl_instance.start_time > 2 * NSEC_PER_SEC) {
+		pr_info("rtnl_lock is held by [%d] from [%llu] to [%llu]\n",
+			rtnl_instance.pid,
+			rtnl_instance.start_time,
+			rtnl_instance.end_time);
+	}
+}
+#endif
+
 struct rtnl_link {
 	rtnl_doit_func		doit;
 	rtnl_dumpit_func	dumpit;
@@ -70,6 +147,10 @@ static DEFINE_MUTEX(rtnl_mutex);
 void rtnl_lock(void)
 {
 	mutex_lock(&rtnl_mutex);
+
+#ifdef CONFIG_RTNL_LOCK_DEBUG
+	rtnl_get_btrace(current);
+#endif
 }
 EXPORT_SYMBOL(rtnl_lock);
 
@@ -95,6 +176,10 @@ void __rtnl_unlock(void)
 
 	defer_kfree_skb_list = NULL;
 
+#ifdef CONFIG_RTNL_LOCK_DEBUG
+	rtnl_relase_btrace();
+#endif
+
 	mutex_unlock(&rtnl_mutex);
 
 	while (head) {
-- 
2.18.0


^ permalink raw reply related	[flat|nested] 4+ messages in thread