Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751868AbdITMbO (ORCPT ); Wed, 20 Sep 2017 08:31:14 -0400 Received: from mx1.redhat.com ([209.132.183.28]:53630 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751768AbdITMbM (ORCPT ); Wed, 20 Sep 2017 08:31:12 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mx1.redhat.com 3EFD6822 Authentication-Results: ext-mx05.extmail.prod.ext.phx2.redhat.com; dmarc=none (p=none dis=none) header.from=redhat.com Authentication-Results: ext-mx05.extmail.prod.ext.phx2.redhat.com; spf=fail smtp.mailfrom=prarit@redhat.com Subject: Re: [tip:timers/core] kselftests: timers: set-timer-lat: Tweak reporting when timer fires early To: John Stultz , Shuah Khan References: <04d5e9e4-ef81-a9e7-8180-2c668e3af9d0@kernel.org> Cc: lkml , Richard Cochran , "H. Peter Anvin" , Thomas Gleixner , Ingo Molnar , Stephen Boyd , Greg Hackmann , Miroslav Lichvar , linux-tip-commits@vger.kernel.org, Shuah Khan From: Prarit Bhargava Message-ID: <36087647-31b1-95a1-fd74-b22f7d931010@redhat.com> Date: Wed, 20 Sep 2017 08:31:10 -0400 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.7.0 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.29]); Wed, 20 Sep 2017 12:31:12 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 12803 Lines: 253 On 09/19/2017 11:36 PM, John Stultz wrote: > On Tue, Sep 19, 2017 at 6:02 PM, Shuah Khan 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 >>> AuthorDate: Tue, 25 Jul 2017 14:36:25 -0700 >>> Committer: John Stultz >>> 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 >>> Cc: Ingo Molnar >>> Cc: Miroslav Lichvar >>> Cc: Richard Cochran >>> Cc: Prarit Bhargava >>> Cc: Stephen Boyd >>> Cc: Shuah Khan >>> Cc: linux-kselftest@vger.kernel.org >>> Signed-off-by: Greg Hackmann >>> Signed-off-by: John Stultz >> >> 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.