HRTimer causing rtctest to fail

[Felipe Balbi <felipe.balbi@linux.intel.com>]

[-- Attachment #1: Type: text/plain, Size: 2767 bytes --]


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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]