Re: RE: Network do not works with linux >= 6.1.2. Issue bisected to "425c9bd06b7a70796d880828d15c11321bdfb76d" (RDMA/irdma: Report the correct link speed)

[Linus Heckemann <git@sphalerite.org>]

Hi,

Zhu Yanjun <yanjun.zhu@linux.dev> 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.

[  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