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

[Alexey Perevalov]

On 02/16/2014 07:39 PM, Thomas Gleixner wrote:
> On Sun, 16 Feb 2014, Alexey Perevalov wrote:
> > As I understand main idea in hrtimer.c was do not decrement expires_next in
> > case of DEFERRABLE timers type.
> > Such small average delay could be explained: it's due higher resolution, and
> > cpu is not in idle when we in hrtimer_interrupt,
> > with timer_list decrementing process not so often.
> > In this case it's hard to me to explain such small "time delta", it occurs
> > almost every time we have larger delay.
> Well, the point of deferrable timers is that they get executed, when
> the cpu is not idle, i.e. running some other timers as well
>
> I did not test my patch and I have no idea whether it really does what
> it should do, but tracing should tell you rather fast.
>
> So w/o instrumenting the kernel you can't tell why a timer is
> expired. Just looking at random numbers does not help. You need to
> create a proper test scenario which makes sure that the system goes
> into an extended nohz idle and then check whether the timers are
> deferred over that idle time.
>
> Thanks,
>
> 	tglx
My system is NO_HZ=ON, I'm sure and timer_list results is proof it.
Regarding to previous result, yes, you right the rootcause of such 
insane deviation was a glitch in logging (but only for really big 
deviation).

I traced it by ftrace.
Bellow is trace-cmd report for HRTIMER_BASE_MONOTONIC_DEFERRABLE.
(it's only part, but it's long part, summary right after the log)

          <idle>-0     [000]   339.148371: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2154000086890 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.148391: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2154300000000 softexpires=2154300000000
          <idle>-0     [000]   339.157821: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2154328094166 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.157837: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2154600000000 softexpires=2154600000000
          <idle>-0     [000]   339.170895: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2154632081099 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.170915: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2154900000000 softexpires=2154900000000
          <idle>-0     [000]   339.180459: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2154912090729 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.180475: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2155200000000 softexpires=2155200000000
          <idle>-0     [000]   339.204672: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2155228092094 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.204694: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2155500000000 softexpires=2155500000000
          <idle>-0     [000]   339.213807: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2155532081987 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.213823: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2155800000000 softexpires=2155800000000
          <idle>-0     [000]   339.226986: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2155816087467 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.227007: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2156100000000 softexpires=2156100000000
          <idle>-0     [000]   339.272420: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2156101736770 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.272438: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2156400000000 softexpires=2156400000000
          <idle>-0     [000]   339.286856: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2156432078659 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.286877: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2156700000000 softexpires=2156700000000
          <idle>-0     [000]   339.363097: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2156728086117 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.363122: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2157000000000 softexpires=2157000000000
          <idle>-0     [000]   339.411552: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2157000091028 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.411576: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2157300000000 softexpires=2157300000000
          <idle>-0     [000]   339.492448: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2157328089996 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.492471: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2157600000000 softexpires=2157600000000
          <idle>-0     [000]   339.526305: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2157600425537 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.526341: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2157900000000 softexpires=2157900000000
          <idle>-0     [000]   339.572977: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2157928085502 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.572997: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2158200000000 softexpires=2158200000000
            Xorg-1166  [000]   339.658862: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2158200013165 function=timerfd_tmrproc/0x0
            Xorg-1166  [000]   339.658893: hrtimer_start: 
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2158500000000 softexpires=2158500000000
          <idle>-0     [000]   339.694244: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2158532090801 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.694263: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2158800000000 softexpires=2158800000000
          <idle>-0     [000]   339.769293: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2158816038362 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.769316: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2159100000000 softexpires=2159100000000
          <idle>-0     [000]   339.808105: hrtimer_expire_entry: 
hrtimer=0xffffffffa04a9280 now=2159122612405 function=timerfd_tmrproc/0x0
          <idle>-0     [000]   339.808127: hrtimer_start:        
hrtimer=0xffffffffa04a9280 function=timerfd_tmrproc 
expires=2159400000000 softexpires=2159400000000

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.

Here is the summary for timer_list, timer is charged with 200 ms interval:

now value | difference with previous value
4295653665|
4295653615|    200000000
4295653563|    208000000
4295653500|    252000000
4295653438|    248000000
4295653365|    292000000
4295653313|    208000000
4295653248|    260000000
4295653198|    200000000
4295653140|    232000000
4295653090|    200000000
4295653038|    208000000
4295652988|    200000000

Average interval is 225 666 666.666667, 25ms delay, it's better.
And for 300ms timer_list shows following result:

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.
------------------------------------------------------------------------
It's log for 300ms timer_list, you could skip it
------------------------------------------------------------------------
<idle>-0     [000]  1914.815152: timer_expire_entry: 
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298169828
          <idle>-0     [000]  1914.815183: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298169903 
[timeout=75]
          <idle>-0     [000]  1914.862357: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298169903
          <idle>-0     [000]  1914.862378: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298169978 
[timeout=75]
         firefox-2898  [000]  1914.901656: timer_expire_entry: 
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298169978
         firefox-2898  [000]  1914.901680: timer_start: 
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170053 
[timeout=75]
          <idle>-0     [000]  1914.946591: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170053
          <idle>-0     [000]  1914.946625: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170128 
[timeout=75]
          <idle>-0     [000]  1914.994114: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170129
          <idle>-0     [000]  1914.994137: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170204 
[timeout=75]
          <idle>-0     [000]  1915.035696: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170212
          <idle>-0     [000]  1915.035719: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170287 
[timeout=75]
          <idle>-0     [000]  1915.082886: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170287
          <idle>-0     [000]  1915.082920: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170362 
[timeout=75]
          <idle>-0     [000]  1915.141888: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170387
          <idle>-0     [000]  1915.141923: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170462 
[timeout=75]
     soffice.bin-3237  [000]  1915.201642: timer_expire_entry: 
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170483
     soffice.bin-3237  [000]  1915.201665: timer_start: 
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170558 
[timeout=75]
          <idle>-0     [000]  1915.264248: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170562
          <idle>-0     [000]  1915.264271: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170637 
[timeout=75]
          <idle>-0     [000]  1915.309599: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170637
          <idle>-0     [000]  1915.309628: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170712 
[timeout=75]
          <idle>-0     [000]  1915.354971: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170712
          <idle>-0     [000]  1915.354986: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170787 
[timeout=75]
          <idle>-0     [000]  1915.398761: timer_expire_entry:   
timer=0xffffffffa05c2280 function=test_def_timer_fn now=4298170787
          <idle>-0     [000]  1915.398794: timer_start:          
timer=0xffffffffa05c2280 function=test_def_timer_fn expires=4298170862 
[timeout=75]


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


--
Best regards,
Alexey Perevalov
--
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/