On Wed, Feb 12, 2025 at 04:29:25PM +0100, Sebastian Andrzej Siewior wrote:

On 2025-02-12 12:21:04 [-0300], Wander Lairson Costa wrote:

quoted

quoted

"eventually fails". Does this mean it passes the first few iterations
but then it times out? In that case it might be something else

Yes. Indeed, might be due something else. I will perform further investigation
when I get the machine back.

Okay. Then I consider this series not going to be applied, I have an
idea what is happening and I wait until you get back.

Sorry it took so long. After a day fighting the machine I could boot an
upstream kernel on it and generate the logs.

These logs are for the test case of booting the kernel with nr_cpus=1:

     kworker/0:0-8       [000] d..2.  2120.708145: process_one_work <-worker_thread
     kworker/0:0-8       [000] ...1.  2120.708145: igbvf_reset_task <-process_one_work
     kworker/0:0-8       [000] ...1.  2120.708145: igbvf_reinit_locked <-process_one_work
     kworker/0:0-8       [000] ...1.  2120.708145: igbvf_down <-igbvf_reinit_locked
     kworker/0:0-8       [000] ...1.  2120.718619: igbvf_update_stats <-igbvf_down
     kworker/0:0-8       [000] ...1.  2120.718619: igbvf_reset <-igbvf_down
     kworker/0:0-8       [000] b..13  2120.718620: e1000_reset_hw_vf <-igbvf_reset
     kworker/0:0-8       [000] b..13  2120.718620: e1000_check_for_rst_vf <-e1000_reset_hw_vf
     kworker/0:0-8       [000] b..13  2120.718621: e1000_write_posted_mbx <-e1000_reset_hw_vf
     kworker/0:0-8       [000] b..13  2120.718621: e1000_write_mbx_vf <-e1000_write_posted_mbx
     kworker/0:0-8       [000] b..13  2120.718624: e1000_check_for_ack_vf <-e1000_write_posted_mbx
     kworker/0:0-8       [000] D.h.3  2120.718626: irq_handler_entry: irq=63 name=ens14f0
     kworker/0:0-8       [000] b..13  2120.719133: e1000_check_for_ack_vf <-e1000_write_posted_mbx
	[...] repeats e1000_check_for_ack_vf for 2000 lines
     kworker/0:0-8       [000] b..13  2120.719634: e1000_check_for_ack_vf <-e1000_write_posted_mbx
     kworker/0:0-8       [000] b..13  2121.730639: e1000_read_posted_mbx <-e1000_reset_hw_vf
     kworker/0:0-8       [000] b..13  2121.730643: e1000_init_hw_vf <-igbvf_reset
     kworker/0:0-8       [000] b..13  2121.730643: e1000_rar_set_vf <-e1000_init_hw_vf
     kworker/0:0-8       [000] b..13  2121.730643: e1000_write_posted_mbx <-e1000_rar_set_vf
     kworker/0:0-8       [000] D.Zf2  2121.730645: igbvf_reset_L14: (igbvf_reset+0x62/0x120 [igbvf])
     kworker/0:0-8       [000] .N...  2121.730649: igbvf_reset_L16: (igbvf_reset+0x7b/0x120 [igbvf])
  irq/63-ens14f0-1112    [000] b..12  2121.730652: igb_msix_other <-irq_thread_fn
  irq/63-ens14f0-1112    [000] b..12  2121.730652: igb_rd32 <-igb_msix_other
  irq/63-ens14f0-1112    [000] b..13  2121.730653: igb_check_for_rst <-igb_msix_other
  irq/63-ens14f0-1112    [000] b..13  2121.730653: igb_check_for_rst_pf <-igb_msix_other

I created two custom probes inside igbvf_reset:

$ perf probe -m /lib/modules/6.14.0-rc3+/kernel/drivers/net/ethernet/intel/igbvf/igbvf.ko -L igbvf_reset
<igbvf_reset@/home/test/kernel-ark/drivers/net/ethernet/intel/igbvf/netdev.c:0>
      0  static void igbvf_reset(struct igbvf_adapter *adapter)
         {
      2         struct e1000_mac_info *mac = &adapter->hw.mac;
                struct net_device *netdev = adapter->netdev;
                struct e1000_hw *hw = &adapter->hw;
         
                spin_lock_bh(&hw->mbx_lock);
         
                /* Allow time for pending master requests to run */
      9         if (mac->ops.reset_hw(hw))
     10                 dev_info(&adapter->pdev->dev, "PF still resetting\n");
         
     12         mac->ops.init_hw(hw);
         
     14         spin_unlock_bh(&hw->mbx_lock);
         
     16         if (is_valid_ether_addr(adapter->hw.mac.addr)) {
     17                 eth_hw_addr_set(netdev, adapter->hw.mac.addr);
     18                 memcpy(netdev->perm_addr, adapter->hw.mac.addr,
                               netdev->addr_len);
                }
         
     22         adapter->last_reset = jiffies;
         }
         
         int igbvf_up(struct igbvf_adapter *adapter)

$ perf probe -m /lib/modules/6.14.0-rc3+/kernel/drivers/net/ethernet/intel/igbvf/igbvf.ko igbvf_reset:14
Added new event:
  probe:igbvf_reset_L14 (on igbvf_reset:14 in igbvf)

You can now use it in all perf tools, such as:

        perf record -e probe:igbvf_reset_L14 -aR sleep 1

$ perf probe -m /lib/modules/6.14.0-rc3+/kernel/drivers/net/ethernet/intel/igbvf/igbvf.ko igbvf_reset:16
Added new event:
  probe:igbvf_reset_L16 (on igbvf_reset:16 in igbvf)

They are intended to monitor the effect of spin_unlock_bh().

This is the trace-cmd command line I ran:

$ trace-cmd start -p function -l 'e1000*' -l 'igb*' -l process_one_work -e irq:irq_handler_entry -e probe
  plugin 'function'

The threaded interrupt handler is called right after (during?)
spin_unlock_bh(). I wonder what the 'f' means in the preempt-count
field there.

I am currently working on something else that has a higher priority, so
I don't have time right now to go deeper on that. But feel free to ask
me for any test or trace you may need.

Sebastian