From: Alexey Perevalov <a.perevalov@samsung.com>
To: Thomas Gleixner <tglx@linutronix.de>
Cc: John Stultz <john.stultz@linaro.org>,
linux-kernel@vger.kernel.org, anton@enomsg.org,
kyungmin.park@samsung.com, akpm@linux-foundation.org,
cw00.choi@samsung.com
Subject: Re: [PATCH v2 0/3] Deferrable timers support for timerfd API
Date: Mon, 17 Feb 2014 18:15:14 +0400 [thread overview]
Message-ID: <53021972.4050400@samsung.com> (raw)
In-Reply-To: <alpine.DEB.2.02.1402161634590.21991@ionos.tec.linutronix.de>
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
next prev parent reply other threads:[~2014-02-17 14:15 UTC|newest]
Thread overview: 28+ messages / expand[flat|nested] mbox.gz Atom feed top
2014-01-13 10:43 [PATCH v2 0/3] Deferrable timers support for timerfd API Alexey Perevalov
2014-01-13 10:43 ` [PATCH v2 1/3] kernel/time: Add new helpers to convert ktime to/from jiffies Alexey Perevalov
2014-01-14 0:15 ` Chanwoo Choi
2014-01-13 10:43 ` [PATCH v2 2/3] timerfd: Factor out timer-type unspecific timerfd_expire() Alexey Perevalov
2014-01-13 10:43 ` [PATCH v2 3/3] timerfd: Add support for deferrable timers Alexey Perevalov
2014-01-13 15:30 ` [PATCH v2 0/3] Deferrable timers support for timerfd API Alexey Perevalov
2014-01-13 17:36 ` Andi Kleen
2014-01-14 6:44 ` Alexey Perevalov
2014-01-21 19:12 ` John Stultz
2014-01-27 7:12 ` Alexey Perevalov
2014-02-04 16:10 ` Thomas Gleixner
2014-02-05 6:43 ` Alexey Perevalov
2014-02-05 21:41 ` Thomas Gleixner
2014-02-05 22:02 ` John Stultz
2014-02-05 22:16 ` Thomas Gleixner
2014-02-06 17:38 ` Alexey Perevalov
2014-02-06 17:47 ` John Stultz
2014-02-06 20:50 ` Thomas Gleixner
2014-02-07 17:41 ` Alexey Perevalov
2014-02-16 15:20 ` Alexey Perevalov
2014-02-16 15:39 ` Thomas Gleixner
2014-02-17 14:15 ` Alexey Perevalov [this message]
2014-02-18 19:43 ` Thomas Gleixner
2014-02-18 19:48 ` Alexey Perevalov
2014-02-18 22:33 ` Thomas Gleixner
2014-02-19 7:08 ` Alexey Perevalov
2014-02-03 6:54 ` Alexey Perevalov
2014-02-03 23:58 ` John Stultz
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=53021972.4050400@samsung.com \
--to=a.perevalov@samsung.com \
--cc=akpm@linux-foundation.org \
--cc=anton@enomsg.org \
--cc=cw00.choi@samsung.com \
--cc=john.stultz@linaro.org \
--cc=kyungmin.park@samsung.com \
--cc=linux-kernel@vger.kernel.org \
--cc=tglx@linutronix.de \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).