timer_settime01 from ubuntu_ltp_syscalls failed on bionic /aws-4.15 on c5.metal

[Kelsey Steele]

21367. 09/25 08:38:06 DEBUG| utils:0153| [stdout] startup='Fri Sep 25 08:37:00 2020'
21368. 09/25 08:38:06 DEBUG| utils:0153| [stdout] tst_test.c:1250: TINFO: Timeout per run is 0h 05m 00s
21369. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:85: TINFO: Testing variant: syscall with old kernel spec
21370. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:96: TINFO: Testing for general initialization:
21371. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_REALTIME) passed
21372. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_MONOTONIC) passed
21373. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_PROCESS_CPUTIME_ID) passed
21374. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_THREAD_CPUTIME_ID) passed
21375. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_BOOTTIME) passed
21376. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_BOOTTIME_ALARM) passed
21377. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_REALTIME_ALARM) passed
21378. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_TAI) passed
21379. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:96: TINFO: Testing for setting old_value:
21380. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_REALTIME) passed
21381. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_MONOTONIC) passed
21382. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_PROCESS_CPUTIME_ID) passed
21383. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_THREAD_CPUTIME_ID) passed
21384. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_BOOTTIME) passed
21385. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_BOOTTIME_ALARM) passed
21386. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_REALTIME_ALARM) passed
21387. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_TAI) passed
21388. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:96: TINFO: Testing for using periodic timer:
21389. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_REALTIME) passed
21390. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_MONOTONIC) passed
21391. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_PROCESS_CPUTIME_ID) passed
21392. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_THREAD_CPUTIME_ID) passed
21393. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_BOOTTIME) passed
21394. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_BOOTTIME_ALARM) passed
21395. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_REALTIME_ALARM) passed
21396. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_TAI) passed
21397. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:96: TINFO: Testing for using absolute time:
21398. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_REALTIME) passed
21399. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:160: TFAIL: timer_gettime(CLOCK_MONOTONIC) reported bad values (0: 50000034): SUCCESS (0)
21400. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_MONOTONIC) passed
21401. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_PROCESS_CPUTIME_ID) passed
21402. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_THREAD_CPUTIME_ID) passed
21403. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_BOOTTIME) passed
21404. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_BOOTTIME_ALARM) passed
21405. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_REALTIME_ALARM) passed
21406. 09/25 08:38:06 DEBUG| utils:0153| [stdout] timer_settime01.c:170: TPASS: timer_settime(CLOCK_TAI) passed
21407. 09/25 08:38:06 DEBUG| utils:0153| [stdout]
21408. 09/25 08:38:06 DEBUG| utils:0153| [stdout] HINT: You _MAY_ be missing kernel fixes, see:
21409. 09/25 08:38:06 DEBUG| utils:0153| [stdout]
21410. 09/25 08:38:06 DEBUG| utils:0153| [stdout] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=f18ddc13af98
21411. 09/25 08:38:06 DEBUG| utils:0153| [stdout] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=e86fea764991
21412. 09/25 08:38:06 DEBUG| utils:0153| [stdout]
21413. 09/25 08:38:06 DEBUG| utils:0153| [stdout] Summary:
21414. 09/25 08:38:06 DEBUG| utils:0153| [stdout] passed 32
21415. 09/25 08:38:06 DEBUG| utils:0153| [stdout] failed 1
21416. 09/25 08:38:06 DEBUG| utils:0153| [stdout] skipped 0
21417. 09/25 08:38:06 DEBUG| utils:0153| [stdout] warnings 0
21418. 09/25 08:38:06 DEBUG| utils:0153| [stdout] tag=timer_settime01 stime=1601023020 dur=2 exit=exited stat=1 core=no cu=202 cs=0

[Thadeu Lima de Souza Cascardo (cascardo)]

The reading back of the timer seems relatively recent.

commit b34e243e85dde089dbb84dd6d63dc0fe95b4d504
Author: Viresh Kumar <email address hidden>
Date: Wed Jul 8 16:01:04 2020 +0530

    syscalls/timer_settime01: Make sure the timer fires

    This patch improves the testcase by doing multiple things:

    - Make sure the timer fires and catch the signals.

    - Verify the values set to the itimerspec by reading them again using
      timer_gettime() syscalls.

    - Reduce the timer interval, 5 seconds was way too much.

    Signed-off-by: Viresh Kumar <email address hidden>
    Signed-off-by: Cyril Hrubis <email address hidden>

That said, we are off by 34 nanoseconds. Not sure that is a strict requirement to have the alarm be triggered by not more than the value given. But this is so close, I would hardly designate it as a bug. Add to it that this is using ABSTIME. There could be a hidden bug here, but I would bet this is not a regression and it hardly matters much. And it is not anyone of the two commits referred by the test.

Cascardo.

[Thadeu Lima de Souza Cascardo (cascardo)]

Ah, I see now what is happening. The userspace code is dealing with microseconds, while the syscalls all deal with nanoseconds.

So, when using absolute time, we read the clock (in nanoseconds), add that to our microseconds value after converting (that is, rounding the value), then set the timer, and read it back.

Take this run, for example:
[pid 27982] timer_create(CLOCK_MONOTONIC, NULL, [0]) = 0
[pid 27982] clock_gettime(CLOCK_MONOTONIC, {tv_sec=53718, tv_nsec=537178810}) = 0
[pid 27982] timer_settime(0, TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=53718, tv_nsec=587179000}}, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}) = 0
[pid 27982] timer_gettime(0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=49842203}}) = 0

We read the time and set it 587179000 - 537178810 = 50000190 nanoseconds in the future, which is more than our 50000 microseconds. No surprise that, if you are fast enough, you are going to read a larger value back.

Not a kernel bug!
Cascardo.

[Thadeu Lima de Souza Cascardo (cascardo)]

http://lists.linux.it/pipermail/ltp/2020-October/019254.html

Sent a fix to LTP, waiting to hear from it.

The good thing is that I reproduced this by using clocksource=jiffies when booting. And the test change fixed it.

Now I wonder what is the clocksource like at this AWS instance.

Cascardo.

[Po-Hsu Lin (cypressyew)]

Patch applied upstream,

https://github.com/linux-test-project/ltp/commit/cba1f26a8fb53577a7910f94c725316815cc8f0f

We can close this bug if it's not spotted on bionic /aws-4.15 on c5.metal anymore.