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

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:

quoted

On Sat, May 8, 2021 at 12:11 PM Rocco Yue [off-list ref] wrote:

quoted

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)

quoted

quoted

<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