lkml.org 
[lkml]   [2018]   [Feb]   [27]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
From
SubjectHRTimer causing rtctest to fail
Date

Hi folks,

I'm facing an odd problem with v4.16-rc2 (also reproducible on v4.15
final) where rtctest fails sometimes which PIE coming too late with
frequencies >= 1024 Hz.

I've modified rtctest.c a bit so that it continues running even after
first failure just so I could get a glimpse of how many times it fails.

Here are the results:

Error 1024Hz i 17/20 diff 1089/976

Error 2048Hz i 2/20 diff 538/488
Error 2048Hz i 9/20 diff 558/488
Error 2048Hz i 16/20 diff 560/488

Error 4096Hz i 2/20 diff 305/244
Error 4096Hz i 7/20 diff 288/244
Error 4096Hz i 9/20 diff 285/244
Error 4096Hz i 11/20 diff 310/244
Error 4096Hz i 16/20 diff 284/244
Error 4096Hz i 20/20 diff 317/244


I added a few trace_printk() calls around rtc_dev_read() (and some other
functions) and captured the time for entry and exit of that function. I
noticed that HRTimer fires way too late and also way too early
sometimes. On the order of 100+ us.

For example with iterations 17 of 1024 Hz (seen above) and 18 (also of
1024 Hz) I captured the following time stamps (all in uS):

| Start | End | Expected End | Diff |
|----------+----------+--------------+------|
| 35900626 | 35901711 | 35901603 | -108 | (too late)
| 35901826 | 35902628 | 35902803 | 174 | (too early)

I can't come up with a proper explanation as to why HRTimer is firing at
such wildly odd extremes. On most of the measurements, HRTimer executes
within 5 uS of scheduled time and I can't convince myself that
scheduling latency would get so high all of a sudden. Specially
considering I'm testing with a 4 core machine and there's nothing else
running on it. It's mostly idle.

Any hints as to how to track down this problem further? Also, do folks
agree that rtctest's 10% slack should also be considered for too early
firing times? I mean:

diff --git a/tools/testing/selftests/timers/rtctest.c b/tools/testing/selftests/timers/rtctest.c
index 411eff625e66..99aa46fc556c 100644
--- a/tools/testing/selftests/timers/rtctest.c
+++ b/tools/testing/selftests/timers/rtctest.c
@@ -317,7 +317,8 @@ int main(int argc, char **argv)
gettimeofday(&end, NULL);
timersub(&end, &start, &diff);
if (diff.tv_sec > 0 ||
- diff.tv_usec > ((1000000L / tmp) * 1.10)) {
+ diff.tv_usec > ((1000000L / tmp) * 1.10) ||
+ diff.tv_usec < ((1000000L / tmp) * 0.9)) {
fprintf(stderr, "\nPIE delta error: %ld.%06ld should be close to 0.%06ld\n",
diff.tv_sec, diff.tv_usec,
(1000000L / tmp));
--
balbi
[unhandled content-type:application/pgp-signature]
\
 
 \ /
  Last update: 2018-02-27 14:23    [W:0.068 / U:0.276 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site