lkml.org 
[lkml]   [2014]   [Feb]   [18]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH v2 0/3] Deferrable timers support for timerfd API
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


\
 
 \ /
  Last update: 2014-02-18 21:21    [W:0.166 / U:0.476 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site