Too many timer interrupts in NO_HZ

Too many timer interrupts in NO_HZ

[Vaidyanathan Srinivasan]

Hi,

I am trying to play around with the tickless kernel and
sched_mc_power_savings tunables to increase the idle duration of the
CPU in an SMP server.  sched_mc_power_savings provides good
consolidation of long running jobs when the system is lightly loaded.
However I am interested to see CPU idle times for couple minutes on
atleast few CPUs in an completely idle SMP system.

I have posted related instrumentation results at
http://lkml.org/lkml/2008/1/8/243

The experimental setup is identical.  Just that I have tried to
collect more data and also bias the wakeup logic.

The kernel is 2.6.25-rc3 with NO_HZ, SCHED_MC, HIGH_RES_TIMERS, and
HPET turned on.

I have tried to collect interesting data from tick-sched.c, sched.c
and softirq.c.

As suggested by Ingo in the previous thread, I have hacked the sched.c
try_to_wake_up logic so that I can force all wake-ups to happen on
CPU0.  This is just and experiment, in reality we will have to
carefully choose a domain and CPU to bias all wakeups on an idle
system.

--- linux-2.6.25-rc3.orig/kernel/sched_fair.c
+++ linux-2.6.25-rc3/kernel/sched_fair.c
@@ -991,6 +991,10 @@ static int select_task_rq_fair(struct ta
        this_cpu = smp_processor_id();
        new_cpu  = cpu;

+       /* Force move all tasks to CPU 0 */
+       if (unlikely(cpu_isset(0, p->cpus_allowed)))
+               return 0;
+
        if (cpu == this_cpu)
                goto out_set_cpu;

Experiment:
-----------

Hardware:
* Two socket dual core intel xeon (4 Logical CPU)

Setup:

* Killed most daemons include irqbalance
* Routed all interrupts to CPU0
* sched_mc_power_savings = 1  
* powertop gives an average ~3 wakeups/sec
* Trace data collected for 120 secs on this completely idle machine
* Log /proc/interrupts before and after the observation period
      
Results:

Interrupt count for 120 seconds:
	   
           CPU0       CPU1       CPU2       CPU3       
 17:         55          0          0          0   IO-APIC-fasteoi-aacraid
214:        277          0          0          0   PCI-MSI-edge-eth0
LOC:        676        306        324        296   Local timer interrupts
CAL:          0         12         12         12   function call interrupts
TLB:          5          3          0          0   TLB shootdowns


		CPU0	CPU1	CPU2	CPU3
Maximum Idle 
Time (ms): 	1000	5250	5320	5250

Some of the process that was woken-up on CPUs 1,2 & 3 because of
affinity and that could not be moved to CPU0:

Wakeup    PID     PROCESS
Count     
60     :    7   [ksoftirqd/1]
58     :   10   [ksoftirqd/2]
58     :   13   [ksoftirqd/3]
 8     :   17   [events/2]
 8     : 1098   [kondemand/2]

The problem:

There are way too many timer interrupts even though the CPUs have
entered tickless idle loop.  Timer interrupts basically bring the CPU
out of idle, and then return to tickless idle.  There are very few
try_to_wake_up()s or need_resched() in between the timer interrupts.

What can happen in an idle system in the timer interrupt context that
does not invoke a need_resched() or try_to_wake_up()?

Trace pattern:

CPU2 Trace sequence:

ns								ns
2135960054680	tick_nohz_stop_sched_tick(), expires = 7290612000000 
*** tick_stopped = 1 ***
2136363725957	tick_nohz_stop_sched_tick(), expires = 7290612000000
*** Timer Interrupt ***
2136767397163	tick_nohz_stop_sched_tick(), expires = 7290612000000
*** Timer Interrupt ***
2137171068369	tick_nohz_stop_sched_tick(), expires = 7290612000000
*** Timer Interrupt ***
2137574739785	tick_nohz_stop_sched_tick(), expires = 7290612000000
.........
.........
*** Timer Interrupt ***
2140804114397	tick_nohz_stop_sched_tick(), expires = 2140808000000
*** try_to_wake_up() ***
2140804121591	tick_nohz_restart_sched_tick()
*** tick_stopped = 0 ***

There is a similar pattern on CPU1 and CPU3, while CPU0 has
significantly more wake-ups and timer interrupts.  

Basically there are more than 10 timer interrupts at 4ms interval even
though the next expected timer is very much into the future.  My HZ is
250, so I assume the tick could not be stopped for some reason.

There are instances in the trace were the tick was stopped
successfully and we get a much larger interval between successive
timer interrupts and tick_nohz_stop_sched_tick() calls.

Please help me to understand the following scenario:

* What can happen in timer interrupt context that need not wakeup any
  process?
* What can prevent tick_nohz_stop_sched_tick() from actually stopping
  the tick?  
* Whats wrong in expecting to see some of the CPUs having tickless
  idle time of few minutes

Thank you for review my experiment.  Comments and suggestions are
welcome.  I will send instrumentation patch and trace data on request.

--Vaidy

Re: Too many timer interrupts in NO_HZ

[Arjan van de Ven]

On Mon, 3 Mar 2008 01:18:13 +0530
Vaidyanathan Srinivasan <svaidy@linux.vnet.ibm.com> wrote:

> Hi,
> 
> I am trying to play around with the tickless kernel and
> sched_mc_power_savings tunables to increase the idle duration of the
> CPU in an SMP server.  sched_mc_power_savings provides good
> consolidation of long running jobs when the system is lightly loaded.
> However I am interested to see CPU idle times for couple minutes on
> atleast few CPUs in an completely idle SMP system.
> 
> I have posted related instrumentation results at
> http://lkml.org/lkml/2008/1/8/243
> 
> The experimental setup is identical.  Just that I have tried to
> collect more data and also bias the wakeup logic.
> 
> The kernel is 2.6.25-rc3 with NO_HZ, SCHED_MC, HIGH_RES_TIMERS, and
> HPET turned on.
> 
> I have tried to collect interesting data from tick-sched.c, sched.c
> and softirq.c.
> 
> As suggested by Ingo in the previous thread, I have hacked the sched.c
> try_to_wake_up logic so that I can force all wake-ups to happen on
> CPU0.  This is just and experiment, in reality we will have to
> carefully choose a domain and CPU to bias all wakeups on an idle
> system.


please show us powertop -d output; that way we can at least see sort of what
is going on...

Re: Too many timer interrupts in NO_HZ

[Vaidyanathan Srinivasan]

* Arjan van de Ven <arjan@infradead.org> [2008-03-02 11:57:09]:
[sniped]
 
> 
> please show us powertop -d output; that way we can at least see sort of what
> is going on...

Here you go...

[root@XXXX sv]# powertop -d
PowerTOP 1.9    (C) 2007 Intel Corporation 

Collecting data for 15 seconds 
< Detailed C-state information is only available on Mobile CPUs (laptops) >
P-states (frequencies)
  2.40 Ghz     0.0%
  2.13 Ghz     0.0%
  1.87 Ghz     0.0%
  1.60 Ghz   100.0%
Wakeups-from-idle per second :  3.1     interval: 15.0s
no ACPI power usage estimate available
Top causes for wakeups:
  41.4% (  2.4)       <interrupt> : eth0 
  17.2% (  1.0)                ip : bnx2_open (bnx2_timer) 
   9.2% (  0.5)     <kernel core> : neigh_table_init_no_netlink (neigh_periodic_timer) 
   3.4% (  0.2)      <kernel IPI> : function call interrupts 
   3.4% (  0.2)              init : schedule_timeout (process_timeout) 
   3.4% (  0.2)            python : schedule_timeout (process_timeout) 
   3.4% (  0.2)     <kernel core> : __netdev_watchdog_up (dev_watchdog) 
   3.4% (  0.2)          sendmail : schedule_timeout (process_timeout) 
   3.4% (  0.2)     <kernel core> : page_writeback_init (wb_timer_fn) 
   2.3% (  0.1)       <interrupt> : aacraid 
   2.3% (  0.1)        rc.sysinit : start_this_handle (commit_timeout) 
   1.1% (  0.1)     <kernel core> : sk_reset_timer (tcp_delack_timer) 
   1.1% (  0.1)              sshd : sk_reset_timer (tcp_write_timer) 
   1.1% (  0.1)     <kernel core> : cache_register (delayed_work_timer_fn) 
   1.1% (  0.1)     <kernel core> : init_nonfatal_mce_checker (delayed_work_timer_fn) 
   1.1% (  0.1)             crond : do_nanosleep (hrtimer_wakeup) 
   1.1% (  0.1)     <kernel core> : neigh_add_timer (neigh_timer_handler) 

Suggestion: increase the VM dirty writeback time from 5.00 to 15 seconds with:
  echo 1500 > /proc/sys/vm/dirty_writeback_centisecs 
This wakes the disk up less frequenty for background VM activity

Suggestion: enable the noatime filesystem option by executing the following command:
   mount -o remount,noatime /          or by pressing the T key 
noatime disables persistent access time of file accesses, which causes lots of disk IO.

--Vaidy

Re: Too many timer interrupts in NO_HZ

[Vaidyanathan Srinivasan]

* Arjan van de Ven <arjan@infradead.org> [2008-03-02 11:57:09]:

> On Mon, 3 Mar 2008 01:18:13 +0530
> Vaidyanathan Srinivasan <svaidy@linux.vnet.ibm.com> wrote:
> 
> > Hi,
> > 
> > I am trying to play around with the tickless kernel and
> > sched_mc_power_savings tunables to increase the idle duration of the
> > CPU in an SMP server.  sched_mc_power_savings provides good
> > consolidation of long running jobs when the system is lightly loaded.
> > However I am interested to see CPU idle times for couple minutes on
> > atleast few CPUs in an completely idle SMP system.
> > 
> > I have posted related instrumentation results at
> > http://lkml.org/lkml/2008/1/8/243
> > 
> > The experimental setup is identical.  Just that I have tried to
> > collect more data and also bias the wakeup logic.
> > 
> > The kernel is 2.6.25-rc3 with NO_HZ, SCHED_MC, HIGH_RES_TIMERS, and
> > HPET turned on.
> > 
> > I have tried to collect interesting data from tick-sched.c, sched.c
> > and softirq.c.
> > 
> > As suggested by Ingo in the previous thread, I have hacked the sched.c
> > try_to_wake_up logic so that I can force all wake-ups to happen on
> > CPU0.  This is just and experiment, in reality we will have to
> > carefully choose a domain and CPU to bias all wakeups on an idle
> > system.
> 
> 
> please show us powertop -d output; that way we can at least see sort of what
> is going on...

I have some more information on the timer interrupt activities in the
system.  I have obtained the following trace from irq_exit and local
timer is the only interrupt on CPUs 1, 2 & 3.

Trace       CPU/function                    Timestamp
number

U2336208    C1 irq_exit             EXIT  4452403.687322 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336212    C3 irq_exit             EXIT  4452403.722253 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336214    C2 irq_exit             EXIT  4452403.722668 ms in_intr 0 in_idle 1 need_resched 0 pid 0


U2336236    C1 irq_exit             EXIT  4452807.345543 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336241    C3 irq_exit             EXIT  4452807.381894 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336242    C2 irq_exit             EXIT  4452807.382144 ms in_intr 0 in_idle 1 need_resched 0 pid 0


U2336248    C1 irq_exit             EXIT  4453211.003638 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336253    C3 irq_exit             EXIT  4453211.041529 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336254    C2 irq_exit             EXIT  4453211.041703 ms in_intr 0 in_idle 1 need_resched 0 pid 0


U2336260    C1 irq_exit             EXIT  4453614.662043 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336265    C3 irq_exit             EXIT  4453614.701429 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336266    C2 irq_exit             EXIT  4453614.701474 ms in_intr 0 in_idle 1 need_resched 0 pid 0


U2336293    C1 irq_exit             EXIT  4454018.320078 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336298    C3 irq_exit             EXIT  4454018.361100 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336299    C2 irq_exit             EXIT  4454018.361142 ms in_intr 0 in_idle 1 need_resched 0 pid 0


U2336313    C1 irq_exit             EXIT  4454421.978047 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336318    C2 irq_exit             EXIT  4454422.020756 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336319    C3 irq_exit             EXIT  4454422.020807 ms in_intr 0 in_idle 1 need_resched 0 pid 0


U2336357    C1 irq_exit             EXIT  4454825.636341 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336369    C2 irq_exit             EXIT  4454825.681058 ms in_intr 0 in_idle 1 need_resched 0 pid 0
U2336370    C3 irq_exit             EXIT  4454825.681191 ms in_intr 0 in_idle 1 need_resched 0 pid 0

This is over a short interval where I complain that the tick is not
really getting stopped.  Actually there is a pattern of 400ms timer
being programmed.

Apart from these there are 4ms pattern on one of the CPU that is used
to drive tick_sched_timer.  Most of the missing trace entries are CPU0
which takes care of all the idle daemon process.

There are wakeups due to kondemand and other kernel threads on CPUs 1,
2 & 3, but the time is in seconds.

Please help me find the source for this timer.

Thanks,
Vaidy

Re: Too many timer interrupts in NO_HZ

[Vaidyanathan Srinivasan]

* Vaidyanathan Srinivasan <svaidy@linux.vnet.ibm.com> [2008-03-03 01:18:13]:

[sniped]
       
 
> The problem:
> 
> There are way too many timer interrupts even though the CPUs have
> entered tickless idle loop.  Timer interrupts basically bring the CPU
> out of idle, and then return to tickless idle.  There are very few
> try_to_wake_up()s or need_resched() in between the timer interrupts.
> 
> What can happen in an idle system in the timer interrupt context that
> does not invoke a need_resched() or try_to_wake_up()?
> 

[sniped]
 
> Please help me to understand the following scenario:
> 
> * What can happen in timer interrupt context that need not wakeup any
>   process?
> * What can prevent tick_nohz_stop_sched_tick() from actually stopping
>   the tick?  
> * Whats wrong in expecting to see some of the CPUs having tickless
>   idle time of few minutes

I think I have the answers to some of the above questions.  

Function        Count                   Name
Address

c0219922        : 5		blk_unplug_timeout
c014f464        : 55		wb_timer_fn
c02b2e67        : 350		bnx2_timer
c03efcbc        : 115		neigh_periodic_timer
c012894a        : 220		process_timeout
c027d1c4        : 2		hangcheck_fire
c03fe232        : 3		peer_check_expire
c012e830        : 25		delayed_work_timer_fn
c03afe92        : 2783		ehci_watchdog
c03f1a35        : 10		neigh_timer_handler
c01d7456        : 110		commit_timeout
c04381e9        : 2		addrconf_verify
c03f6d39        : 365		dev_watchdog
c04126bc        : 114		tcp_write_timer

These are roughly the list of functions that were responsible for the
timer interrupts across all cpus including the ones in idle.  Most of
the functions complete the job in interrupt context and also re-queue
the timer.  The count number is the call count in the 120s observation
window across all 4 CPUs.

I got these function addresses from __next_timer_interrupt() in
timer.c.  Previously, I did not look in timer.c since hrtimers were
enabled and I assumed all timer call will be through __run_hrtimer
from hrtimer.c.  The call count of __run_hrtimer was very minimal and
did not correspond to the local timer interrupt count.

These are device driver timers that we need to investigate.  We should
try to migrate them to CPU0 (or some other package) to get really long
uninterrupted CPU sleep time.  

I will post more results after tweaking some of the above timers.

Should PowerTop include local timer interrupt counts as well during
the observation period?  Interrupt do significantly affect CPU sleep
time whether they wakeup any process or not.

Comments?

Thanks,
Vaidy

Re: [linux-pm] Too many timer interrupts in NO_HZ

[Alan Stern]

On Sun, 16 Mar 2008, Vaidyanathan Srinivasan wrote:

> > The problem:
> > 
> > There are way too many timer interrupts even though the CPUs have
> > entered tickless idle loop.  Timer interrupts basically bring the CPU
> > out of idle, and then return to tickless idle.  There are very few
> > try_to_wake_up()s or need_resched() in between the timer interrupts.
> > 
> > What can happen in an idle system in the timer interrupt context that
> > does not invoke a need_resched() or try_to_wake_up()?

> Function        Count                   Name
> Address
> 
> c0219922        : 5		blk_unplug_timeout
> c014f464        : 55		wb_timer_fn
> c02b2e67        : 350		bnx2_timer
> c03efcbc        : 115		neigh_periodic_timer
> c012894a        : 220		process_timeout
> c027d1c4        : 2		hangcheck_fire
> c03fe232        : 3		peer_check_expire
> c012e830        : 25		delayed_work_timer_fn
> c03afe92        : 2783		ehci_watchdog
> c03f1a35        : 10		neigh_timer_handler
> c01d7456        : 110		commit_timeout
> c04381e9        : 2		addrconf_verify
> c03f6d39        : 365		dev_watchdog
> c04126bc        : 114		tcp_write_timer

> These are device driver timers that we need to investigate.  We should
> try to migrate them to CPU0 (or some other package) to get really long
> uninterrupted CPU sleep time.  

The largest entry is for ehci_watchdog.  This timer won't run at all if
your EHCI controllers are allowed to autosuspend, which will happen
automatically if

	(1) You enable CONFIG_USB_SUSPEND, and

	(2) You have no high-speed USB devices attached, or the
	    ones that are attached have all been suspended.

On the other hand, if you were actively using some high-speed USB 
device during the test then it's understandable that there should be 
lots of timer interrupts as a result.

Alan Stern

Re: [linux-pm] Too many timer interrupts in NO_HZ

[David Brownell]

On Sunday 16 March 2008, Alan Stern wrote:
> On Sun, 16 Mar 2008, Vaidyanathan Srinivasan wrote:
> 
> The largest entry is for ehci_watchdog.  This timer won't run at all if

... you're not accessing EHCI devices at all.  Is HAL or
something else polling them too often?  Or are you maybe
doing something else that resembles "real work"?


> your EHCI controllers are allowed to autosuspend, which will happen
> automatically if
> 
> 	(1) You enable CONFIG_USB_SUSPEND, and
> 
> 	(2) You have no high-speed USB devices attached, or the
> 	    ones that are attached have all been suspended.
> 
> On the other hand, if you were actively using some high-speed USB 
> device during the test then it's understandable that there should be 
> lots of timer interrupts as a result.

That watchdog is a bit messy, but it's got two basic tasks:

 (a) Take work off the async ring ... bulk and control
     transfers will leave an empty QH there for a few
     milliseconds before taking it off, to avoid wasting
     effort in the common case where another transfer
     quickly follows the first one.  In the extreme case,
     when there's no more work, that ring gets disabled.

 (b) A real I/O watchdog ... in case the hardware forgets
     to issue some kind of I/O completion interrupt.  This
     watchdog rarely needs to fire.

So I'm thinking this is most likely a case where something
is sending work to one or more high speed devices.

- Dave