Messages in this thread | | | Date | Tue, 18 Feb 2014 20:43:21 +0100 (CET) | From | Thomas Gleixner <> | Subject | Re: [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
| |