Messages in this thread | | | From | Andy Shevchenko <> | Date | Thu, 29 Apr 2021 12:32:17 +0300 | Subject | Re: [PATCH] rtnetlink: add rtnl_lock debug log |
| |
On Thu, Apr 29, 2021 at 10:21 AM Rocco Yue <rocco.yue@mediatek.com> wrote: > > We often encounter system hangs caused by certain processes > 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 such debug information of this lightweight rtnl_lock, > 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 to help identify the issue point. > > i.e: from the following logs, we can clear know that the pid=5546
clearly
> RfxSender_4 process hold rtnl_lock for a long time, causing the
holds
> system hang. And we can also speculate that the delay operation
to hang
> may be performed in devinet_ioctl(), resulting in rtnl_lock was > not released in time. > > <6>[ 141.151364] ----------- rtnl_print_btrace start -----------
Can you, please, shrink this to the point?
> <6>[ 141.152079] RfxSender_4[5546][R] hold rtnl_lock more than 2 sec, > start time: 139129481562 > <4>[ 141.153114] rtnl_lock+0x88/0xfc > <4>[ 141.153523] devinet_ioctl+0x190/0x1268 > <4>[ 141.154007] inet_ioctl+0x108/0x1f4 > <4>[ 141.154449] sock_do_ioctl+0x88/0x200 > <4>[ 141.154911] sock_ioctl+0x4b0/0x884 > <4>[ 141.155367] do_vfs_ioctl+0x6b0/0xcc4 > <4>[ 141.155830] __arm64_sys_ioctl+0xc0/0xec > <4>[ 141.156326] el0_svc_common+0x130/0x2c0 > <4>[ 141.156810] el0_svc_handler+0xd0/0xe0 > <4>[ 141.157283] el0_svc+0x8/0xc > <4>[ 141.157646] Call trace: > <4>[ 141.157956] dump_backtrace+0x0/0x240 > <4>[ 141.158418] show_stack+0x18/0x24 > <4>[ 141.158836] rtnl_print_btrace+0x138/0x1cc > <4>[ 141.159362] call_timer_fn+0x120/0x47c > <4>[ 141.159834] expire_timers+0x28c/0x420 > <4>[ 141.160306] __run_timers+0x3d0/0x494 > <4>[ 141.160768] run_timer_softirq+0x24/0x48 > <4>[ 141.161262] __do_softirq+0x26c/0x968 > <4>[ 141.161725] irq_exit+0x1f8/0x2b4 > <4>[ 141.162145] __handle_domain_irq+0xdc/0x15c > <4>[ 141.162672] gic_handle_irq+0xe4/0x188 > <4>[ 141.163144] el1_irq+0x104/0x200 > <4>[ 141.163559] __const_udelay+0x118/0x1b0 > <4>[ 141.164044] devinet_ioctl+0x1a0/0x1268 > <4>[ 141.164527] inet_ioctl+0x108/0x1f4 > <4>[ 141.164968] sock_do_ioctl+0x88/0x200 > <4>[ 141.165428] sock_ioctl+0x4b0/0x884 > <4>[ 141.165868] do_vfs_ioctl+0x6b0/0xcc4 > <4>[ 141.166330] __arm64_sys_ioctl+0xc0/0xec > <4>[ 141.166825] el0_svc_common+0x130/0x2c0 > <4>[ 141.167308] el0_svc_handler+0xd0/0xe0 > <4>[ 141.167786] el0_svc+0x8/0xc > <6>[ 141.168153] ------------ rtnl_print_btrace end ----------- > > <6>[ 147.321389] rtnl_lock is held by [5546] from > [139129481562] to [147321378812]
...
> +static struct rtnl_debug_btrace_t rtnl_instance = { > + .task = NULL, > + .pid = 0, > + .start_time = 0, > + .end_time = 0, > + .nr_entries = 0,
static assumes all 0:s, what's the point?
> +};
...
> +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 2 sec, start time: %llu\n", > + rtnl_instance.task->comm, > + rtnl_instance.pid, > + task_state_to_char(rtnl_instance.task), > + rtnl_instance.start_time); > + stack_trace_print(rtnl_instance.addrs, rtnl_instance.nr_entries, 0);
> + show_stack(rtnl_instance.task, NULL, KERN_DEBUG);
Unaligned debug level.
> + pr_info("------------ %s end -----------\n", __func__);
Looking into tons of these, perhaps you need to define pr_fmt(). I haven't checked if it's already defined, though.
> +}
...
> + if (rtnl_instance.end_time - rtnl_instance.start_time > 2000000000ULL) {
Perhaps you should use one of the defined constants from time64.h ?
> + pr_info("rtnl_lock is held by [%d] from [%llu] to [%llu]\n", > + rtnl_instance.pid, > + rtnl_instance.start_time, > + rtnl_instance.end_time); > + }
-- With Best Regards, Andy Shevchenko
| |