| Message ID | 20210511113257.2094-1-rocco.yue@mediatek.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | [v3] rtnetlink: add rtnl_lock debug log | expand |
On Tue, May 11, 2021 at 4:46 AM Rocco yue <rocco.yue@mediatek.com> wrote: > > From: Rocco Yue <rocco.yue@mediatek.com> > > 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. Any reason why this is specific to RTNL lock? To me holding a mutex lock for a long time is problematic for any mutex. I have seen some fs mutex being held for a long time caused many hung tasks in the system. Thanks.
On Tue, 2021-05-11 at 10:00 -0700, Cong Wang wrote: > On Tue, May 11, 2021 at 4:46 AM Rocco yue <rocco.yue@mediatek.com> wrote: > > > > From: Rocco Yue <rocco.yue@mediatek.com> > > > > 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. > > Any reason why this is specific to RTNL lock? To me holding > a mutex lock for a long time is problematic for any mutex. > I have seen some fs mutex being held for a long time caused > many hung tasks in the system. > > Thanks. Thank you for a good question. It's a problem to hold rtnl_lock for a long time, and other locks are no exception. the reason for adding rtnl_lock debug log: 1.rtnl_lock is a widely used lock: In my view, for some other mutex locks, such as "f2fs_stat_mutex" in the fs/f2fs/debug.c , there are not many codes that use this lock, and the module involved is relatively single. But when we search for rtnl_lock in the entire Linux kernel, we will get a lot of matching results. Obviously this lock is a widely used lock, which makes it difficult for us to locate the problem. If we do not enable CONFIG_DEBUG_LOCKDEP and CONFIG_PROVE_LOCKING, it is often difficult for us to find out where went wrong. 2.codes that use rtnl_lock include some basic functions of networking: There are many networking modules that use rtnl_lock, and some functions that use rtnl_lock are infrastructure part, such as unregister_netdev(), dev_ioctl(). Perhaps this can also explain to a certain extent the importance of adding a lightweight debug mechanism for rtnl_lock. And mediatek and our customer have benefited a lot from such log. Hope above contents can answer your question. Best Regards Rocco
On Tue, 11 May 2021 19:32:57 +0800 Rocco yue wrote: > 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. You can achieve that with a pair of fexit/fentry hooks or kprobes, and maybe a bit of BPF. No need for config options, and hardcoded parameters..
On Wed, May 12, 2021 at 1:38 AM Rocco.Yue <rocco.yue@mediatek.com> wrote: > > On Tue, 2021-05-11 at 10:00 -0700, Cong Wang wrote: > > On Tue, May 11, 2021 at 4:46 AM Rocco yue <rocco.yue@mediatek.com> wrote: > > > > > > From: Rocco Yue <rocco.yue@mediatek.com> > > > > > > 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. > > > > Any reason why this is specific to RTNL lock? To me holding > > a mutex lock for a long time is problematic for any mutex. > > I have seen some fs mutex being held for a long time caused > > many hung tasks in the system. > > > > Thanks. > > Thank you for a good question. > > It's a problem to hold rtnl_lock for a long time, and other locks are no > exception. Then please try to make it generic so that other mutex locks will benefit too. Thanks.
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) {