Dynamic ticks make system jerking

Dynamic ticks make system jerking

[Uwe Kleine-König]

Hello,

I implemented GENERIC_TIME and GENERIC_CLOCKEVENTS for
arch-arm/mach-ns9xxx (patches available at

	http://www.modarm9.com/git?p=people/ukleinek/linux-2.6.git;a=shortlog;h=clock

or

	git://www.modarm9.com/gitsrc/pub/people/ukleinek/linux-2.6.git

in the clock branch

). 

If I enable NO_HZ, the system jerks (I hope this is an understandable
term ...).   E.g. 

	# time find /sys
	...
	real    1m 19.52s
	user    0m 0.18s
	sys     0m 0.15s

on a freshly booted machine.  The output comes in several hunks with
pausing between them.  With no_hz=off, I get approx. the same.

If I have NO_HZ disabled however, I get

	# time find /sys
	...
	real    0m 1.53s
	user    0m 0.15s
	sys     0m 0.18s

Another thing is, if I press Enter once, the next prompt appears in a
reasonable time.  If I press twice in a row the 2nd prompt needs
perceptible longer.

Does someone have a hint for me how to debug (or even solve) this problem?

First I wondered why set_next_event is called twice between two timer
interrupts most of the time.  I found out that the timer is programed
for the next tick in any case and if nothing needs the next tick, the
interval is enlarged.  I didn't spend time yet to check if it is
easier/faster to only program the timer once.

Best regards
Uwe

Some addional data:

- ns9xxx_cpuclock() returns 176947200 = 0xa8c0000 for that machine.

- SYS_TR is a read-only register indicating the current timer value.

- SYS_TRC is the start value (and the reload value for auto-reloading
  timers)

- My console is an 8250 clone.

- /proc/timer_list 
	Timer List Version: v0.3
	HRTIMER_MAX_CLOCK_BASES: 2
	now at 15091350847 nsecs

	cpu: 0
	 clock 0:
	  .index:      0
	  .resolution: 1 nsecs
	  .get_time:   ktime_get_real
	  .offset:     0 nsecs
	active timers:
	 clock 1:
	  .index:      1
	  .resolution: 1 nsecs
	  .get_time:   ktime_get
	  .offset:     0 nsecs
	active timers:
	 #0: <c02e5ea0>, tick_sched_timer, S:01
	 # expires at 15100000000 nsecs [in 8649153 nsecs]
	  .expires_next   : 15100000000 nsecs
	  .hres_active    : 1
	  .nr_events      : 424
	  .nohz_mode      : 2
	  .idle_tick      : 14320000000 nsecs
	  .tick_stopped   : 0
	  .idle_jiffies   : 4294938728
	  .idle_calls     : 104
	  .idle_sleeps    : 88
	  .idle_entrytime : 15052376577 nsecs
	  .idle_sleeptime : 10627230732 nsecs
	  .last_jiffies   : 4294938801
	  .next_jiffies   : 4294938802
	  .idle_expires   : 15060000000 nsecs
	jiffies: 4294938805


	Tick Device: mode:     1
	Clock Event Device: ns9xxx-timer2
	 max_delta_ns:   2147483647
	 min_delta_ns:   1000
	 mult:           185542
	 shift:          20
	 mode:           3
	 next_event:     15100000000 nsecs
	 set_next_event: ns9xxx_clockevent_setnextevent
	 set_mode:       ns9xxx_clockevent_setmode
	 event_handler:  hrtimer_interrupt

-- 
Uwe Kleine-König

http://www.google.com/search?q=e+%5E+%28i+pi%29

Re: Dynamic ticks make system jerking

[Thomas Gleixner]

On Tue, 2007-06-26 at 17:00 +0200, Uwe Kleine-König wrote:
> If I enable NO_HZ, the system jerks (I hope this is an understandable
> term ...).   E.g. 
> 
> 	# time find /sys
> 	...
> 	real    1m 19.52s
> 	user    0m 0.18s
> 	sys     0m 0.15s
> 
> on a freshly booted machine.  The output comes in several hunks with
> pausing between them.  With no_hz=off, I get approx. the same.

it's nohz=off not no_hz=off

> If I have NO_HZ disabled however, I get
> 
> 	# time find /sys
> 	...
> 	real    0m 1.53s
> 	user    0m 0.15s
> 	sys     0m 0.18s

Well, you run in periodic mode then.

> Another thing is, if I press Enter once, the next prompt appears in a
> reasonable time.  If I press twice in a row the 2nd prompt needs
> perceptible longer.
> 
> Does someone have a hint for me how to debug (or even solve) this problem?
> 
> First I wondered why set_next_event is called twice between two timer
> interrupts most of the time.  I found out that the timer is programed
> for the next tick in any case and if nothing needs the next tick, the
> interval is enlarged.  I didn't spend time yet to check if it is
> easier/faster to only program the timer once.

We optimize for the non-idle path, i.e. we keep the timer running as
long as we are not idle. Once we go idle we reprogram it.

I looked at the patch and as far as I can understand it, there is
nothing obviously wrong about it.

One remark: why did you expand the clocksource to be 64 bit? The generic
code handles the 32 bit wrap already, so the expansion in your read
routine is adding overhead. The counter will wrap every 24 seconds, so
there is nothing to worry about.

The behavior you are describing is might be related to some problem with
the clocksource readout, as the reprogramming values are calculated from
there. 

	tglx

Re: Dynamic ticks make system jerking

[Uwe Kleine-Koenig]

Hello,

Thomas Gleixner wrote:
> On Tue, 2007-06-26 at 17:00 +0200, Uwe Kleine-K??nig wrote:
> > If I enable NO_HZ, the system jerks (I hope this is an understandable
> > term ...).   E.g. 
> > 
> > 	# time find /sys
> > 	...
> > 	real    1m 19.52s
> > 	user    0m 0.18s
> > 	sys     0m 0.15s
> > 
> > on a freshly booted machine.  The output comes in several hunks with
> > pausing between them.  With no_hz=off, I get approx. the same.
> 
> it's nohz=off not no_hz=off
Currently I'm not sure, which I was really using.  I think it was the
right one, because dmesg changed.  But anyhow, I will retest if I made
it wrong.
 
> > First I wondered why set_next_event is called twice between two timer
> > interrupts most of the time.  I found out that the timer is programed
> > for the next tick in any case and if nothing needs the next tick, the
> > interval is enlarged.  I didn't spend time yet to check if it is
> > easier/faster to only program the timer once.
> 
> We optimize for the non-idle path, i.e. we keep the timer running as
> long as we are not idle. Once we go idle we reprogram it.
OK, sounds sane.
 
> I looked at the patch and as far as I can understand it, there is
> nothing obviously wrong about it.
What a pity.

> One remark: why did you expand the clocksource to be 64 bit? The generic
> code handles the 32 bit wrap already, so the expansion in your read
> routine is adding overhead. The counter will wrap every 24 seconds, so
> there is nothing to worry about.
OK, I thought it to be better to have 64bit + some overhead.  I will
change that.
 
> The behavior you are describing is might be related to some problem with
> the clocksource readout, as the reprogramming values are calculated from
> there. 
Any hints how I can debug that?

Currently I cannot retest, but I will dig into it again and rereport.

Thanks for your answer.

Best regards
Uwe

-- 
Uwe Kleine-Koenig

http://www.google.com/search?q=speed+of+light%3D

Re: Dynamic ticks make system jerking

[Uwe Kleine-König]

Hello,

Uwe Kleine-König wrote:
> > it's nohz=off not no_hz=off
> Currently I'm not sure, which I was really using.  I think it was the
> right one, because dmesg changed.  But anyhow, I will retest if I made
> it wrong.
OK, I was really using no_hz, and with nohz I got approx the same result
as with CONFIG_NO_HZ=n.  Uups.

> > > First I wondered why set_next_event is called twice between two timer
> > > interrupts most of the time.  I found out that the timer is programed
> > > for the next tick in any case and if nothing needs the next tick, the
> > > interval is enlarged.  I didn't spend time yet to check if it is
> > > easier/faster to only program the timer once.
> > 
> > We optimize for the non-idle path, i.e. we keep the timer running as
> > long as we are not idle. Once we go idle we reprogram it.
> OK, sounds sane.
Probably you understand that better, but your argument only convinced me
for a short time.  Is it really better to program at least once and in
the idle case a 2nd time instead of only once every time.  Moreover
if you program the timer late you can notice if the time to tick is
already over because the timer irq handling took to long (or CONFIG_HZ
is too large).

> > I looked at the patch and as far as I can understand it, there is
> > nothing obviously wrong about it.
> What a pity.
I found the problem, it had only indirectly to do with nohz.  I didn't
acknowledge the serial interrupt but as the timer and the serial need
the same acknowledgement the serial irq got his ack always when the
timer triggerd.  Up to now that delay didn't stick out as the delay was
< 10ms.

> > One remark: why did you expand the clocksource to be 64 bit? The generic
> > code handles the 32 bit wrap already, so the expansion in your read
> > routine is adding overhead. The counter will wrap every 24 seconds, so
> > there is nothing to worry about.
> OK, I thought it to be better to have 64bit + some overhead.  I will
> change that.
done.  (But I reserve the right to evaluate the 64bit case and check how
worse the overhead is :-)

Best regards
Uwe

-- 
Uwe Kleine-König

http://www.google.com/search?q=sin%28pi%2F2%29

Re: Dynamic ticks make system jerking

[Ingo Molnar]

* Uwe Kleine-König <ukleinek@informatik.uni-freiburg.de> wrote:

> I found the problem, it had only indirectly to do with nohz.  I didn't 
> acknowledge the serial interrupt but as the timer and the serial need 
> the same acknowledgement the serial irq got his ack always when the 
> timer triggerd.  Up to now that delay didn't stick out as the delay 
> was < 10ms.

yeah, that makes sense. Now you've probably got a better serial driver 
as a side-effect :-)

	Ingo