> Subject: Re: RE: Network do not works with linux >= 6.1.2. Issue bisected to
> "425c9bd06b7a70796d880828d15c11321bdfb76d" (RDMA/irdma: Report the
> correct link speed)
>
> Hi,
>
> Zhu Yanjun <yanjun.zhu@xxxxxxxxx> writes:
>
> > 在 2023/1/10 3:36, Saleem, Shiraz 写道:
> >>> Subject: Re: Network do not works with linux >= 6.1.2. Issue
> >>> bisected to "425c9bd06b7a70796d880828d15c11321bdfb76d" (RDMA/irdma:
> >>> Report the correct link speed)
> >>>
> >>> On Fri, Jan 06, 2023 at 08:55:29AM +0100, Jaroslav Pulchart wrote:
> >>>> [ 257.967099] task:NetworkManager state:D stack:0 pid:3387
> >>>> ppid:1 flags:0x00004002
> >>>> [ 257.975446] Call Trace:
> >>>> [ 257.977901] <TASK>
> >>>> [ 257.980004] __schedule+0x1eb/0x630 [ 257.983498]
> >>>> schedule+0x5a/0xd0 [ 257.986641] schedule_timeout+0x11d/0x160 [
> >>>> 257.990654] __wait_for_common+0x90/0x1e0 [ 257.994666] ?
> >>>> usleep_range_state+0x90/0x90 [ 257.998854]
> >>>> __flush_workqueue+0x13a/0x3f0 [ 258.002955] ?
> >>>> __kernfs_remove.part.0+0x11e/0x1e0
> >>>> [ 258.007661] ib_cache_cleanup_one+0x1c/0xe0 [ib_core] [
> >>>> 258.012721] __ib_unregister_device+0x62/0xa0 [ib_core] [
> >>>> 258.017959]
> >>>> ib_unregister_device+0x22/0x30 [ib_core] [ 258.023024]
> >>>> irdma_remove+0x1a/0x60 [irdma] [ 258.027223]
> >>>> auxiliary_bus_remove+0x18/0x30 [ 258.031414]
> >>>> device_release_driver_internal+0x1aa/0x230
> >>>> [ 258.036643] bus_remove_device+0xd8/0x150 [ 258.040654]
> >>>> device_del+0x18b/0x3f0 [ 258.044149] ice_unplug_aux_dev+0x42/0x60
> >>>> [ice]
> >>>
> >>> We talked about this already - wasn't it on this series?
> >>
> >> This is yet another path (when ice ports are added to a bond) I
> >> believe where the RDMA aux device is removed holding the RTNL lock.
> >> It's being exposed now with this recent irdma patch - 425c9bd06b7a, causing a
> deadlock.
> >>
> >> ice_lag_event_handler [rtnl_lock]
> >> ->ice_lag_changeupper_event
> >> ->ice_unplug_aux_dev
> >> ->irdma_remove
> >> ->ib_unregister_device
> >> ->ib_cache_cleanup_one
> >> ->flush_workqueue(ib)
> >> ->irdma_query_port
> >> -> ib_get_eth_speed [rtnl_lock]
> >
> > Agree with the above analysis.
> > Maybe a quick and direct fix is like this.
> >
> > @@ -74,6 +74,7 @@ static int irdma_query_port(struct ib_device *ibdev,
> > u32 port,
> > {
> > struct irdma_device *iwdev = to_iwdev(ibdev);
> > struct net_device *netdev = iwdev->netdev;
> > + bool unlock_rtnl = false;
> >
> > /* no need to zero out pros here. done by caller */
> >
> > @@ -91,9 +92,16 @@ static int irdma_query_port(struct ib_device
> > *ibdev,
> > u32 port,
> > props->phys_state = IB_PORT_PHYS_STATE_DISABLED;
> > }
> >
> > + if (rtnl_is_locked()) {
> > + rtnl_unlock();
> > + unlock_rtnl = true;
> > + }
>
> Does this not introduce a window where something else could acquire the lock,
> when something further up in the call chain could be holding the lock for a good
> reason?
>
> > ib_get_eth_speed(ibdev, port, &props->active_speed,
> > &props->active_width);
> >
> > + if (unlock_rtnl) {
> > + rtnl_lock();
> > + }
> > if (rdma_protocol_roce(ibdev, 1)) {
> > props->gid_tbl_len = 32;
> > props->ip_gids = true;
> >
>
> That said, I've tested this anyway and it does appear to solve the reported
> deadlock, but seems to introduce other hangs (this is rarer -- I've encountered the
> issue on 3 boots out of 30). Maybe this is the race condition which I suspect? Here
> are the hung-task traces from one such occurrence.
David E. is fixing this in ice. To defer the remove/add auxiliary device outside the RTNL context during an ice bonding event.
A patch for it will be posted when ready.
>
> [ 247.237227] INFO: task kworker/10:1:415 blocked for more than 122 seconds.
> [ 247.244183] Not tainted 5.15.86 #1-NixOS
> [ 247.248626] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> [ 247.256453] task:kworker/10:1 state:D stack: 0 pid: 415 ppid: 2
> flags:0x00004000
> [ 247.256457] Workqueue: ipv6_addrconf addrconf_dad_work [ 247.256462] Call
> Trace:
> [ 247.256463] <TASK>
> [ 247.256466] __schedule+0x2e6/0x13a0
> [ 247.256471] ? ip6_finish_output2+0x1f5/0x6d0 [ 247.256473]
> schedule+0x5b/0xd0 [ 247.256475] schedule_preempt_disabled+0xa/0x10
> [ 247.256477] __mutex_lock.constprop.0+0x216/0x400
> [ 247.256479] addrconf_dad_work+0x3e/0x570 [ 247.256481] ?
> mld_ifc_work+0x1b2/0x450 [ 247.256482] process_one_work+0x1f1/0x390 [
> 247.256485] worker_thread+0x53/0x3e0 [ 247.256486] ?
> process_one_work+0x390/0x390 [ 247.256487] kthread+0x127/0x150 [
> 247.256489] ? set_kthread_struct+0x50/0x50 [ 247.256491]
> ret_from_fork+0x22/0x30 [ 247.256494] </TASK> [ 247.256499] INFO: task
> kworker/34:1:460 blocked for more than 122 seconds.
> [ 247.263367] Not tainted 5.15.86 #1-NixOS
> [ 247.267813] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> [ 247.275640] task:kworker/34:1 state:D stack: 0 pid: 460 ppid: 2
> flags:0x00004000
> [ 247.275643] Workqueue: events_power_efficient reg_check_chans_work
> [cfg80211] [ 247.275661] Call Trace:
> [ 247.275662] <TASK>
> [ 247.275663] __schedule+0x2e6/0x13a0
> [ 247.275665] ? select_task_rq_fair+0x1010/0x1090 [ 247.275668]
> schedule+0x5b/0xd0 [ 247.275669] schedule_preempt_disabled+0xa/0x10
> [ 247.275671] __mutex_lock.constprop.0+0x216/0x400
> [ 247.275673] reg_check_chans_work+0x2d/0x390 [cfg80211] [ 247.275687]
> process_one_work+0x1f1/0x390 [ 247.275688] worker_thread+0x53/0x3e0 [
> 247.275689] ? process_one_work+0x390/0x390 [ 247.275690]
> kthread+0x127/0x150 [ 247.275692] ? set_kthread_struct+0x50/0x50 [
> 247.275693] ret_from_fork+0x22/0x30 [ 247.275695] </TASK> [ 247.275698]
> INFO: task kworker/46:1:484 blocked for more than 122 seconds.
> [ 247.282572] Not tainted 5.15.86 #1-NixOS
> [ 247.287017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> [ 247.294842] task:kworker/46:1 state:D stack: 0 pid: 484 ppid: 2
> flags:0x00004000
> [ 247.294844] Workqueue: ipv6_addrconf addrconf_verify_work [ 247.294846]
> Call Trace:
> [ 247.294847] <TASK>
> [ 247.294847] __schedule+0x2e6/0x13a0
> [ 247.294849] ? raw_spin_rq_lock_nested+0x12/0x70 [ 247.294851] ?
> newidle_balance+0x2ee/0x400 [ 247.294852] schedule+0x5b/0xd0 [ 247.294854]
> schedule_preempt_disabled+0xa/0x10
> [ 247.294856] __mutex_lock.constprop.0+0x216/0x400
> [ 247.294857] addrconf_verify_work+0xa/0x20 [ 247.294858]
> process_one_work+0x1f1/0x390 [ 247.294859] worker_thread+0x53/0x3e0 [
> 247.294860] ? process_one_work+0x390/0x390 [ 247.294861]
> kthread+0x127/0x150 [ 247.294862] ? set_kthread_struct+0x50/0x50 [
> 247.294864] ret_from_fork+0x22/0x30 [ 247.294866] </TASK> [ 247.294888]
> INFO: task systemd-udevd:1658 blocked for more than 122 seconds.
> [ 247.301934] Not tainted 5.15.86 #1-NixOS
> [ 247.306379] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> [ 247.314206] task:systemd-udevd state:D stack: 0 pid: 1658 ppid: 1506
> flags:0x00004226
> [ 247.314208] Call Trace:
> [ 247.314209] <TASK>
> [ 247.314209] __schedule+0x2e6/0x13a0
> [ 247.314212] schedule+0x5b/0xd0
> [ 247.314214] schedule_preempt_disabled+0xa/0x10
> [ 247.314216] __mutex_lock.constprop.0+0x216/0x400
> [ 247.314217] ? kobject_uevent_env+0x11f/0x680 [ 247.314220] ?
> bus_add_driver+0x1a8/0x200 [ 247.314225]
> register_netdevice_notifier+0x21/0x110
> [ 247.314228] ? 0xffffffffc181f000
> [ 247.314247] irdma_init_module+0xa6/0x1000 [irdma] [ 247.314258]
> do_one_initcall+0x44/0x1d0 [ 247.314260] ? __cond_resched+0x16/0x50 [
> 247.314262] ? kmem_cache_alloc_trace+0x44/0x3d0 [ 247.314265]
> do_init_module+0x4c/0x250 [ 247.314268] __do_sys_init_module+0x12e/0x1b0 [
> 247.314271] do_syscall_64+0x3b/0x90 [ 247.314274]
> entry_SYSCALL_64_after_hwframe+0x61/0xcb
> [ 247.314276] RIP: 0033:0x7f7a2089a0fe
> [ 247.314279] RSP: 002b:00007ffd449a33e8 EFLAGS: 00000246 ORIG_RAX:
> 00000000000000af [ 247.314281] RAX: ffffffffffffffda RBX: 0000556ce7b5f6c0
> RCX: 00007f7a2089a0fe [ 247.314282] RDX: 00007f7a209feb1d RSI:
> 00000000000cef90 RDI: 0000556ce7f21430 [ 247.314283] RBP: 0000556ce7f21430
> R08: 0000000000000007 R09: 0000556ce7b607e0 [ 247.314283] R10:
> 0000000000000005 R11: 0000000000000246 R12: 00007f7a209feb1d [ 247.314284]
> R13: 0000556ce7b5f6c0 R14: 0000556ce7b472b0 R15: 0000556ce7b5f6c0 [
> 247.314285] </TASK>
>
> Thanks for looking into this!
>
> Linus Heckemann
