Re: [PATCH][v2] rtnetlink: add rtnl_lock debug log
From: Rocco.Yue <hidden>
Date: 2021-05-10 07:48:50
Also in:
linux-mediatek
On Sun, 2021-05-09 at 12:42 +0300, Andy Shevchenko wrote:
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]
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]
Best Regards Rocco _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel