2017-09-20 01:03:04

by Shuah Khan

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

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 <[email protected]>
> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
> Committer: John Stultz <[email protected]>
> 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 <[email protected]>
> Cc: Ingo Molnar <[email protected]>
> Cc: Miroslav Lichvar <[email protected]>
> Cc: Richard Cochran <[email protected]>
> Cc: Prarit Bhargava <[email protected]>
> Cc: Stephen Boyd <[email protected]>
> Cc: Shuah Khan <[email protected]>
> Cc: [email protected]
> Signed-off-by: Greg Hackmann <[email protected]>
> Signed-off-by: John Stultz <[email protected]>

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.

I had to revert the following as well, however a524b1184b8e86141d689fa78ad150fbf2db9b4c
is the suspect.

Commit-ID: 28be3f8f48cfb3cf024860f042d424cd4824f5f7
Gitweb: http://git.kernel.org/tip/28be3f8f48cfb3cf024860f042d424cd4824f5f7
Author: Greg Hackmann <[email protected]>
AuthorDate: Tue, 25 Jul 2017 14:36:26 -0700
Committer: John Stultz <[email protected]>
CommitDate: Thu, 17 Aug 2017 12:14:58 -0700

kselftests: timers: set-timer-lat: Add one-shot timer test cases

Please let me know how you want to proceed. At the moment kselftest
run hangs due this test hang.

thanks,
-- Shuah


2017-09-20 03:21:34

by John Stultz

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

On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan <[email protected]> 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 <[email protected]>
>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
>> Committer: John Stultz <[email protected]>
>> 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 <[email protected]>
>> Cc: Ingo Molnar <[email protected]>
>> Cc: Miroslav Lichvar <[email protected]>
>> Cc: Richard Cochran <[email protected]>
>> Cc: Prarit Bhargava <[email protected]>
>> Cc: Stephen Boyd <[email protected]>
>> Cc: Shuah Khan <[email protected]>
>> Cc: [email protected]
>> Signed-off-by: Greg Hackmann <[email protected]>
>> Signed-off-by: John Stultz <[email protected]>
>
> 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.
>
> I had to revert the following as well, however a524b1184b8e86141d689fa78ad150fbf2db9b4c
> is the suspect.
>
> Commit-ID: 28be3f8f48cfb3cf024860f042d424cd4824f5f7
> Gitweb: http://git.kernel.org/tip/28be3f8f48cfb3cf024860f042d424cd4824f5f7
> Author: Greg Hackmann <[email protected]>
> AuthorDate: Tue, 25 Jul 2017 14:36:26 -0700
> Committer: John Stultz <[email protected]>
> CommitDate: Thu, 17 Aug 2017 12:14:58 -0700
>
> kselftests: timers: set-timer-lat: Add one-shot timer test cases
>
> Please let me know how you want to proceed. At the moment kselftest
> run hangs due this test hang.

Huh. I didn't see such a hang in my testing. Let me try to reproduce
and see if I can figure out whats going on.

thanks
-john

2017-09-20 03:36:25

by John Stultz

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

On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan <[email protected]> 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 <[email protected]>
>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
>> Committer: John Stultz <[email protected]>
>> 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 <[email protected]>
>> Cc: Ingo Molnar <[email protected]>
>> Cc: Miroslav Lichvar <[email protected]>
>> Cc: Richard Cochran <[email protected]>
>> Cc: Prarit Bhargava <[email protected]>
>> Cc: Stephen Boyd <[email protected]>
>> Cc: Shuah Khan <[email protected]>
>> Cc: [email protected]
>> Signed-off-by: Greg Hackmann <[email protected]>
>> Signed-off-by: John Stultz <[email protected]>
>
> 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.

thanks
-john

2017-09-20 12:31:14

by Prarit Bhargava

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

On 09/19/2017 11:36 PM, John Stultz wrote:
> On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan <[email protected]> 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 <[email protected]>
>>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
>>> Committer: John Stultz <[email protected]>
>>> 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 <[email protected]>
>>> Cc: Ingo Molnar <[email protected]>
>>> Cc: Miroslav Lichvar <[email protected]>
>>> Cc: Richard Cochran <[email protected]>
>>> Cc: Prarit Bhargava <[email protected]>
>>> Cc: Stephen Boyd <[email protected]>
>>> Cc: Shuah Khan <[email protected]>
>>> Cc: [email protected]
>>> Signed-off-by: Greg Hackmann <[email protected]>
>>> Signed-off-by: John Stultz <[email protected]>
>>
>> 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.

2017-09-20 23:38:59

by Shuah Khan

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

On 09/20/2017 06:31 AM, Prarit Bhargava wrote:
> On 09/19/2017 11:36 PM, John Stultz wrote:
>> On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan <[email protected]> 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 <[email protected]>
>>>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
>>>> Committer: John Stultz <[email protected]>
>>>> 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 <[email protected]>
>>>> Cc: Ingo Molnar <[email protected]>
>>>> Cc: Miroslav Lichvar <[email protected]>
>>>> Cc: Richard Cochran <[email protected]>
>>>> Cc: Prarit Bhargava <[email protected]>
>>>> Cc: Stephen Boyd <[email protected]>
>>>> Cc: Shuah Khan <[email protected]>
>>>> Cc: [email protected]
>>>> Signed-off-by: Greg Hackmann <[email protected]>
>>>> Signed-off-by: John Stultz <[email protected]>
>>>
>>> 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

John/Prarit,

Thanks for getting back to me. I isolated the problem to redirecting
test output. If I redirect the output it hangs.

./set-timer-lat > /tmp/set-timer-lat 2>&1

it hangs. The reason I am seeing this is because there is a patch
that came in recently to redirect individual test output to a separate
file to make it easier to understand the test results.

Looks like Commits 28be3f8f48cfb3cf024860f042d424cd4824f5f7 and/or
a524b1184b8e86141d689fa78ad150fbf2db9b4c add dependency on stdin/out/err
to the test.

Anyway just an update. It can be reproduced easily. If we have tests
that can't tolerate redirecting output, I might end up dropping the
patch that is in linux-kselftest fixes

fbcab13d2e2511a858590846ac2e2d7cbd830591

So fat set-timer-lat is the only one I found.

thanks,
-- Shuah

2017-09-21 19:40:13

by Greg Hackmann

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

On 09/20/2017 04:38 PM, Shuah Khan wrote:
> On 09/20/2017 06:31 AM, Prarit Bhargava wrote:
>> On 09/19/2017 11:36 PM, John Stultz wrote:
>>> On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan <[email protected]> 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 <[email protected]>
>>>>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
>>>>> Committer: John Stultz <[email protected]>
>>>>> 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 <[email protected]>
>>>>> Cc: Ingo Molnar <[email protected]>
>>>>> Cc: Miroslav Lichvar <[email protected]>
>>>>> Cc: Richard Cochran <[email protected]>
>>>>> Cc: Prarit Bhargava <[email protected]>
>>>>> Cc: Stephen Boyd <[email protected]>
>>>>> Cc: Shuah Khan <[email protected]>
>>>>> Cc: [email protected]
>>>>> Signed-off-by: Greg Hackmann <[email protected]>
>>>>> Signed-off-by: John Stultz <[email protected]>
>>>>
>>>> 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
>
> John/Prarit,
>
> Thanks for getting back to me. I isolated the problem to redirecting
> test output. If I redirect the output it hangs.
>
> ./set-timer-lat > /tmp/set-timer-lat 2>&1
>
> it hangs. The reason I am seeing this is because there is a patch
> that came in recently to redirect individual test output to a separate
> file to make it easier to understand the test results.
>
> Looks like Commits 28be3f8f48cfb3cf024860f042d424cd4824f5f7 and/or
> a524b1184b8e86141d689fa78ad150fbf2db9b4c add dependency on stdin/out/err
> to the test.
>
> Anyway just an update. It can be reproduced easily. If we have tests
> that can't tolerate redirecting output, I might end up dropping the
> patch that is in linux-kselftest fixes
>
> fbcab13d2e2511a858590846ac2e2d7cbd830591
>
> So fat set-timer-lat is the only one I found.
>
> thanks,
> -- Shuah
>
I'm able to reproduce this locally, though I'm not sure it's a
redirection issue. 28be3f8f48cf ("kselftests: timers: set-timer-lat:
Add one-shot timer test cases") appears to have a regression where if
timer_create() fails due to missing CAP_WAKE_ALARM, do_timer() will
still try to run the test anyway.

Please revert 28be3f8f48cf and verify whether this fixes the problem for
you. If so, I'll send a V2 as soon as possible that fixes the issue.
(Basically, setup_timer() needs a discrete return value for unsupported
test cases.)

Sorry for the confusion.

2017-09-21 19:42:34

by Shuah Khan

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

On 09/21/2017 01:40 PM, Greg Hackmann wrote:
> On 09/20/2017 04:38 PM, Shuah Khan wrote:
>> On 09/20/2017 06:31 AM, Prarit Bhargava wrote:
>>> On 09/19/2017 11:36 PM, John Stultz wrote:
>>>> On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan <[email protected]> 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 <[email protected]>
>>>>>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700
>>>>>> Committer: John Stultz <[email protected]>
>>>>>> 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 <[email protected]>
>>>>>> Cc: Ingo Molnar <[email protected]>
>>>>>> Cc: Miroslav Lichvar <[email protected]>
>>>>>> Cc: Richard Cochran <[email protected]>
>>>>>> Cc: Prarit Bhargava <[email protected]>
>>>>>> Cc: Stephen Boyd <[email protected]>
>>>>>> Cc: Shuah Khan <[email protected]>
>>>>>> Cc: [email protected]
>>>>>> Signed-off-by: Greg Hackmann <[email protected]>
>>>>>> Signed-off-by: John Stultz <[email protected]>
>>>>>
>>>>> 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
>>
>> John/Prarit,
>>
>> Thanks for getting back to me. I isolated the problem to redirecting
>> test output. If I redirect the output it hangs.
>>
>> ./set-timer-lat > /tmp/set-timer-lat 2>&1
>>
>> it hangs. The reason I am seeing this is because there is a patch
>> that came in recently to redirect individual test output to a separate
>> file to make it easier to understand the test results.
>>
>> Looks like Commits 28be3f8f48cfb3cf024860f042d424cd4824f5f7 and/or
>> a524b1184b8e86141d689fa78ad150fbf2db9b4c add dependency on stdin/out/err
>> to the test.
>>
>> Anyway just an update. It can be reproduced easily. If we have tests
>> that can't tolerate redirecting output, I might end up dropping the
>> patch that is in linux-kselftest fixes
>>
>> fbcab13d2e2511a858590846ac2e2d7cbd830591
>>
>> So fat set-timer-lat is the only one I found.
>>
>> thanks,
>> -- Shuah
>>
> I'm able to reproduce this locally, though I'm not sure it's a redirection issue. 28be3f8f48cf ("kselftests: timers: set-timer-lat: Add one-shot timer test cases") appears to have a regression where if timer_create() fails due to missing CAP_WAKE_ALARM, do_timer() will still try to run the test anyway.

Yeah I found two problems - patches on their way. The first one returning 0 for unsupported
alarm cases and a second in select. Just about to send patches. Will cc on those.

thanks,
-- Shuah