Re: [tip:timers/core] kselftests: timers: set-timer-lat: Tweak reporting when timer fires early

[Prarit Bhargava <prarit@redhat.com>]

On 09/19/2017 11:36 PM, John Stultz wrote:
> On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan <shuah@kernel.org> wrote:
>> Hi Greg,
>>
>> On 08/20/2017 03:56 AM, tip-bot for Greg Hackmann wrote:
>>> Commit-ID:  a524b1184b8e86141d689fa78ad150fbf2db9b4c
>>> Gitweb:     http://git.kernel.org/tip/a524b1184b8e86141d689fa78ad150fbf2db9b4c
>>> Author:     Greg Hackmann <ghackmann@google.com>
>>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
>>> Committer:  John Stultz <john.stultz@linaro.org>
>>> CommitDate: Thu, 17 Aug 2017 12:14:54 -0700
>>>
>>> kselftests: timers: set-timer-lat: Tweak reporting when timer fires early
>>>
>>> Rather than printing an error inside the alarm signal handler, set a
>>> flag that we check later.  This keeps the test from spamming the console
>>> every time the alarm fires early.  It also fixes the test exiting with
>>> error code 0 if this was the only test failure.
>>>
>>> Cc: Thomas Gleixner <tglx@linutronix.de>
>>> Cc: Ingo Molnar <mingo@kernel.org>
>>> Cc: Miroslav Lichvar <mlichvar@redhat.com>
>>> Cc: Richard Cochran <richardcochran@gmail.com>
>>> Cc: Prarit Bhargava <prarit@redhat.com>
>>> Cc: Stephen Boyd <stephen.boyd@linaro.org>
>>> Cc: Shuah Khan <shuah@kernel.org>
>>> Cc: linux-kselftest@vger.kernel.org
>>> Signed-off-by: Greg Hackmann <ghackmann@google.com>
>>> Signed-off-by: John Stultz <john.stultz@linaro.org>
>>
>> This commit is making the set-timer-lat hang. I reverted this commit
>> and there is no hang. Could you please take a look and see if this
>> commit should be reverted.
>>
>> make kselftest as well as make -C tools/testing/selftests/timers run_tests
>> hang.
> 
> Do you have any specific details as to how the test hangs? (ie: Log
> data, as in where it might be when it hangs? Any details about the
> machine?)
> 
> I'm not seeing it so far in my testing.
> 

I just ran it here and don't see any issues.  I'll try on a few other boxes
to make sure.

# make -C tools/testing/selftests/timers run_tests
make: Entering directory `/home/linux/tools/testing/selftests/timers'
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  posix_timers.c  -o
/home/linux/tools/testing/selftests/timers/posix_timers
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  nanosleep.c  -o
/home/linux/tools/testing/selftests/timers/nanosleep
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  nsleep-lat.c  -o
/home/linux/tools/testing/selftests/timers/nsleep-lat
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  set-timer-lat.c  -o
/home/linux/tools/testing/selftests/timers/set-timer-lat
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  mqueue-lat.c  -o
/home/linux/tools/testing/selftests/timers/mqueue-lat
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  inconsistency-check.c  -o
/home/linux/tools/testing/selftests/timers/inconsistency-check
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  raw_skew.c  -o
/home/linux/tools/testing/selftests/timers/raw_skew
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  threadtest.c  -o
/home/linux/tools/testing/selftests/timers/threadtest
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  rtctest.c  -o
/home/linux/tools/testing/selftests/timers/rtctest
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  alarmtimer-suspend.c   -o
alarmtimer-suspend
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  valid-adjtimex.c   -o
valid-adjtimex
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  adjtick.c   -o adjtick
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  change_skew.c   -o change_skew
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  skew_consistency.c   -o
skew_consistency
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  clocksource-switch.c   -o
clocksource-switch
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  freq-step.c   -o freq-step
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  leap-a-day.c   -o leap-a-day
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  leapcrash.c   -o leapcrash
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  set-tai.c   -o set-tai
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  set-2038.c   -o set-2038
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  set-tz.c   -o set-tz
gcc -O3 -Wl,-no-as-needed -Wall  -lrt -lpthread -lm  rtctest_setdate.c   -o
rtctest_setdate
TAP version 13
selftests: posix_timers
========================================
Testing posix timers. False negative may happen on CPU execution
based timers if other threads run on the CPU...
Check itimer virtual... [OK]
Check itimer prof... [OK]
Check itimer real... [OK]
Check timer_create() per thread... [OK]
Check timer_create() per process... [OK]
Pass 0 Fail 0 Xfail 0 Xpass 0 Skip 0 Error 0
1..0
ok 1..1 selftests: posix_timers [PASS]
selftests: nanosleep
========================================
Nanosleep CLOCK_REALTIME                  [OK]
Nanosleep CLOCK_MONOTONIC                 [OK]
Nanosleep CLOCK_MONOTONIC_RAW             [UNSUPPORTED]
Nanosleep CLOCK_REALTIME_COARSE           [UNSUPPORTED]
Nanosleep CLOCK_MONOTONIC_COARSE          [UNSUPPORTED]
Nanosleep CLOCK_BOOTTIME                  [OK]
Nanosleep CLOCK_REALTIME_ALARM            [OK]
Nanosleep CLOCK_BOOTTIME_ALARM            [OK]
Nanosleep CLOCK_TAI                       [OK]
Pass 0 Fail 0 Xfail 0 Xpass 0 Skip 0 Error 0
1..0
ok 1..2 selftests: nanosleep [PASS]
selftests: nsleep-lat
========================================
  nsleep latency CLOCK_REALTIME             [OK]
nsleep latency CLOCK_MONOTONIC            [OK]
nsleep latency CLOCK_MONOTONIC_RAW        [UNSUPPORTED]
nsleep latency CLOCK_REALTIME_COARSE      [UNSUPPORTED]
nsleep latency CLOCK_MONOTONIC_COARSE     [UNSUPPORTED]
nsleep latency CLOCK_BOOTTIME             [OK]
nsleep latency CLOCK_REALTIME_ALARM       [OK]
nsleep latency CLOCK_BOOTTIME_ALARM       [OK]
nsleep latency CLOCK_TAI                  [OK]
Pass 0 Fail 0 Xfail 0 Xpass 0 Skip 0 Error 0
1..0
ok 1..3 selftests: nsleep-lat [PASS]
selftests: set-timer-lat
========================================
Setting timers for every 1 seconds
CLOCK_REALTIME         ABSTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_REALTIME         ABSTIME PERIODIC max latency:     100795 ns : [OK]
CLOCK_REALTIME         RELTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_REALTIME         RELTIME PERIODIC max latency:     103484 ns : [OK]
CLOCK_REALTIME         ABSTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_REALTIME         ABSTIME ONE-SHOT max latency:      78764 ns : [OK]
CLOCK_REALTIME         ABSTIME ONE-SHOT count:                   1 : [OK]
CLOCK_REALTIME         RELTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_REALTIME         RELTIME ONE-SHOT max latency:     107690 ns : [OK]
CLOCK_REALTIME         RELTIME ONE-SHOT count:                   1 : [OK]
CLOCK_MONOTONIC        ABSTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_MONOTONIC        ABSTIME PERIODIC max latency:      97220 ns : [OK]
CLOCK_MONOTONIC        RELTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_MONOTONIC        RELTIME PERIODIC max latency:      99225 ns : [OK]
CLOCK_MONOTONIC        ABSTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_MONOTONIC        ABSTIME ONE-SHOT max latency:      74499 ns : [OK]
CLOCK_MONOTONIC        ABSTIME ONE-SHOT count:                   1 : [OK]
CLOCK_MONOTONIC        RELTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_MONOTONIC        RELTIME ONE-SHOT max latency:      98656 ns : [OK]
CLOCK_MONOTONIC        RELTIME ONE-SHOT count:                   1 : [OK]
CLOCK_BOOTTIME         ABSTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_BOOTTIME         ABSTIME PERIODIC max latency:     107843 ns : [OK]
CLOCK_BOOTTIME         RELTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_BOOTTIME         RELTIME PERIODIC max latency:     110695 ns : [OK]
CLOCK_BOOTTIME         ABSTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_BOOTTIME         ABSTIME ONE-SHOT max latency:      73135 ns : [OK]
CLOCK_BOOTTIME         ABSTIME ONE-SHOT count:                   1 : [OK]
CLOCK_BOOTTIME         RELTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_BOOTTIME         RELTIME ONE-SHOT max latency:      94899 ns : [OK]
CLOCK_BOOTTIME         RELTIME ONE-SHOT count:                   1 : [OK]
CLOCK_REALTIME_ALARM   ABSTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_REALTIME_ALARM   ABSTIME PERIODIC max latency:      96219 ns : [OK]
CLOCK_REALTIME_ALARM   RELTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_REALTIME_ALARM   RELTIME PERIODIC max latency:     104495 ns : [OK]
CLOCK_REALTIME_ALARM   ABSTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_REALTIME_ALARM   ABSTIME ONE-SHOT max latency:      76691 ns : [OK]
CLOCK_REALTIME_ALARM   ABSTIME ONE-SHOT count:                   1 : [OK]
CLOCK_REALTIME_ALARM   RELTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_REALTIME_ALARM   RELTIME ONE-SHOT max latency:     101372 ns : [OK]
CLOCK_REALTIME_ALARM   RELTIME ONE-SHOT count:                   1 : [OK]
CLOCK_BOOTTIME_ALARM   ABSTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_BOOTTIME_ALARM   ABSTIME PERIODIC max latency:      98144 ns : [OK]
CLOCK_BOOTTIME_ALARM   RELTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_BOOTTIME_ALARM   RELTIME PERIODIC max latency:     104286 ns : [OK]
CLOCK_BOOTTIME_ALARM   ABSTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_BOOTTIME_ALARM   ABSTIME ONE-SHOT max latency:      72154 ns : [OK]
CLOCK_BOOTTIME_ALARM   ABSTIME ONE-SHOT count:                   1 : [OK]
CLOCK_BOOTTIME_ALARM   RELTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_BOOTTIME_ALARM   RELTIME ONE-SHOT max latency:      81766 ns : [OK]
CLOCK_BOOTTIME_ALARM   RELTIME ONE-SHOT count:                   1 : [OK]
CLOCK_TAI              ABSTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_TAI              ABSTIME PERIODIC max latency:     100615 ns : [OK]
CLOCK_TAI              RELTIME PERIODIC timer fired early:       0 : [OK]
CLOCK_TAI              RELTIME PERIODIC max latency:     101477 ns : [OK]
CLOCK_TAI              ABSTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_TAI              ABSTIME ONE-SHOT max latency:      73973 ns : [OK]
CLOCK_TAI              ABSTIME ONE-SHOT count:                   1 : [OK]
CLOCK_TAI              RELTIME ONE-SHOT timer fired early:       0 : [OK]
CLOCK_TAI              RELTIME ONE-SHOT max latency:      98194 ns : [OK]
CLOCK_TAI              RELTIME ONE-SHOT count:                   1 : [OK]
Pass 0 Fail 0 Xfail 0 Xpass 0 Skip 0 Error 0
1..0
ok 1..4 selftests: set-timer-lat [PASS]
selftests: mqueue-lat
========================================
Mqueue latency :                          [OK]
Pass 0 Fail 0 Xfail 0 Xpass 0 Skip 0 Error 0
1..0
ok 1..5 selftests: mqueue-lat [PASS]
selftests: inconsistency-check
========================================
Consistent CLOCK_REALTIME                 [OK]
Consistent CLOCK_MONOTONIC                [OK]
Consistent CLOCK_PROCESS_CPUTIME_ID       [OK]
Consistent CLOCK_THREAD_CPUTIME_ID        [OK]
Consistent CLOCK_MONOTONIC_RAW            [OK]
Consistent CLOCK_REALTIME_COARSE          [OK]
Consistent CLOCK_MONOTONIC_COARSE         [OK]
Consistent CLOCK_BOOTTIME                 [OK]
Consistent CLOCK_REALTIME_ALARM           [OK]
Consistent CLOCK_BOOTTIME_ALARM           [OK]
Consistent CLOCK_TAI                      [OK]
Pass 0 Fail 0 Xfail 0 Xpass 0 Skip 0 Error 0
1..0
ok 1..6 selftests: inconsistency-check [PASS]
selftests: raw_skew
========================================
Estimating clock drift: 41.659(est) 40.697(act) [OK]
Pass 0 Fail 0 Xfail 0 Xpass 0 Skip 0 Error 0
1..0
ok 1..7 selftests: raw_skew [PASS]
selftests: threadtest
========================================
Wed, 20 Sep 2017 08:17:18 -0400
Testing consistency with 8 threads for 30 seconds: [OK]
Pass 0 Fail 0 Xfail 0 Xpass 0 Skip 0 Error 0
1..0
ok 1..8 selftests: threadtest [PASS]
selftests: rtctest
========================================

                        RTC Driver Test Example.

Counting 5 update (1/sec) interrupts from reading /dev/rtc0: 1 2 3 4 5
Again, from using select(2) on /dev/rtc: 1 2 3 4 5

Current RTC date/time is 20-9-2017, 08:17:58.
Alarm time now set to 08:18:03.
Waiting 5 seconds for alarm... okay. Alarm rang.

Periodic IRQ rate is 1024Hz.
Counting 20 interrupts at:
2Hz:     1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
4Hz:     1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
8Hz:     1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
16Hz:    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
32Hz:    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
64Hz:    1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20

                         *** Test complete ***
ok 1..9 selftests: rtctest [PASS]
make: Leaving directory `/home/linux/tools/testing/selftests/timers'

P.