Re: [PATCH v2 0/3] Deferrable timers support for timerfd API

[Thomas Gleixner]

On Mon, 17 Feb 2014, Alexey Perevalov wrote:
> On 02/16/2014 07:39 PM, Thomas Gleixner wrote:

> Here is the summary:
> 
> now value    |  difference with previous value
> 2159122612405|
> 2158816038362|    306574043
> 2158532090801|    283947561
> 2158200013165|    332077636
> 2157928085502|    271927663
> 2157600425537|    327659965
> 2157328089996|    272335541
> 2157000091028|    327998968
> 2156728086117|    272004911
> 2156432078659|    296007458
> 2156101736770|    330341889
> 2155816087467|    285649303
> 2155532081987|    284005480
> 2155228092094|    303989893
> 2154912090729|    316001365
> 2154632081099|    280009630
> 2154328094166|    303986933
> 2154000086890|    328007276
> 
> Timer was charged with 300ms interval. And we see difference in neighborhood
>  of point 300 000 000 - 300ms. The average value as we can see:
> 301325030.294118
>  - the average delay is 1 ms.

Math is hard, right?

Lets look at the trace data:

> hrtimer=0xffffffffa04a9280 now=2154000086890 function=timerfd_tmrproc/0x0
>           <idle>-0     [000]   339.148391: hrtimer_start:
> hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc expires=2154300000000
> softexpires=2154300000000

expires=2154300000000

>           <idle>-0     [000]   339.157821: hrtimer_expire_entry:
> hrtimer=0xffffffffa04a9280 now=2154328094166 function=timerfd_tmrproc/0x0

now=2154328094166 

-> delay = 2154328094166 - 2154300000000 = 28094166 = 28ms


>           <idle>-0     [000]   339.157837: hrtimer_start:
> hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc expires=2154600000000
> softexpires=2154600000000

expires=2154600000000

>           <idle>-0     [000]   339.170895: hrtimer_expire_entry:
> hrtimer=0xffffffffa04a9280 now=2154632081099 function=timerfd_tmrproc/0x0

now=2154632081099

-> delay = 2154632081099 - 2154600000000 = 32081099 = 32ms

You cannot sum up the delta between the expiry times when you use an
timer on an absolute time line. You need to look at the delta between
the programmed expiry time and the actual expiry time. That tells you
the deferred time. And running your excerpt through a filter tells me:

Delta:  28.0ms
Delta:  32.0ms
Delta:  12.0ms
Delta:  28.0ms
Delta:  32.0ms
Delta:  16.0ms
Delta:   1.0ms
Delta:  32.0ms
Delta:  28.0ms
Delta:   0.0ms
Delta:  28.0ms
Delta:   0.0ms
Delta:  28.0ms
Delta:   0.0ms
Delta:  32.0ms
Delta:  16.0ms
Delta:  22.0ms

Avg:    19.0ms

> 4298170712|    300000000
> 4298170637|    300000000
> 4298170562|    300000000
> 4298170483|    316000000
> 4298170387|    384000000
> 4298170287|    400000000
> 4298170212|    300000000
> 4298170129|    332000000
> 4298170053|    304000000
> 4298169978|    300000000
> 4298169903|    300000000
> 4298169828|    300000000
> 
> Average delay here is 20ms.

Your trace tells a different story:

Delta:   0.0ms
Delta:   0.0ms
Delta:   0.0ms
Delta:   1.0ms
Delta:   8.0ms
Delta:   0.0ms
Delta:  25.0ms
Delta:  21.0ms
Delta:   4.0ms
Delta:   0.0ms
Delta:   0.0ms
Delta:   0.0ms

Avg:     4.0ms

> Maybe it's due cpuidle implementation or clock_device on my system. It was
> MENU cpuidle governor.

I fear it's something else ...

Thanks,

	tglx
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/