| Message ID | 20210508085738.6296-1-rocco.yue@mediatek.com |
|---|---|
| State | New |
| Headers | show |
| Series | [v2] rtnetlink: add rtnl_lock debug log | expand |
On Mon, May 10, 2021 at 03:23:41PM +0800, Rocco.Yue wrote: > On Sun, 2021-05-09 at 12:42 +0300, Andy Shevchenko wrote: > > On Sat, May 8, 2021 at 12:11 PM Rocco Yue <rocco.yue@mediatek.com> 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. > > > > > > <6>[ 40.191481][ C6] rtnetlink: -- rtnl_print_btrace start -- > > > > You don't seem to get it. It's a quite long trace for the commit > > message. Do you need all those lines below? Why? > > > > The contents shown in all the lines below are the original printed after > adding this patch, I pasted these lines into commit message to > illustrate this patch as a case. > > It now appears that some of following are indeed unnecessary, I am going > to condense a lot of following contents as follows. > > Could you please help to take a look at it again? many thanks :-) > > [ 40.191481] rtnetlink: -- rtnl_print_btrace start -- > [ 40.191494] RfxSender_4[2206][R] hold rtnl_lock more than 2 sec, > start time: 38181400013 > [ 40.191571] Call trace: > [ 40.191586] rtnl_print_btrace+0xf0/0x124 > [ 40.191656] __delay+0xc0/0x180 > [ 40.191663] devinet_ioctl+0x21c/0x75c > [ 40.191668] inet_ioctl+0xb8/0x1f8 > [ 40.191675] sock_do_ioctl+0x70/0x2ac > [ 40.191682] sock_ioctl+0x5dc/0xa74 > [ 40.191715] rtnetlink: -- rtnl_print_btrace end -- > [ 42.181879] rtnetlink: rtnl_lock is held by [2206] from > [38181400013] to [42181875177] Much better, thanks! (You still need a real review on the contents of the change) > > > <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] -- With Best Regards, Andy Shevchenko
> Gesendet: Samstag, 08. Mai 2021 um 10:57 Uhr > Von: "Rocco Yue" <rocco.yue@mediatek.com> > Betreff: [PATCH][v2] rtnetlink: add rtnl_lock debug log > <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 it would be good to have same time-format (seconds.nanosec) > <6>[ 42.181879][ T2206] rtnetlink: rtnl_lock is held by [2206] from > [38181400013] to [42181875177] same as above > +static void rtnl_relase_btrace(void) should this be release_btrace? regards Frank
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) {
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(+)