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

From: Prarit Bhargava
Date: Wed Sep 20 2017 - 08:31:18 EST

Next message: Jens Axboe: "Re: [PATCH 6/6] fs-writeback: only allow one inflight and pending !nr_pages flush"
Previous message: Ulf Hansson: "Re: [PATCH] PM: Document rules on using pm_runtime_resume() in system suspend callbacks"
In reply to: John Stultz: "Re: [tip:timers/core] kselftests: timers: set-timer-lat: Tweak reporting when timer fires early"
Next in thread: Shuah Khan: "Re: [tip:timers/core] kselftests: timers: set-timer-lat: Tweak reporting when timer fires early"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On 09/19/2017 11:36 PM, John Stultz wrote:
> On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan <shuah@xxxxxxxxxx> 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@xxxxxxxxxx>
>>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
>>> Committer: John Stultz <john.stultz@xxxxxxxxxx>
>>> 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@xxxxxxxxxxxxx>
>>> Cc: Ingo Molnar <mingo@xxxxxxxxxx>
>>> Cc: Miroslav Lichvar <mlichvar@xxxxxxxxxx>
>>> Cc: Richard Cochran <richardcochran@xxxxxxxxx>
>>> Cc: Prarit Bhargava <prarit@xxxxxxxxxx>
>>> Cc: Stephen Boyd <stephen.boyd@xxxxxxxxxx>
>>> Cc: Shuah Khan <shuah@xxxxxxxxxx>
>>> Cc: linux-kselftest@xxxxxxxxxxxxxxx
>>> Signed-off-by: Greg Hackmann <ghackmann@xxxxxxxxxx>
>>> Signed-off-by: John Stultz <john.stultz@xxxxxxxxxx>
>>
>> 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.

Next message: Jens Axboe: "Re: [PATCH 6/6] fs-writeback: only allow one inflight and pending !nr_pages flush"
Previous message: Ulf Hansson: "Re: [PATCH] PM: Document rules on using pm_runtime_resume() in system suspend callbacks"
In reply to: John Stultz: "Re: [tip:timers/core] kselftests: timers: set-timer-lat: Tweak reporting when timer fires early"
Next in thread: Shuah Khan: "Re: [tip:timers/core] kselftests: timers: set-timer-lat: Tweak reporting when timer fires early"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]