Re: NOHZ: local_softirq_pending 08

[Dave Jones <davej@redhat.com>]

On Wed, Jun 06, 2012 at 07:42:51AM +0200, Francois Romieu wrote:

 > My sequence was:
 > 
 > echo 0 > tracing_on
 > echo nop > current_tracer
 > echo 10000 > buffer_size_kb
 > echo function > current_tracer
 > echo rtl* > set_ftrace_filter
 > echo r8169* >> set_ftrace_filter
 > echo tick_nohz_stop_sched_tick >> set_ftrace_filter
 > 
 > I only enabled tracing_on right before 'ip link ... up'.

Ok. This was a bit of a pain to trace, as I can't trigger the NOHZ message
when I bring up/down the interface by hand. It only seems to happen
during boot now for some reason. So I modified the networking ifup scripts
to start/stop the logging. It's still a pain, because there are two NICs
in the affected machine, so everything happens twice.
It also seems to have started too early & finished too late.. oh well.
hopefully you can get something interesting out of it.

 > tick_nohz_stop_sched_tick fills the log rather fast.

I don't have that symbol for some reason.

The log is still huge though. (68M uncompressed) at http://www.codemonkey.org.uk/junk/r8169-trace.txt.xz

Here's the order of events on that boot...

[   53.086040] r8169 0000:01:00.0: eth0: link down
[   53.086441] r8169 0000:01:00.0: eth0: link down
[   53.086545] NOHZ: local_softirq_pending 08
[   53.113025] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   54.773637] r8169 0000:01:00.0: eth0: link up
[   54.783210] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   64.941664] r8169 0000:05:00.0: eth1: link down
[   64.941748] r8169 0000:05:00.0: eth1: link down
[   64.941792] NOHZ: local_softirq_pending 08
[   64.968326] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
[   67.948677] r8169 0000:05:00.0: eth1: link up
[   67.961872] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready


	Dave