Re: NOHZ: local_softirq_pending 08
From: Francois Romieu
Date: Tue Jun 05 2012 - 19:24:47 EST
Marc Dionne <marc.c.dionne@xxxxxxxxx> :
> If it helps, I've been seeing the same thing here on a system with an
> r8169. The message appears consistently enough on network startup to
> be able to track it down to this specific commit:
> 98ddf986fca17840e46e070354b7e2cd2169da15: r8169: bh locking redux
> and task scheduling.
>
> The softirq pending messages always come right after "link down"
> messages for the interface.
Let's see the traces.
I have added some code to trace the timing and values of the irq in
rtl8169_interrupt(). Patches against current git are attached.
This is the relevant part of kernel messages as seen through the serial
console:
[...]
[ 2441.972077] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded
[ 2441.977882] r8169 0000:01:00.0: enabling Mem-Wr-Inval
[ 2441.977939] r8169 0000:01:00.0: enabling bus mastering
[ 2441.978046] r8169 0000:01:00.0: irq 42 for MSI/MSI-X
[ 2441.979412] r8169 0000:01:00.0: eth0: RTL8168b/8111b at 0xffffc90000032000, 00:13:8f:ea:b1:5d, XID 18000000 IRQ 42
[ 2441.990081] r8169 0000:01:00.0: eth0: jumbo features [frames: 4080 bytes, tx checksumming: ko]
[...]
[ 2683.588223] r8169 0000:01:00.0: 8168b-lom: link down
[ 2683.593302] r8169 0000:01:00.0: 8168b-lom: link down
[ 2683.598341] NOHZ: local_softirq_pending 08
[ 2683.599356] IPv6: ADDRCONF(NETDEV_UP): 8168b-lom: link is not ready
[ 2685.779376] r8169 0000:01:00.0: 8168b-lom: link up
[ 2685.784824] IPv6: ADDRCONF(NETDEV_CHANGE): 8168b-lom: link becomes ready
Now the content of the IntrStatus register from rtl8169_interrupt() :
[35882] 0020 (LinkChg, see [ 2683.593302] r8169 ... 8168b-lom: link down)
[57792] 0020 (LinkChg, see [ 2685.779376] r8169 ... 8168b-lom: link up)
[57960] 0084
[64880] 0084
[74880] 0084
[06240] 0084
[14960] 0084
[55040] 0084
'ip link set dev 8168b-lom up' + 'cat /sys/kernel/debug/tracing/trace':
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
[...]
<idle>-0 [001] d..1 2681.581946: tick_nohz_stop_sched_tick <-tick_nohz_idle_enter
ip-1437 [000] ...1 2681.582967: rtl8169_get_stats64 <-dev_get_stats
ip-1437 [000] ...1 2681.582974: rtl8169_get_stats64 <-dev_get_stats
ip-1437 [000] ...1 2681.582990: rtl8169_get_stats64 <-dev_get_stats
ip-1437 [000] ...1 2681.582996: rtl8169_get_stats64 <-dev_get_stats
ip-1437 [000] ...1 2681.583002: rtl8169_get_stats64 <-dev_get_stats
ip-1437 [000] .... 2681.583146: rtl_device_event <-notifier_call_chain
ip-1437 [000] .... 2681.583148: rtl_open <-__dev_open
ip-1437 [000] .... 2681.583153: rtl8169_init_ring <-rtl_open
ip-1437 [000] .... 2681.583155: rtl8169_alloc_rx_data <-rtl8169_init_ring
[...]
ip-1437 [000] .... 2681.583497: rtl8169_alloc_rx_data <-rtl8169_init_ring
ip-1437 [000] .... 2681.583498: rtl_request_uncached_firmware <-rtl_open
ip-1437 [000] .... 2681.583539: rtl8169_init_phy <-rtl_open
ip-1437 [000] .... 2681.583540: rtl_hw_phy_config <-rtl8169_init_phy
ip-1437 [000] .... 2681.583540: rtl_writephy_batch <-rtl_hw_phy_config
ip-1437 [000] .... 2681.583541: rtl_writephy <-rtl_writephy_batch
ip-1437 [000] .... 2681.583542: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.583669: rtl_writephy <-rtl_writephy_batch
ip-1437 [000] .... 2681.583669: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.583795: rtl_writephy <-rtl_writephy_batch
ip-1437 [000] .... 2681.583796: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.583924: rtl8169_xmii_reset_enable <-rtl8169_init_phy
ip-1437 [000] .... 2681.583925: rtl_readphy <-rtl8169_xmii_reset_enable
ip-1437 [000] .... 2681.583925: r8169_mdio_read <-rtl_readphy
ip-1437 [000] .... 2681.584053: rtl_writephy <-rtl8169_xmii_reset_enable
ip-1437 [000] .... 2681.584053: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.584180: rtl8169_xmii_reset_pending <-rtl8169_init_phy
ip-1437 [000] .... 2681.584180: rtl_readphy <-rtl8169_xmii_reset_pending
ip-1437 [000] .... 2681.584180: r8169_mdio_read <-rtl_readphy
ip-1437 [000] .... 2681.584308: rtl8169_set_speed <-rtl8169_init_phy
ip-1437 [000] .... 2681.584309: rtl8169_set_speed_xmii <-rtl8169_set_speed
ip-1437 [000] .... 2681.584309: rtl_writephy <-rtl8169_set_speed_xmii
ip-1437 [000] .... 2681.584309: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.584436: rtl_readphy <-rtl8169_set_speed_xmii
ip-1437 [000] .... 2681.584436: r8169_mdio_read <-rtl_readphy
ip-1437 [000] .... 2681.584564: rtl_readphy <-rtl8169_set_speed_xmii
ip-1437 [000] .... 2681.584564: r8169_mdio_read <-rtl_readphy
ip-1437 [000] .... 2681.584692: rtl_writephy <-rtl8169_set_speed_xmii
ip-1437 [000] .... 2681.584692: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.584819: rtl_writephy <-rtl8169_set_speed_xmii
ip-1437 [000] .... 2681.584819: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.584946: rtl_writephy <-rtl8169_set_speed_xmii
ip-1437 [000] .... 2681.584946: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.585074: rtl_writephy <-r8168_pll_power_up
ip-1437 [000] .... 2681.585075: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.585201: rtl_writephy <-r8168_pll_power_up
ip-1437 [000] .... 2681.585201: r8169_mdio_write <-rtl_writephy
<idle>-0 [001] d..2 2681.585306: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
ip-1437 [000] .... 2681.585326: rtl_writephy <-r8168_pll_power_up
ip-1437 [000] .... 2681.585327: r8169_mdio_write <-rtl_writephy
ip-1437 [000] .... 2681.585453: rtl_hw_start_8168 <-rtl_open
ip-1437 [000] .... 2681.585456: rtl_set_rx_tx_desc_registers <-rtl_hw_start_8168
ip-1437 [000] .... 2681.585456: rtl_set_rx_mode <-rtl_hw_start_8168
ip-1437 [000] .... 2681.585461: rtl_hw_start_8168bb <-rtl_hw_start_8168
ip-1437 [000] .... 2681.585464: rtl_tx_performance_tweak <-rtl_hw_start_8168bb
ip-1437 [000] .... 2681.585472: rtl8169_xmii_link_ok <-__rtl8169_check_link_status
[See first LinkChg event above]
ip-1437 [000] d.h. 2681.585477: rtl8169_interrupt <-handle_irq_event_percpu
ip-1437 [000] ..s1 2681.585481: rtl8169_poll <-net_rx_action
[r8169 NAPI handler schedules some work for the link event...]
ip-1437 [000] ..s1 2681.585483: rtl_schedule_task <-rtl8169_poll
<idle>-0 [001] d..2 2681.589280: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
ip-1437 [000] .Ns1 2681.590517: rtl_set_rx_mode <-__dev_set_rx_mode
ip-1437 [000] .Ns1 2681.590523: rtl_set_rx_mode <-__dev_set_rx_mode
ip-1437 [000] .N.. 2681.590533: rtl8169_get_stats64 <-dev_get_stats
ip-1437 [000] .Ns1 2681.590546: rtl_set_rx_mode <-__dev_set_rx_mode
[... and kworker kicks in]
kworker/0:2-44 [000] .... 2681.590565: rtl_task <-process_one_work
kworker/0:2-44 [000] .... 2681.590566: rtl_slow_event_work <-rtl_task
[Here comes the 'link down' message...]
kworker/0:2-44 [000] .... 2681.590568: rtl8169_xmii_link_ok <-__rtl8169_check_link_status
<idle>-0 [001] d..1 2681.590774: tick_nohz_stop_sched_tick <-tick_nohz_idle_enter
<idle>-0 [001] d..2 2681.593285: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
[... and the 'local_softirq_pending' message takes place ~5ms later]
<idle>-0 [000] d..1 2681.595607: tick_nohz_stop_sched_tick <-tick_nohz_idle_enter
ip-1437 [001] .... 2681.596629: rtl_device_event <-notifier_call_chain
[NAPI was scheduled from 'rtl_slow_event_work'. rtl8169_poll experiences a
10 ms delay but I really don't care: there should not be much slow events
and it avoids shared locking between the slow work thread and the NAPI
handler]
<idle>-0 [000] .Ns2 2681.606110: rtl8169_poll <-net_rx_action
<idle>-0 [000] d..1 2681.606377: tick_nohz_stop_sched_tick <-tick_nohz_idle_enter
<idle>-0 [001] d..1 2681.606506: tick_nohz_stop_sched_tick <-tick_nohz_idle_enter
<idle>-0 [000] d..2 2681.606526: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
<idle>-0 [000] d..2 2681.607842: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
<idle>-0 [001] d..2 2681.609292: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
<idle>-0 [001] d..2 2681.613272: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
<idle>-0 [001] d..2 2681.617268: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
<idle>-0 [001] d..2 2681.621265: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
<idle>-0 [001] d..2 2681.625275: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
<idle>-0 [001] d..2 2681.629262: tick_nohz_stop_sched_tick <-tick_nohz_irq_exit
[...]
<idle>-0 [001] d..1 2683.551714: tick_nohz_stop_sched_tick <-tick_nohz_idle_enter
<idle>-0 [001] d..1 2683.751544: tick_nohz_stop_sched_tick <-tick_nohz_idle_enter
<idle>-0 [000] d.h1 2683.774846: rtl8169_interrupt <-handle_irq_event_percpu
<idle>-0 [000] ..s2 2683.774850: rtl8169_poll <-net_rx_action
<idle>-0 [000] ..s2 2683.774852: rtl_schedule_task <-rtl8169_poll
kworker/0:2-44 [000] .... 2683.774860: rtl_task <-process_one_work
kworker/0:2-44 [000] .... 2683.774861: rtl_slow_event_work <-rtl_task
[link up message, 2s after the 'link down' one]
kworker/0:2-44 [000] .... 2683.774863: rtl8169_xmii_link_ok <-__rtl8169_check_link_status
kworker/0:2-44 [000] .... 2683.774865: rtl_link_chg_patch <-__rtl8169_check_link_status
98ddf986fca17840e46e070354b7e2cd2169da15 removed bh locking, whence the
implicit do_softirq() called from _local_bh_enable_ip.
With my stupid driver maintainer hat on, I can only tell that
it works as designed.
It could be worth checking if Dave's traces look the same or not.
--
Ueimor