linux-kernel - HRTimer causing rtctest to fail

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite for Android: free password hash cracker in your pocket

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Date:   Tue, 27 Feb 2018 15:20:58 +0200
From:   Felipe Balbi <felipe.balbi@...ux.intel.com>
To:     Thomas Gleixner <tglx@...utronix.de>,
        Alessandro Zummo <a.zummo@...ertech.it>,
        Alexandre Belloni <alexandre.belloni@...e-electrons.com>
Cc:     linux-kernel@...r.kernel.org, linux-rtc@...r.kernel.org
Subject: HRTimer causing rtctest to fail

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

Download attachment "signature.asc" of type "application/pgp-signature" (833 bytes)