irq pipeline: Netdev watchdog triggered

irq pipeline: Netdev watchdog triggered

[Bezdeka, Florian]

Hi,

here is another IRQ_PIPELINE problem we're facing on on of our quite
big Xenomai machines: 

Platform:
Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
2 Sockets, 6 cores per socket, 2 threads per core
(2 NUMA nodes)

As soon as we enable CONFIG_IRQ_PIPELINE the netdev watchdog triggers.
There is no specific load on the system. In most cases the watchdog
triggers right after booting up. There is no xenomai task running when
the crash happens.

The problem was detected during reboot tests. Disabling
CONFIG_IRQ_PIPELINE helped. We didn't run into a problem for >400
reboots.

Any advise how to debug that? Dovetail torture tests have already been
run and there was no error reported. CONFIG_DEBUG_IRQ_PIPELINE is
enabled as well and did not help so far.

The stacktrace follows but I guess it's not really helpful:

------------[ cut here ]------------
[   42.114151] NETDEV WATCHDOG: enp7s0f0 (igb): transmit queue 5 timed out
[   42.114173] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
[   42.163593] Modules linked in: overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx hid_generic usbhid hid raid6_pq libcrc32c raid1 raid0 multipath linear lpc_ich ahci i2c_i801 xhci_pci i2c_smbus mfd_core libahci mpt3sas igb i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
[   42.435191] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.61-dovetaildbg-noxeno-pipedbg-0 #1
[   42.486198] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
[   42.546050] IRQ stage: Linux
[   42.563263] RIP: 0010:dev_watchdog+0x205/0x210
[   42.589837] Code: 91 26 fe ff eb b1 4c 89 ef c6 05 9e 1d b7 00 01 e8 90 86 fb ff 44 89 e1 4c 89 ee 48 c7 c7 48 41 de b7 48 89 c2 e8 8a c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
[   42.702205] RSP: 0018:ffff9ff4c0003ec0 EFLAGS: 00010282
[   42.733459] RAX: 0000000000000000 RBX: ffff930cc42438c0 RCX: 4000000000000002
[   42.776148] RDX: 4000000000000004 RSI: 0000000000000000 RDI: ffffffffb70cb824
[   42.818841] RBP: ffff930cc7e903b8 R08: 000000000007daee R09: ffff9ff4c0003cc8
[   42.861531] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000006
[   42.904224] R13: ffff930cc7e90000 R14: ffffffffb7686860 R15: ffff9ff4c0003f18
[   42.946916] FS:  0000000000000000(0000) GS:ffff931bff800000(0000) knlGS:0000000000000000
[   42.995328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   43.029700] CR2: 000000c000e50000 CR3: 00000001057ca001 CR4: 00000000001706f0
[   43.072391] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   43.115082] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[   43.157774] Call Trace:
[   43.172388]  <IRQ>
[   43.184400]  ? pfifo_fast_dequeue+0x1e0/0x1e0
[   43.210453]  call_timer_fn+0x2b/0x100
[   43.232344]  __run_timers.part.0+0x1d9/0x250
[   43.257879]  ? ktime_get+0x35/0x90
[   43.278205]  run_timer_softirq+0x26/0x50
[   43.301661]  __do_softirq+0x105/0x30b
[   43.323550]  asm_call_irq_on_stack+0xf/0x20
[   43.348562]  </IRQ>
[   43.361099]  do_softirq_own_stack+0x37/0x40
[   43.386108]  irq_exit_rcu+0xaa/0xe0
[   43.406960]  arch_do_IRQ_pipelined+0x78/0x130
[   43.433012]  sync_current_irq_stage+0x177/0x250
[   43.460100]  __inband_irq_enable+0x4c/0x50
[   43.484593]  cpuidle_enter_state+0x100/0x3a0
[   43.510125]  cpuidle_enter+0x29/0x40
[   43.531498]  do_idle+0x1eb/0x230
[   43.550787]  cpu_startup_entry+0x19/0x20
[   43.574241]  start_kernel+0x56d/0x590
[   43.596134]  secondary_startup_64_no_verify+0xb0/0xbb
[   43.626343] ---[ end trace b219258fce8dc761 ]---
[   43.654095] igb 0000:07:00.0 enp7s0f0: Reset adapter
[   46.090948] igb 0000:07:00.0: exceed max 2 second

Best regards,
Florian

-- 
Siemens AG, T RDA IOT
Corporate Competence Center Embedded Linux

Re: irq pipeline: Netdev watchdog triggered

[Jan Kiszka]

On 06.09.21 14:58, Bezdeka, Florian (T RDA IOT SES-DE) wrote:
> Hi,
> 
> here is another IRQ_PIPELINE problem we're facing on on of our quite
> big Xenomai machines:
> 
> Platform:
> Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
> 2 Sockets, 6 cores per socket, 2 threads per core
> (2 NUMA nodes)
> 
> As soon as we enable CONFIG_IRQ_PIPELINE the netdev watchdog triggers.
> There is no specific load on the system. In most cases the watchdog
> triggers right after booting up. There is no xenomai task running when
> the crash happens.
> 
> The problem was detected during reboot tests. Disabling
> CONFIG_IRQ_PIPELINE helped. We didn't run into a problem for >400
> reboots.
> 
> Any advise how to debug that? Dovetail torture tests have already been
> run and there was no error reported. CONFIG_DEBUG_IRQ_PIPELINE is
> enabled as well and did not help so far.
> 
> The stacktrace follows but I guess it's not really helpful:
> 
> ------------[ cut here ]------------
> [   42.114151] NETDEV WATCHDOG: enp7s0f0 (igb): transmit queue 5 timed out
> [   42.114173] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
> [   42.163593] Modules linked in: overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx hid_generic usbhid hid raid6_pq libcrc32c raid1 raid0 multipath linear lpc_ich ahci i2c_i801 xhci_pci i2c_smbus mfd_core libahci mpt3sas igb i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
> [   42.435191] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.61-dovetaildbg-noxeno-pipedbg-0 #1
> [   42.486198] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
> [   42.546050] IRQ stage: Linux
> [   42.563263] RIP: 0010:dev_watchdog+0x205/0x210
> [   42.589837] Code: 91 26 fe ff eb b1 4c 89 ef c6 05 9e 1d b7 00 01 e8 90 86 fb ff 44 89 e1 4c 89 ee 48 c7 c7 48 41 de b7 48 89 c2 e8 8a c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
> [   42.702205] RSP: 0018:ffff9ff4c0003ec0 EFLAGS: 00010282
> [   42.733459] RAX: 0000000000000000 RBX: ffff930cc42438c0 RCX: 4000000000000002
> [   42.776148] RDX: 4000000000000004 RSI: 0000000000000000 RDI: ffffffffb70cb824
> [   42.818841] RBP: ffff930cc7e903b8 R08: 000000000007daee R09: ffff9ff4c0003cc8
> [   42.861531] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000006
> [   42.904224] R13: ffff930cc7e90000 R14: ffffffffb7686860 R15: ffff9ff4c0003f18
> [   42.946916] FS:  0000000000000000(0000) GS:ffff931bff800000(0000) knlGS:0000000000000000
> [   42.995328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   43.029700] CR2: 000000c000e50000 CR3: 00000001057ca001 CR4: 00000000001706f0
> [   43.072391] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [   43.115082] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [   43.157774] Call Trace:
> [   43.172388]  <IRQ>
> [   43.184400]  ? pfifo_fast_dequeue+0x1e0/0x1e0
> [   43.210453]  call_timer_fn+0x2b/0x100
> [   43.232344]  __run_timers.part.0+0x1d9/0x250
> [   43.257879]  ? ktime_get+0x35/0x90
> [   43.278205]  run_timer_softirq+0x26/0x50
> [   43.301661]  __do_softirq+0x105/0x30b
> [   43.323550]  asm_call_irq_on_stack+0xf/0x20
> [   43.348562]  </IRQ>
> [   43.361099]  do_softirq_own_stack+0x37/0x40
> [   43.386108]  irq_exit_rcu+0xaa/0xe0
> [   43.406960]  arch_do_IRQ_pipelined+0x78/0x130
> [   43.433012]  sync_current_irq_stage+0x177/0x250
> [   43.460100]  __inband_irq_enable+0x4c/0x50
> [   43.484593]  cpuidle_enter_state+0x100/0x3a0
> [   43.510125]  cpuidle_enter+0x29/0x40
> [   43.531498]  do_idle+0x1eb/0x230
> [   43.550787]  cpu_startup_entry+0x19/0x20
> [   43.574241]  start_kernel+0x56d/0x590
> [   43.596134]  secondary_startup_64_no_verify+0xb0/0xbb
> [   43.626343] ---[ end trace b219258fce8dc761 ]---
> [   43.654095] igb 0000:07:00.0 enp7s0f0: Reset adapter
> [   46.090948] igb 0000:07:00.0: exceed max 2 second
> 

This is just the warning from the NIC watchdog handler. What we still
need to find out is the health of other NIC interrupts around this
event. Also if other interrupts are possibly affected as well or just
one or more of the device.

BTW, can we recover the device by ifdown/up? Or by driver unbind/bind?

Jan

-- 
Siemens AG, T RDA IOT
Corporate Competence Center Embedded Linux

Re: irq pipeline: Netdev watchdog triggered

[Philippe Gerum]

Bezdeka, Florian <florian.bezdeka@siemens.com> writes:

> Hi,
>
> here is another IRQ_PIPELINE problem we're facing on on of our quite
> big Xenomai machines: 
>
> Platform:
> Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
> 2 Sockets, 6 cores per socket, 2 threads per core
> (2 NUMA nodes)
>
> As soon as we enable CONFIG_IRQ_PIPELINE the netdev watchdog triggers.
> There is no specific load on the system. In most cases the watchdog
> triggers right after booting up. There is no xenomai task running when
> the crash happens.
>
> The problem was detected during reboot tests. Disabling
> CONFIG_IRQ_PIPELINE helped. We didn't run into a problem for >400
> reboots.
>
> Any advise how to debug that? Dovetail torture tests have already been
> run and there was no error reported. CONFIG_DEBUG_IRQ_PIPELINE is
> enabled as well and did not help so far.
>
> The stacktrace follows but I guess it's not really helpful:
>
> ------------[ cut here ]------------
> [   42.114151] NETDEV WATCHDOG: enp7s0f0 (igb): transmit queue 5 timed out
> [   42.114173] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
> [   42.163593] Modules linked in: overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx hid_generic usbhid hid raid6_pq libcrc32c raid1 raid0 multipath linear lpc_ich ahci i2c_i801 xhci_pci i2c_smbus mfd_core libahci mpt3sas igb i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
> [   42.435191] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.61-dovetaildbg-noxeno-pipedbg-0 #1
> [   42.486198] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
> [   42.546050] IRQ stage: Linux
> [   42.563263] RIP: 0010:dev_watchdog+0x205/0x210
> [   42.589837] Code: 91 26 fe ff eb b1 4c 89 ef c6 05 9e 1d b7 00 01 e8 90 86 fb ff 44 89 e1 4c 89 ee 48 c7 c7 48 41 de b7 48 89 c2 e8 8a c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
> [   42.702205] RSP: 0018:ffff9ff4c0003ec0 EFLAGS: 00010282
> [   42.733459] RAX: 0000000000000000 RBX: ffff930cc42438c0 RCX: 4000000000000002
> [   42.776148] RDX: 4000000000000004 RSI: 0000000000000000 RDI: ffffffffb70cb824
> [   42.818841] RBP: ffff930cc7e903b8 R08: 000000000007daee R09: ffff9ff4c0003cc8
> [   42.861531] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000006
> [   42.904224] R13: ffff930cc7e90000 R14: ffffffffb7686860 R15: ffff9ff4c0003f18
> [   42.946916] FS:  0000000000000000(0000) GS:ffff931bff800000(0000) knlGS:0000000000000000
> [   42.995328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   43.029700] CR2: 000000c000e50000 CR3: 00000001057ca001 CR4: 00000000001706f0
> [   43.072391] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [   43.115082] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [   43.157774] Call Trace:
> [   43.172388]  <IRQ>
> [   43.184400]  ? pfifo_fast_dequeue+0x1e0/0x1e0
> [   43.210453]  call_timer_fn+0x2b/0x100
> [   43.232344]  __run_timers.part.0+0x1d9/0x250
> [   43.257879]  ? ktime_get+0x35/0x90
> [   43.278205]  run_timer_softirq+0x26/0x50
> [   43.301661]  __do_softirq+0x105/0x30b
> [   43.323550]  asm_call_irq_on_stack+0xf/0x20
> [   43.348562]  </IRQ>
> [   43.361099]  do_softirq_own_stack+0x37/0x40
> [   43.386108]  irq_exit_rcu+0xaa/0xe0
> [   43.406960]  arch_do_IRQ_pipelined+0x78/0x130
> [   43.433012]  sync_current_irq_stage+0x177/0x250
> [   43.460100]  __inband_irq_enable+0x4c/0x50
> [   43.484593]  cpuidle_enter_state+0x100/0x3a0
> [   43.510125]  cpuidle_enter+0x29/0x40
> [   43.531498]  do_idle+0x1eb/0x230
> [   43.550787]  cpu_startup_entry+0x19/0x20
> [   43.574241]  start_kernel+0x56d/0x590
> [   43.596134]  secondary_startup_64_no_verify+0xb0/0xbb
> [   43.626343] ---[ end trace b219258fce8dc761 ]---
> [   43.654095] igb 0000:07:00.0 enp7s0f0: Reset adapter
> [   46.090948] igb 0000:07:00.0: exceed max 2 second
>

Might be an interrupt stuck in the in-band log of the pipeline, in which
case the CPU would go idle without synchronizing the log, leaving a
pending IRQ unhandled until the next exit from the idle state. I wonder
if the unstable TSC issue might not be another symptom of that kind of
cause.

Do you see any change when booting with idle=poll?

-- 
Philippe.

Re: irq pipeline: Netdev watchdog triggered

[Bezdeka, Florian]

On Mon, 2021-09-06 at 16:56 +0200, Philippe Gerum wrote:
> Bezdeka, Florian <florian.bezdeka@siemens.com> writes:
> 
> > Hi,
> > 
> > here is another IRQ_PIPELINE problem we're facing on on of our quite
> > big Xenomai machines: 
> > 
> > Platform:
> > Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
> > 2 Sockets, 6 cores per socket, 2 threads per core
> > (2 NUMA nodes)
> > 
> > As soon as we enable CONFIG_IRQ_PIPELINE the netdev watchdog triggers.
> > There is no specific load on the system. In most cases the watchdog
> > triggers right after booting up. There is no xenomai task running when
> > the crash happens.
> > 
> > The problem was detected during reboot tests. Disabling
> > CONFIG_IRQ_PIPELINE helped. We didn't run into a problem for >400
> > reboots.
> > 
> > Any advise how to debug that? Dovetail torture tests have already been
> > run and there was no error reported. CONFIG_DEBUG_IRQ_PIPELINE is
> > enabled as well and did not help so far.
> > 
> > The stacktrace follows but I guess it's not really helpful:
> > 
> > ------------[ cut here ]------------
> > [   42.114151] NETDEV WATCHDOG: enp7s0f0 (igb): transmit queue 5 timed out
> > [   42.114173] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
> > [   42.163593] Modules linked in: overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx hid_generic usbhid hid raid6_pq libcrc32c raid1 raid0 multipath linear lpc_ich ahci i2c_i801 xhci_pci i2c_smbus mfd_core libahci mpt3sas igb i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
> > [   42.435191] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.61-dovetaildbg-noxeno-pipedbg-0 #1
> > [   42.486198] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
> > [   42.546050] IRQ stage: Linux
> > [   42.563263] RIP: 0010:dev_watchdog+0x205/0x210
> > [   42.589837] Code: 91 26 fe ff eb b1 4c 89 ef c6 05 9e 1d b7 00 01 e8 90 86 fb ff 44 89 e1 4c 89 ee 48 c7 c7 48 41 de b7 48 89 c2 e8 8a c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
> > [   42.702205] RSP: 0018:ffff9ff4c0003ec0 EFLAGS: 00010282
> > [   42.733459] RAX: 0000000000000000 RBX: ffff930cc42438c0 RCX: 4000000000000002
> > [   42.776148] RDX: 4000000000000004 RSI: 0000000000000000 RDI: ffffffffb70cb824
> > [   42.818841] RBP: ffff930cc7e903b8 R08: 000000000007daee R09: ffff9ff4c0003cc8
> > [   42.861531] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000006
> > [   42.904224] R13: ffff930cc7e90000 R14: ffffffffb7686860 R15: ffff9ff4c0003f18
> > [   42.946916] FS:  0000000000000000(0000) GS:ffff931bff800000(0000) knlGS:0000000000000000
> > [   42.995328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [   43.029700] CR2: 000000c000e50000 CR3: 00000001057ca001 CR4: 00000000001706f0
> > [   43.072391] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [   43.115082] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [   43.157774] Call Trace:
> > [   43.172388]  <IRQ>
> > [   43.184400]  ? pfifo_fast_dequeue+0x1e0/0x1e0
> > [   43.210453]  call_timer_fn+0x2b/0x100
> > [   43.232344]  __run_timers.part.0+0x1d9/0x250
> > [   43.257879]  ? ktime_get+0x35/0x90
> > [   43.278205]  run_timer_softirq+0x26/0x50
> > [   43.301661]  __do_softirq+0x105/0x30b
> > [   43.323550]  asm_call_irq_on_stack+0xf/0x20
> > [   43.348562]  </IRQ>
> > [   43.361099]  do_softirq_own_stack+0x37/0x40
> > [   43.386108]  irq_exit_rcu+0xaa/0xe0
> > [   43.406960]  arch_do_IRQ_pipelined+0x78/0x130
> > [   43.433012]  sync_current_irq_stage+0x177/0x250
> > [   43.460100]  __inband_irq_enable+0x4c/0x50
> > [   43.484593]  cpuidle_enter_state+0x100/0x3a0
> > [   43.510125]  cpuidle_enter+0x29/0x40
> > [   43.531498]  do_idle+0x1eb/0x230
> > [   43.550787]  cpu_startup_entry+0x19/0x20
> > [   43.574241]  start_kernel+0x56d/0x590
> > [   43.596134]  secondary_startup_64_no_verify+0xb0/0xbb
> > [   43.626343] ---[ end trace b219258fce8dc761 ]---
> > [   43.654095] igb 0000:07:00.0 enp7s0f0: Reset adapter
> > [   46.090948] igb 0000:07:00.0: exceed max 2 second
> > 
> 
> Might be an interrupt stuck in the in-band log of the pipeline, in which
> case the CPU would go idle without synchronizing the log, leaving a
> pending IRQ unhandled until the next exit from the idle state. I wonder
> if the unstable TSC issue might not be another symptom of that kind of
> cause.

That was one of my initial thoughts as well. Maybe it's the timer IRQ
being late, but I was unable to prove that.

> 
> Do you see any change when booting with idle=poll?
> 

Will give it a try... Will take some time, I don't have access to one
of the machines where this issue can be reproduced, so I have to wait
for some colleagues.

Re: irq pipeline: Netdev watchdog triggered

[Bezdeka, Florian]

On Mon, 2021-09-06 at 16:56 +0200, Philippe Gerum wrote:
> Bezdeka, Florian <florian.bezdeka@siemens.com> writes:
> 
> > Hi,
> > 
> > here is another IRQ_PIPELINE problem we're facing on on of our quite
> > big Xenomai machines: 
> > 
> > Platform:
> > Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
> > 2 Sockets, 6 cores per socket, 2 threads per core
> > (2 NUMA nodes)
> > 
> > As soon as we enable CONFIG_IRQ_PIPELINE the netdev watchdog triggers.
> > There is no specific load on the system. In most cases the watchdog
> > triggers right after booting up. There is no xenomai task running when
> > the crash happens.
> > 
> > The problem was detected during reboot tests. Disabling
> > CONFIG_IRQ_PIPELINE helped. We didn't run into a problem for >400
> > reboots.
> > 
> > Any advise how to debug that? Dovetail torture tests have already been
> > run and there was no error reported. CONFIG_DEBUG_IRQ_PIPELINE is
> > enabled as well and did not help so far.
> > 
> > The stacktrace follows but I guess it's not really helpful:
> > 
> > ------------[ cut here ]------------
> > [   42.114151] NETDEV WATCHDOG: enp7s0f0 (igb): transmit queue 5 timed out
> > [   42.114173] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
> > [   42.163593] Modules linked in: overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx hid_generic usbhid hid raid6_pq libcrc32c raid1 raid0 multipath linear lpc_ich ahci i2c_i801 xhci_pci i2c_smbus mfd_core libahci mpt3sas igb i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
> > [   42.435191] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.61-dovetaildbg-noxeno-pipedbg-0 #1
> > [   42.486198] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
> > [   42.546050] IRQ stage: Linux
> > [   42.563263] RIP: 0010:dev_watchdog+0x205/0x210
> > [   42.589837] Code: 91 26 fe ff eb b1 4c 89 ef c6 05 9e 1d b7 00 01 e8 90 86 fb ff 44 89 e1 4c 89 ee 48 c7 c7 48 41 de b7 48 89 c2 e8 8a c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
> > [   42.702205] RSP: 0018:ffff9ff4c0003ec0 EFLAGS: 00010282
> > [   42.733459] RAX: 0000000000000000 RBX: ffff930cc42438c0 RCX: 4000000000000002
> > [   42.776148] RDX: 4000000000000004 RSI: 0000000000000000 RDI: ffffffffb70cb824
> > [   42.818841] RBP: ffff930cc7e903b8 R08: 000000000007daee R09: ffff9ff4c0003cc8
> > [   42.861531] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000006
> > [   42.904224] R13: ffff930cc7e90000 R14: ffffffffb7686860 R15: ffff9ff4c0003f18
> > [   42.946916] FS:  0000000000000000(0000) GS:ffff931bff800000(0000) knlGS:0000000000000000
> > [   42.995328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [   43.029700] CR2: 000000c000e50000 CR3: 00000001057ca001 CR4: 00000000001706f0
> > [   43.072391] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [   43.115082] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [   43.157774] Call Trace:
> > [   43.172388]  <IRQ>
> > [   43.184400]  ? pfifo_fast_dequeue+0x1e0/0x1e0
> > [   43.210453]  call_timer_fn+0x2b/0x100
> > [   43.232344]  __run_timers.part.0+0x1d9/0x250
> > [   43.257879]  ? ktime_get+0x35/0x90
> > [   43.278205]  run_timer_softirq+0x26/0x50
> > [   43.301661]  __do_softirq+0x105/0x30b
> > [   43.323550]  asm_call_irq_on_stack+0xf/0x20
> > [   43.348562]  </IRQ>
> > [   43.361099]  do_softirq_own_stack+0x37/0x40
> > [   43.386108]  irq_exit_rcu+0xaa/0xe0
> > [   43.406960]  arch_do_IRQ_pipelined+0x78/0x130
> > [   43.433012]  sync_current_irq_stage+0x177/0x250
> > [   43.460100]  __inband_irq_enable+0x4c/0x50
> > [   43.484593]  cpuidle_enter_state+0x100/0x3a0
> > [   43.510125]  cpuidle_enter+0x29/0x40
> > [   43.531498]  do_idle+0x1eb/0x230
> > [   43.550787]  cpu_startup_entry+0x19/0x20
> > [   43.574241]  start_kernel+0x56d/0x590
> > [   43.596134]  secondary_startup_64_no_verify+0xb0/0xbb
> > [   43.626343] ---[ end trace b219258fce8dc761 ]---
> > [   43.654095] igb 0000:07:00.0 enp7s0f0: Reset adapter
> > [   46.090948] igb 0000:07:00.0: exceed max 2 second
> > 
> 
> Might be an interrupt stuck in the in-band log of the pipeline, in which
> case the CPU would go idle without synchronizing the log, leaving a
> pending IRQ unhandled until the next exit from the idle state. I wonder
> if the unstable TSC issue might not be another symptom of that kind of
> cause.
> 
> Do you see any change when booting with idle=poll?
> 

The call stack looks different with idle=poll, as expected:

[   48.752335] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
[   48.801769] Modules linked in: sha512_ssse3 sha512_generic cmac sha256_ssse3 sha256_generic libsha256 hmac nls_cp437 cifs libdes libarc4 xt_conntrack xt_MASQUERADE xfrm_user xfrm_algo xt_addrtype iptable_filter iptable_nat nf_nat nf_conn                track nf_defrag_ipv6 nf_defrag_ipv4 br_netfilter bridge stp llc overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 hid_generic usbhid hid raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx raid6_pq libcrc32c raid1 raid0 multipath linear i2c_i801 lpc_ich i2c_smbus ahci igb mfd_core xhci_pci libahci mpt3sas i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
[   49.213706] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.53-xenomai-0 #1
[   49.254843] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
[   49.314694] IRQ stage: Linux
[   49.331907] RIP: 0010:dev_watchdog+0x205/0x210
[   49.358477] Code: b1 26 fe ff eb b1 4c 89 ef c6 05 fb 23 b4 00 01 e8 d0 87 fb ff 44 89 e1 4c 89 ee 48 c7 c7 18 09 df b9 48 89 c2 e8 c3 c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
[   49.470849] RSP: 0018:ffffa041c0003ec0 EFLAGS: 00010282
[   49.470851] RAX: 0000000000000000 RBX: ffff90ca43edb8c0 RCX: ffff90c9ff817948
[   49.470852] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff90c9ff817940
[   49.470854] RBP: ffff90bac76e03b8 R08: ffffffffba139e28 R09: 0000000000009ffb
[   49.470857] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000002
[   49.672860] R13: ffff90bac76e0000 R14: ffffffffb96ca7a0 R15: ffffa041c0003f18
[   49.723877] FS:  0000000000000000(0000) GS:ffff90c9ff800000(0000) knlGS:0000000000000000
[   49.780606] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   49.823302] CR2: 00007f96466f7048 CR3: 0000001087a60006 CR4: 00000000001706f0
[   49.868591] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   49.911284] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[   49.953977] Call Trace:
[   49.968593]  <IRQ>
[   49.980597]  ? pfifo_fast_dequeue+0x1e0/0x1e0
[   50.006654]  call_timer_fn+0x2b/0x100
[   50.028544]  __run_timers.part.0+0x1d9/0x250
[   50.054078]  ? proxy_set_next_ktime+0x155/0x180
[   50.081163]  run_timer_softirq+0x26/0x50
[   50.104620]  __do_softirq+0x105/0x30b
[   50.126512]  asm_call_irq_on_stack+0xf/0x20
[   50.151518]  </IRQ>
[   50.164059]  do_softirq_own_stack+0x37/0x40
[   50.189067]  irq_exit_rcu+0xaa/0xe0
[   50.209920]  arch_do_IRQ_pipelined+0xbf/0x130
[   50.235974]  sync_current_irq_stage+0x157/0x1f0
[   50.263061]  handle_irq_pipelined_finish+0x8b/0x190
[   50.292240]  arch_pipeline_entry+0xb0/0x100
[   50.317247]  asm_sysvec_apic_timer_interrupt+0xf/0x20
[   50.347459] RIP: 0010:cpu_idle_poll.isra.0+0x46/0xe0
[   50.377147] Code: 40 3a 99 ff e8 8b 7c 92 ff e8 06 2b 99 ff 65 48 8b 1c 25 c0 6c 01 00 e8 c8 be 91 ff 48 8b 03 a8 08                 74 0b eb 1c f3 90 48 8b 03 <a8> 08 75 13 8b 05 e0 35 a7 00 85 c0 75 ed e8 07 61 94 ff 85 c0 75
[   50.489518] RSP: 0018:ffffffffba003eb8 EFLAGS: 00000202
[   50.520767] RAX: 0000000000204000 RBX: ffffffffba011940 RCX: 000000000000001f
[   50.563463] RDX: 000000001bbb4d5a RSI: 0000000000000000 RDI: ffffffffb97afefa
[   50.606154] RBP: 0000000000000000 R08: 000000001bbb4d5a R09: 0000000000000000
[   50.648840] R10: 0000000000001400 R11: 0000000000000000 R12: 00000000000000ac
[   50.691537] R13: ffffffffba6150a0 R14: 0000000000000001 R15: 0000000000000008
[   50.734226]  ? cpu_idle_poll.isra.0+0x2a/0xe0
[   50.760278]  ? cpu_idle_poll.isra.0+0x38/0xe0
[   50.786336]  do_idle+0x7e/0x200

Where would be the right place to add a warning when one of the CPUs
tries to enter the idle state with pending IRQs?

Re: irq pipeline: Netdev watchdog triggered

[Philippe Gerum]

Bezdeka, Florian <florian.bezdeka@siemens.com> writes:

> On Mon, 2021-09-06 at 16:56 +0200, Philippe Gerum wrote:
>> Bezdeka, Florian <florian.bezdeka@siemens.com> writes:
>> 
>> > Hi,
>> > 
>> > here is another IRQ_PIPELINE problem we're facing on on of our quite
>> > big Xenomai machines: 
>> > 
>> > Platform:
>> > Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
>> > 2 Sockets, 6 cores per socket, 2 threads per core
>> > (2 NUMA nodes)
>> > 
>> > As soon as we enable CONFIG_IRQ_PIPELINE the netdev watchdog triggers.
>> > There is no specific load on the system. In most cases the watchdog
>> > triggers right after booting up. There is no xenomai task running when
>> > the crash happens.
>> > 
>> > The problem was detected during reboot tests. Disabling
>> > CONFIG_IRQ_PIPELINE helped. We didn't run into a problem for >400
>> > reboots.
>> > 
>> > Any advise how to debug that? Dovetail torture tests have already been
>> > run and there was no error reported. CONFIG_DEBUG_IRQ_PIPELINE is
>> > enabled as well and did not help so far.
>> > 
>> > The stacktrace follows but I guess it's not really helpful:
>> > 
>> > ------------[ cut here ]------------
>> > [   42.114151] NETDEV WATCHDOG: enp7s0f0 (igb): transmit queue 5 timed out
>> > [   42.114173] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
>> > [   42.163593] Modules linked in: overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx hid_generic usbhid hid raid6_pq libcrc32c raid1 raid0 multipath linear lpc_ich ahci i2c_i801 xhci_pci i2c_smbus mfd_core libahci mpt3sas igb i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
>> > [   42.435191] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.61-dovetaildbg-noxeno-pipedbg-0 #1
>> > [   42.486198] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
>> > [   42.546050] IRQ stage: Linux
>> > [   42.563263] RIP: 0010:dev_watchdog+0x205/0x210
>> > [   42.589837] Code: 91 26 fe ff eb b1 4c 89 ef c6 05 9e 1d b7 00 01 e8 90 86 fb ff 44 89 e1 4c 89 ee 48 c7 c7 48 41 de b7 48 89 c2 e8 8a c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
>> > [   42.702205] RSP: 0018:ffff9ff4c0003ec0 EFLAGS: 00010282
>> > [   42.733459] RAX: 0000000000000000 RBX: ffff930cc42438c0 RCX: 4000000000000002
>> > [   42.776148] RDX: 4000000000000004 RSI: 0000000000000000 RDI: ffffffffb70cb824
>> > [   42.818841] RBP: ffff930cc7e903b8 R08: 000000000007daee R09: ffff9ff4c0003cc8
>> > [   42.861531] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000006
>> > [   42.904224] R13: ffff930cc7e90000 R14: ffffffffb7686860 R15: ffff9ff4c0003f18
>> > [   42.946916] FS:  0000000000000000(0000) GS:ffff931bff800000(0000) knlGS:0000000000000000
>> > [   42.995328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> > [   43.029700] CR2: 000000c000e50000 CR3: 00000001057ca001 CR4: 00000000001706f0
>> > [   43.072391] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> > [   43.115082] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
>> > [   43.157774] Call Trace:
>> > [   43.172388]  <IRQ>
>> > [   43.184400]  ? pfifo_fast_dequeue+0x1e0/0x1e0
>> > [   43.210453]  call_timer_fn+0x2b/0x100
>> > [   43.232344]  __run_timers.part.0+0x1d9/0x250
>> > [   43.257879]  ? ktime_get+0x35/0x90
>> > [   43.278205]  run_timer_softirq+0x26/0x50
>> > [   43.301661]  __do_softirq+0x105/0x30b
>> > [   43.323550]  asm_call_irq_on_stack+0xf/0x20
>> > [   43.348562]  </IRQ>
>> > [   43.361099]  do_softirq_own_stack+0x37/0x40
>> > [   43.386108]  irq_exit_rcu+0xaa/0xe0
>> > [   43.406960]  arch_do_IRQ_pipelined+0x78/0x130
>> > [   43.433012]  sync_current_irq_stage+0x177/0x250
>> > [   43.460100]  __inband_irq_enable+0x4c/0x50
>> > [   43.484593]  cpuidle_enter_state+0x100/0x3a0
>> > [   43.510125]  cpuidle_enter+0x29/0x40
>> > [   43.531498]  do_idle+0x1eb/0x230
>> > [   43.550787]  cpu_startup_entry+0x19/0x20
>> > [   43.574241]  start_kernel+0x56d/0x590
>> > [   43.596134]  secondary_startup_64_no_verify+0xb0/0xbb
>> > [   43.626343] ---[ end trace b219258fce8dc761 ]---
>> > [   43.654095] igb 0000:07:00.0 enp7s0f0: Reset adapter
>> > [   46.090948] igb 0000:07:00.0: exceed max 2 second
>> > 
>> 
>> Might be an interrupt stuck in the in-band log of the pipeline, in which
>> case the CPU would go idle without synchronizing the log, leaving a
>> pending IRQ unhandled until the next exit from the idle state. I wonder
>> if the unstable TSC issue might not be another symptom of that kind of
>> cause.
>> 
>> Do you see any change when booting with idle=poll?
>> 
>
> The call stack looks different with idle=poll, as expected:
>
> [   48.752335] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
> [   48.801769] Modules linked in: sha512_ssse3 sha512_generic cmac sha256_ssse3 sha256_generic libsha256 hmac nls_cp437 cifs libdes libarc4 xt_conntrack xt_MASQUERADE xfrm_user xfrm_algo xt_addrtype iptable_filter iptable_nat nf_nat nf_conn                track nf_defrag_ipv6 nf_defrag_ipv4 br_netfilter bridge stp llc overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 hid_generic usbhid hid raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx raid6_pq libcrc32c raid1 raid0 multipath linear i2c_i801 lpc_ich i2c_smbus ahci igb mfd_core xhci_pci libahci mpt3sas i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
> [   49.213706] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.53-xenomai-0 #1
> [   49.254843] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
> [   49.314694] IRQ stage: Linux
> [   49.331907] RIP: 0010:dev_watchdog+0x205/0x210
> [   49.358477] Code: b1 26 fe ff eb b1 4c 89 ef c6 05 fb 23 b4 00 01 e8 d0 87 fb ff 44 89 e1 4c 89 ee 48 c7 c7 18 09 df b9 48 89 c2 e8 c3 c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
> [   49.470849] RSP: 0018:ffffa041c0003ec0 EFLAGS: 00010282
> [   49.470851] RAX: 0000000000000000 RBX: ffff90ca43edb8c0 RCX: ffff90c9ff817948
> [   49.470852] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff90c9ff817940
> [   49.470854] RBP: ffff90bac76e03b8 R08: ffffffffba139e28 R09: 0000000000009ffb
> [   49.470857] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000002
> [   49.672860] R13: ffff90bac76e0000 R14: ffffffffb96ca7a0 R15: ffffa041c0003f18
> [   49.723877] FS:  0000000000000000(0000) GS:ffff90c9ff800000(0000) knlGS:0000000000000000
> [   49.780606] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   49.823302] CR2: 00007f96466f7048 CR3: 0000001087a60006 CR4: 00000000001706f0
> [   49.868591] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [   49.911284] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [   49.953977] Call Trace:
> [   49.968593]  <IRQ>
> [   49.980597]  ? pfifo_fast_dequeue+0x1e0/0x1e0
> [   50.006654]  call_timer_fn+0x2b/0x100
> [   50.028544]  __run_timers.part.0+0x1d9/0x250
> [   50.054078]  ? proxy_set_next_ktime+0x155/0x180
> [   50.081163]  run_timer_softirq+0x26/0x50
> [   50.104620]  __do_softirq+0x105/0x30b
> [   50.126512]  asm_call_irq_on_stack+0xf/0x20
> [   50.151518]  </IRQ>
> [   50.164059]  do_softirq_own_stack+0x37/0x40
> [   50.189067]  irq_exit_rcu+0xaa/0xe0
> [   50.209920]  arch_do_IRQ_pipelined+0xbf/0x130
> [   50.235974]  sync_current_irq_stage+0x157/0x1f0
> [   50.263061]  handle_irq_pipelined_finish+0x8b/0x190
> [   50.292240]  arch_pipeline_entry+0xb0/0x100
> [   50.317247]  asm_sysvec_apic_timer_interrupt+0xf/0x20
> [   50.347459] RIP: 0010:cpu_idle_poll.isra.0+0x46/0xe0
> [   50.377147] Code: 40 3a 99 ff e8 8b 7c 92 ff e8 06 2b 99 ff 65 48 8b 1c 25 c0 6c 01 00 e8 c8 be 91 ff 48 8b 03 a8 08                 74 0b eb 1c f3 90 48 8b 03 <a8> 08 75 13 8b 05 e0 35 a7 00 85 c0 75 ed e8 07 61 94 ff 85 c0 75
> [   50.489518] RSP: 0018:ffffffffba003eb8 EFLAGS: 00000202
> [   50.520767] RAX: 0000000000204000 RBX: ffffffffba011940 RCX: 000000000000001f
> [   50.563463] RDX: 000000001bbb4d5a RSI: 0000000000000000 RDI: ffffffffb97afefa
> [   50.606154] RBP: 0000000000000000 R08: 000000001bbb4d5a R09: 0000000000000000
> [   50.648840] R10: 0000000000001400 R11: 0000000000000000 R12: 00000000000000ac
> [   50.691537] R13: ffffffffba6150a0 R14: 0000000000000001 R15: 0000000000000008
> [   50.734226]  ? cpu_idle_poll.isra.0+0x2a/0xe0
> [   50.760278]  ? cpu_idle_poll.isra.0+0x38/0xe0
> [   50.786336]  do_idle+0x7e/0x200
>
> Where would be the right place to add a warning when one of the CPUs
> tries to enter the idle state with pending IRQs?

Something like this:

diff --git a/include/linux/irq_pipeline.h b/include/linux/irq_pipeline.h
index cbeb0109fa7ff47..17436e10e620072 100644
--- a/include/linux/irq_pipeline.h
+++ b/include/linux/irq_pipeline.h
@@ -88,6 +88,8 @@ int handle_irq_pipelined(struct pt_regs *regs);
 
 void sync_inband_irqs(void);
 
+bool irq_is_pending(void);
+
 extern struct irq_domain *synthetic_irq_domain;
 
 #else /* !CONFIG_IRQ_PIPELINE */
@@ -134,6 +136,11 @@ static inline bool inband_irq_pending(void)
 
 static inline void sync_inband_irqs(void) { }
 
+static inline bool irq_is_pending(void)
+{
+	return false;
+}
+
 #endif /* !CONFIG_IRQ_PIPELINE */
 
 #if !defined(CONFIG_IRQ_PIPELINE) || !defined(CONFIG_SPARSE_IRQ)
diff --git a/kernel/irq/pipeline.c b/kernel/irq/pipeline.c
index c4974a8d7244dec..116214690d47cda 100644
--- a/kernel/irq/pipeline.c
+++ b/kernel/irq/pipeline.c
@@ -1575,6 +1575,18 @@ bool irq_cpuidle_enter(struct cpuidle_device *dev,
 	return irq_cpuidle_control(dev, state);
 }
 
+bool irq_is_pending(void)
+{
+	unsigned long flags;
+	bool ret;
+
+	flags = hard_local_irq_save();
+	ret = inband_irq_pending();
+	hard_local_irq_restore(flags);
+
+	return ret;
+}
+
 static unsigned int inband_work_sirq;
 
 static irqreturn_t inband_work_interrupt(int sirq, void *dev_id)
diff --git a/kernel/sched/idle.c b/kernel/sched/idle.c
index e8bb54eeb0c98af..702e08143108881 100644
--- a/kernel/sched/idle.c
+++ b/kernel/sched/idle.c
@@ -115,6 +115,7 @@ void __cpuidle default_idle_call(void)
 		rcu_idle_enter();
 		lockdep_hardirqs_on(_THIS_IP_);
 
+		WARN_ON_ONCE(irq_is_pending());
 		arch_cpu_idle();
 
 		/*
@@ -252,6 +253,7 @@ static void cpuidle_idle_call(void)
 	}
 
 exit_idle:
+	WARN_ON_ONCE(irq_is_pending());
 	__current_set_polling();
 
 	/*
-- 
Philippe.

Re: irq pipeline: Netdev watchdog triggered

[Bezdeka, Florian]

On Mon, 2021-09-06 at 18:16 +0200, Philippe Gerum wrote:
> Bezdeka, Florian <florian.bezdeka@siemens.com> writes:
> 
> > On Mon, 2021-09-06 at 16:56 +0200, Philippe Gerum wrote:
> > > Bezdeka, Florian <florian.bezdeka@siemens.com> writes:
> > > 
> > > > Hi,
> > > > 
> > > > here is another IRQ_PIPELINE problem we're facing on on of our quite
> > > > big Xenomai machines: 
> > > > 
> > > > Platform:
> > > > Intel(R) Xeon(R) CPU E5-2620 0 @ 2.00GHz
> > > > 2 Sockets, 6 cores per socket, 2 threads per core
> > > > (2 NUMA nodes)
> > > > 
> > > > As soon as we enable CONFIG_IRQ_PIPELINE the netdev watchdog triggers.
> > > > There is no specific load on the system. In most cases the watchdog
> > > > triggers right after booting up. There is no xenomai task running when
> > > > the crash happens.
> > > > 
> > > > The problem was detected during reboot tests. Disabling
> > > > CONFIG_IRQ_PIPELINE helped. We didn't run into a problem for >400
> > > > reboots.
> > > > 
> > > > Any advise how to debug that? Dovetail torture tests have already been
> > > > run and there was no error reported. CONFIG_DEBUG_IRQ_PIPELINE is
> > > > enabled as well and did not help so far.
> > > > 
> > > > The stacktrace follows but I guess it's not really helpful:
> > > > 
> > > > ------------[ cut here ]------------
> > > > [   42.114151] NETDEV WATCHDOG: enp7s0f0 (igb): transmit queue 5 timed out
> > > > [   42.114173] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
> > > > [   42.163593] Modules linked in: overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx hid_generic usbhid hid raid6_pq libcrc32c raid1 raid0 multipath linear lpc_ich ahci i2c_i801 xhci_pci i2c_smbus mfd_core libahci mpt3sas igb i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
> > > > [   42.435191] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.61-dovetaildbg-noxeno-pipedbg-0 #1
> > > > [   42.486198] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
> > > > [   42.546050] IRQ stage: Linux
> > > > [   42.563263] RIP: 0010:dev_watchdog+0x205/0x210
> > > > [   42.589837] Code: 91 26 fe ff eb b1 4c 89 ef c6 05 9e 1d b7 00 01 e8 90 86 fb ff 44 89 e1 4c 89 ee 48 c7 c7 48 41 de b7 48 89 c2 e8 8a c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
> > > > [   42.702205] RSP: 0018:ffff9ff4c0003ec0 EFLAGS: 00010282
> > > > [   42.733459] RAX: 0000000000000000 RBX: ffff930cc42438c0 RCX: 4000000000000002
> > > > [   42.776148] RDX: 4000000000000004 RSI: 0000000000000000 RDI: ffffffffb70cb824
> > > > [   42.818841] RBP: ffff930cc7e903b8 R08: 000000000007daee R09: ffff9ff4c0003cc8
> > > > [   42.861531] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000006
> > > > [   42.904224] R13: ffff930cc7e90000 R14: ffffffffb7686860 R15: ffff9ff4c0003f18
> > > > [   42.946916] FS:  0000000000000000(0000) GS:ffff931bff800000(0000) knlGS:0000000000000000
> > > > [   42.995328] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > > [   43.029700] CR2: 000000c000e50000 CR3: 00000001057ca001 CR4: 00000000001706f0
> > > > [   43.072391] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > > > [   43.115082] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > > > [   43.157774] Call Trace:
> > > > [   43.172388]  <IRQ>
> > > > [   43.184400]  ? pfifo_fast_dequeue+0x1e0/0x1e0
> > > > [   43.210453]  call_timer_fn+0x2b/0x100
> > > > [   43.232344]  __run_timers.part.0+0x1d9/0x250
> > > > [   43.257879]  ? ktime_get+0x35/0x90
> > > > [   43.278205]  run_timer_softirq+0x26/0x50
> > > > [   43.301661]  __do_softirq+0x105/0x30b
> > > > [   43.323550]  asm_call_irq_on_stack+0xf/0x20
> > > > [   43.348562]  </IRQ>
> > > > [   43.361099]  do_softirq_own_stack+0x37/0x40
> > > > [   43.386108]  irq_exit_rcu+0xaa/0xe0
> > > > [   43.406960]  arch_do_IRQ_pipelined+0x78/0x130
> > > > [   43.433012]  sync_current_irq_stage+0x177/0x250
> > > > [   43.460100]  __inband_irq_enable+0x4c/0x50
> > > > [   43.484593]  cpuidle_enter_state+0x100/0x3a0
> > > > [   43.510125]  cpuidle_enter+0x29/0x40
> > > > [   43.531498]  do_idle+0x1eb/0x230
> > > > [   43.550787]  cpu_startup_entry+0x19/0x20
> > > > [   43.574241]  start_kernel+0x56d/0x590
> > > > [   43.596134]  secondary_startup_64_no_verify+0xb0/0xbb
> > > > [   43.626343] ---[ end trace b219258fce8dc761 ]---
> > > > [   43.654095] igb 0000:07:00.0 enp7s0f0: Reset adapter
> > > > [   46.090948] igb 0000:07:00.0: exceed max 2 second
> > > > 
> > > 
> > > Might be an interrupt stuck in the in-band log of the pipeline, in which
> > > case the CPU would go idle without synchronizing the log, leaving a
> > > pending IRQ unhandled until the next exit from the idle state. I wonder
> > > if the unstable TSC issue might not be another symptom of that kind of
> > > cause.
> > > 
> > > Do you see any change when booting with idle=poll?
> > > 
> > 
> > The call stack looks different with idle=poll, as expected:
> > 
> > [   48.752335] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x205/0x210
> > [   48.801769] Modules linked in: sha512_ssse3 sha512_generic cmac sha256_ssse3 sha256_generic libsha256 hmac nls_cp437 cifs libdes libarc4 xt_conntrack xt_MASQUERADE xfrm_user xfrm_algo xt_addrtype iptable_filter iptable_nat nf_nat nf_conn                track nf_defrag_ipv6 nf_defrag_ipv4 br_netfilter bridge stp llc overlay x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul mei_me iTCO_wdt iTCO_vendor_support mei hed ipmi_si ipmi_devintf ipmi_msghandler msr fuse configfs ip_tables x_tables ipv6 autofs4 hid_generic usbhid hid raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx raid6_pq libcrc32c raid1 raid0 multipath linear i2c_i801 lpc_ich i2c_smbus ahci igb mfd_core xhci_pci libahci mpt3sas i2c_algo_bit raid_class xhci_hcd scsi_transport_sas
> > [   49.213706] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.53-xenomai-0 #1
> > [   49.254843] Hardware name: Siemens <...snip...>, BIOS s2.0a_M1 08/02/2016
> > [   49.314694] IRQ stage: Linux
> > [   49.331907] RIP: 0010:dev_watchdog+0x205/0x210
> > [   49.358477] Code: b1 26 fe ff eb b1 4c 89 ef c6 05 fb 23 b4 00 01 e8 d0 87 fb ff 44 89 e1 4c 89 ee 48 c7 c7 18 09 df b9 48 89 c2 e8 c3 c1 0a 00 <0f> 0b eb 92 0f 1f 80 00 00 00 00 0f 1f 44 00 00 f0 80 a7 d8 00 00
> > [   49.470849] RSP: 0018:ffffa041c0003ec0 EFLAGS: 00010282
> > [   49.470851] RAX: 0000000000000000 RBX: ffff90ca43edb8c0 RCX: ffff90c9ff817948
> > [   49.470852] RDX: 00000000ffffffd8 RSI: 0000000000000027 RDI: ffff90c9ff817940
> > [   49.470854] RBP: ffff90bac76e03b8 R08: ffffffffba139e28 R09: 0000000000009ffb
> > [   49.470857] R10: 00000000ffffe000 R11: 3fffffffffffffff R12: 0000000000000002
> > [   49.672860] R13: ffff90bac76e0000 R14: ffffffffb96ca7a0 R15: ffffa041c0003f18
> > [   49.723877] FS:  0000000000000000(0000) GS:ffff90c9ff800000(0000) knlGS:0000000000000000
> > [   49.780606] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [   49.823302] CR2: 00007f96466f7048 CR3: 0000001087a60006 CR4: 00000000001706f0
> > [   49.868591] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [   49.911284] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [   49.953977] Call Trace:
> > [   49.968593]  <IRQ>
> > [   49.980597]  ? pfifo_fast_dequeue+0x1e0/0x1e0
> > [   50.006654]  call_timer_fn+0x2b/0x100
> > [   50.028544]  __run_timers.part.0+0x1d9/0x250
> > [   50.054078]  ? proxy_set_next_ktime+0x155/0x180
> > [   50.081163]  run_timer_softirq+0x26/0x50
> > [   50.104620]  __do_softirq+0x105/0x30b
> > [   50.126512]  asm_call_irq_on_stack+0xf/0x20
> > [   50.151518]  </IRQ>
> > [   50.164059]  do_softirq_own_stack+0x37/0x40
> > [   50.189067]  irq_exit_rcu+0xaa/0xe0
> > [   50.209920]  arch_do_IRQ_pipelined+0xbf/0x130
> > [   50.235974]  sync_current_irq_stage+0x157/0x1f0
> > [   50.263061]  handle_irq_pipelined_finish+0x8b/0x190
> > [   50.292240]  arch_pipeline_entry+0xb0/0x100
> > [   50.317247]  asm_sysvec_apic_timer_interrupt+0xf/0x20
> > [   50.347459] RIP: 0010:cpu_idle_poll.isra.0+0x46/0xe0
> > [   50.377147] Code: 40 3a 99 ff e8 8b 7c 92 ff e8 06 2b 99 ff 65 48 8b 1c 25 c0 6c 01 00 e8 c8 be 91 ff 48 8b 03 a8 08                 74 0b eb 1c f3 90 48 8b 03 <a8> 08 75 13 8b 05 e0 35 a7 00 85 c0 75 ed e8 07 61 94 ff 85 c0 75
> > [   50.489518] RSP: 0018:ffffffffba003eb8 EFLAGS: 00000202
> > [   50.520767] RAX: 0000000000204000 RBX: ffffffffba011940 RCX: 000000000000001f
> > [   50.563463] RDX: 000000001bbb4d5a RSI: 0000000000000000 RDI: ffffffffb97afefa
> > [   50.606154] RBP: 0000000000000000 R08: 000000001bbb4d5a R09: 0000000000000000
> > [   50.648840] R10: 0000000000001400 R11: 0000000000000000 R12: 00000000000000ac
> > [   50.691537] R13: ffffffffba6150a0 R14: 0000000000000001 R15: 0000000000000008
> > [   50.734226]  ? cpu_idle_poll.isra.0+0x2a/0xe0
> > [   50.760278]  ? cpu_idle_poll.isra.0+0x38/0xe0
> > [   50.786336]  do_idle+0x7e/0x200
> > 
> > Where would be the right place to add a warning when one of the CPUs
> > tries to enter the idle state with pending IRQs?
> 
> Something like this:
> 
> diff --git a/include/linux/irq_pipeline.h b/include/linux/irq_pipeline.h
> index cbeb0109fa7ff47..17436e10e620072 100644
> --- a/include/linux/irq_pipeline.h
> +++ b/include/linux/irq_pipeline.h
> @@ -88,6 +88,8 @@ int handle_irq_pipelined(struct pt_regs *regs);
>  
>  void sync_inband_irqs(void);
>  
> +bool irq_is_pending(void);
> +
>  extern struct irq_domain *synthetic_irq_domain;
>  
>  #else /* !CONFIG_IRQ_PIPELINE */
> @@ -134,6 +136,11 @@ static inline bool inband_irq_pending(void)
>  
>  static inline void sync_inband_irqs(void) { }
>  
> +static inline bool irq_is_pending(void)
> +{
> +	return false;
> +}
> +
>  #endif /* !CONFIG_IRQ_PIPELINE */
>  
>  #if !defined(CONFIG_IRQ_PIPELINE) || !defined(CONFIG_SPARSE_IRQ)
> diff --git a/kernel/irq/pipeline.c b/kernel/irq/pipeline.c
> index c4974a8d7244dec..116214690d47cda 100644
> --- a/kernel/irq/pipeline.c
> +++ b/kernel/irq/pipeline.c
> @@ -1575,6 +1575,18 @@ bool irq_cpuidle_enter(struct cpuidle_device *dev,
>  	return irq_cpuidle_control(dev, state);
>  }
>  
> +bool irq_is_pending(void)
> +{
> +	unsigned long flags;
> +	bool ret;
> +
> +	flags = hard_local_irq_save();
> +	ret = inband_irq_pending();
> +	hard_local_irq_restore(flags);
> +
> +	return ret;
> +}
> +
>  static unsigned int inband_work_sirq;
>  
>  static irqreturn_t inband_work_interrupt(int sirq, void *dev_id)
> diff --git a/kernel/sched/idle.c b/kernel/sched/idle.c
> index e8bb54eeb0c98af..702e08143108881 100644
> --- a/kernel/sched/idle.c
> +++ b/kernel/sched/idle.c
> @@ -115,6 +115,7 @@ void __cpuidle default_idle_call(void)
>  		rcu_idle_enter();
>  		lockdep_hardirqs_on(_THIS_IP_);
>  
> +		WARN_ON_ONCE(irq_is_pending());
>  		arch_cpu_idle();
>  
>  		/*
> @@ -252,6 +253,7 @@ static void cpuidle_idle_call(void)
>  	}
>  
>  exit_idle:
> +	WARN_ON_ONCE(irq_is_pending());
>  	__current_set_polling();
>  
>  	/*

The situation changed a bit since last time. We rebased the kernel
configuration to the Debian config and added our Xenomai specifics on
top.

The issue is no longer reproducible on the same machine, but I still
have one machine in our lab which shows this issue. It can be
reproduced easily. The machine shows the WARNING below while booting
up. In 99% of the time the machine hangs and is unusable (even no
serial connection working), sometimes it recovers and igb driver is
able to reset the device.

I patched the kernel with the suggestions above, but the WARN_ON_ONCE
actually never triggered.

Adding idle=poll to the kernel cmdline helped this time. The issue did
not come back until now.

As the machine is normally dead tracing doesn't help here. Any further
ideas?

[   30.019524] ------------[ cut here ]------------
[   30.047208] WARNING: CPU: 6 PID: 0 at net/sched/sch_generic.c:467 dev_watchdog+0x24d/0x260
[   30.096708] Modules linked in: nls_utf8(E) cifs(E) libarc4(E) dns_resolver(E) fscache(E) libdes(E) xt_conntrack(E) xt_MASQUERADE(E) nf_conntrack_netlink(E) nfnetlink(E) xfrm_user(E) xfrm_algo(E) xt_addrtype(E) iptable_filter(E) iptable_nat(E) nf_nat(E) nf_conntrack(E))
[   30.096895]  ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid1(E) multipath(E) linear(E) raid0()
[   30.956756] CPU: 6 PID: 0 Comm: swapper/6 Tainted: G            E     5.10.61-xenomai-1-orig #1
[   31.008853] Hardware name: Supermicro X9DR3-F/X9DR3-F, BIOS 2.0 02/20/2013
[   31.050038] IRQ stage: Linux
[   31.067309] RIP: 0010:dev_watchdog+0x24d/0x260
[   31.093932] Code: 29 cb fd ff eb a9 4c 89 f7 c6 05 b7 bc ef 00 01 e8 88 a0 fa ff 44 89 e9 4c 89 f6 48 c7 c7 28 24 97 b6 48 89 c2 e8 2d 1c 14 00 <0f> 0b eb 8a 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 66 66 66
[   31.206352] RSP: 0018:ffffba6cc1b68eb0 EFLAGS: 00010282
[   31.237659] RAX: 0000000000000000 RBX: ffff9390c18d78c0 RCX: ffff93943784c800
[   31.280403] RDX: ffff93943784c800 RSI: 0000000000000000 RDI: 0000000000000006
[   31.323146] RBP: ffff9390c6c343dc R08: 0000000000000000 R09: ffffba6cc1b68cb8
[   31.365891] R10: 0000000000000040 R11: ffff93943ff88228 R12: ffff9390c6c34480
[   31.408636] R13: 0000000000000005 R14: ffff9390c6c34000 R15: ffff9390c18d7940
[   31.451382] FS:  0000000000000000(0000) GS:ffff939437800000(0000) knlGS:0000000000000000
[   31.499846] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   31.534271] CR2: 000000000045b3c0 CR3: 00000001f080a003 CR4: 00000000000606e0
[   31.577015] Call Trace:
[   31.591683]  <IRQ>
[   31.603748]  ? pfifo_fast_enqueue+0x150/0x150
[   31.629849]  ? pfifo_fast_enqueue+0x150/0x150
[   31.655956]  call_timer_fn+0x29/0xf0
[   31.677378]  __run_timers.part.0+0x1dd/0x250
[   31.702967]  ? proxy_set_next_ktime+0xe0/0x110
[   31.729587]  run_timer_softirq+0x26/0x50
[   31.753097]  __do_softirq+0xc3/0x271
[   31.774515]  asm_call_irq_on_stack+0x12/0x20
[   31.800099]  </IRQ>
[   31.812692]  do_softirq_own_stack+0x37/0x40
[   31.837754]  irq_exit_rcu+0x8c/0xc0
[   31.858658]  arch_do_IRQ_pipelined+0xc2/0x140
[   31.884760]  sync_current_irq_stage+0x1b9/0x260
[   31.911903]  inband_irq_enable+0x42/0x50
[   31.935411]  cpuidle_enter_state+0xe4/0x370
[   31.960472]  cpuidle_enter+0x29/0x40
[   31.981900]  do_idle+0x1e8/0x2a0
[   32.001241]  cpu_startup_entry+0x19/0x20
[   32.024746]  secondary_startup_64_no_verify+0xb0/0xbb
[   32.055008] ---[ end trace fa5156f5ac624722 ]---