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:
signature.asc
Description: PGP signature
