From 80b0d6975c1582d03436ba82146983d557b0a1a6 Mon Sep 17 00:00:00 2001 From: John Bytheway Date: Mon, 13 Apr 2020 08:34:27 -0400 Subject: [PATCH] Add --min-duration option A test runner already has a --durations option to print durations. However, this isn't entirely satisfactory. When there are many tests, this produces output spam which makes it hard to find the test failure output. Nevertheless, it is helpful to be informed of tests which are unusually slow. Therefore, introduce a new option --min-duration that causes all durations above a certain threshold to be printed. This allows slow tests to be visible without mentioning every test. --- docs/command-line.md | 4 ++ src/catch2/catch_config.cpp | 1 + src/catch2/catch_config.hpp | 2 + .../interfaces/catch_interfaces_config.hpp | 1 + src/catch2/internal/catch_commandline.cpp | 3 ++ src/catch2/reporters/catch_reporter_bases.cpp | 7 ++++ src/catch2/reporters/catch_reporter_bases.hpp | 2 + .../reporters/catch_reporter_compact.cpp | 5 ++- .../reporters/catch_reporter_console.cpp | 5 ++- tests/CMakeLists.txt | 4 ++ tests/SelfTest/TimingTests/Sleep.tests.cpp | 23 +++++++++++ tests/TestScripts/testTimeThreshold.py | 41 +++++++++++++++++++ 12 files changed, 94 insertions(+), 4 deletions(-) create mode 100644 tests/SelfTest/TimingTests/Sleep.tests.cpp create mode 100644 tests/TestScripts/testTimeThreshold.py diff --git a/docs/command-line.md b/docs/command-line.md index 1741eb8f..77e969b0 100644 --- a/docs/command-line.md +++ b/docs/command-line.md @@ -222,6 +222,10 @@ available warnings When set to ```yes``` Catch will report the duration of each test case, in milliseconds. Note that it does this regardless of whether a test case passes or fails. Note, also, the certain reporters (e.g. Junit) always report test case durations regardless of this option being set or not. +
-D, --min-duration <value>
+ +When set, Catch will report the duration of each test case that took more than <value> seconds, in milliseconds. + ## Load test names to run from a file 
-f, --input-file <filename>
diff --git a/src/catch2/catch_config.cpp b/src/catch2/catch_config.cpp index 1f89af56..a5caeb33 100644 --- a/src/catch2/catch_config.cpp +++ b/src/catch2/catch_config.cpp @@ -69,6 +69,7 @@ namespace Catch { bool Config::warnAboutMissingAssertions() const { return !!(m_data.warnings & WarnAbout::NoAssertions); } bool Config::warnAboutNoTests() const { return !!(m_data.warnings & WarnAbout::NoTests); } ShowDurations::OrNot Config::showDurations() const { return m_data.showDurations; } + double Config::minDuration() const { return m_data.minDuration; } RunTests::InWhatOrder Config::runOrder() const { return m_data.runOrder; } unsigned int Config::rngSeed() const { return m_data.rngSeed; } UseColour::YesOrNo Config::useColour() const { return m_data.useColour; } diff --git a/src/catch2/catch_config.hpp b/src/catch2/catch_config.hpp index dd8767dc..57ec1fff 100644 --- a/src/catch2/catch_config.hpp +++ b/src/catch2/catch_config.hpp @@ -48,6 +48,7 @@ namespace Catch { Verbosity verbosity = Verbosity::Normal; WarnAbout::What warnings = WarnAbout::Nothing; ShowDurations::OrNot showDurations = ShowDurations::DefaultForReporter; + double minDuration = -1; RunTests::InWhatOrder runOrder = RunTests::InDeclarationOrder; UseColour::YesOrNo useColour = UseColour::Auto; WaitForKeypress::When waitForKeypress = WaitForKeypress::Never; @@ -98,6 +99,7 @@ namespace Catch { bool warnAboutMissingAssertions() const override; bool warnAboutNoTests() const override; ShowDurations::OrNot showDurations() const override; + double minDuration() const override; RunTests::InWhatOrder runOrder() const override; unsigned int rngSeed() const override; UseColour::YesOrNo useColour() const override; diff --git a/src/catch2/interfaces/catch_interfaces_config.hpp b/src/catch2/interfaces/catch_interfaces_config.hpp index 0612eb83..8f3926f5 100644 --- a/src/catch2/interfaces/catch_interfaces_config.hpp +++ b/src/catch2/interfaces/catch_interfaces_config.hpp @@ -67,6 +67,7 @@ namespace Catch { virtual int abortAfter() const = 0; virtual bool showInvisibles() const = 0; virtual ShowDurations::OrNot showDurations() const = 0; + virtual double minDuration() const = 0; virtual TestSpec const& testSpec() const = 0; virtual bool hasTestFilters() const = 0; virtual std::vector const& getTestsOrTags() const = 0; diff --git a/src/catch2/internal/catch_commandline.cpp b/src/catch2/internal/catch_commandline.cpp index 9890ca64..2759eb8e 100644 --- a/src/catch2/internal/catch_commandline.cpp +++ b/src/catch2/internal/catch_commandline.cpp @@ -170,6 +170,9 @@ namespace Catch { | Opt( [&]( bool flag ) { config.showDurations = flag ? ShowDurations::Always : ShowDurations::Never; }, "yes|no" ) ["-d"]["--durations"] ( "show test durations" ) + | Opt( config.minDuration, "seconds" ) + ["-D"]["--min-duration"] + ( "show test durations for tests taking at least the given number of seconds" ) | Opt( loadTestNamesFromFile, "filename" ) ["-f"]["--input-file"] ( "load test names to run from a file" ) diff --git a/src/catch2/reporters/catch_reporter_bases.cpp b/src/catch2/reporters/catch_reporter_bases.cpp index 3534ce4d..e875b596 100644 --- a/src/catch2/reporters/catch_reporter_bases.cpp +++ b/src/catch2/reporters/catch_reporter_bases.cpp @@ -43,6 +43,13 @@ namespace Catch { return std::string(buffer); } + bool shouldShowDuration( IConfig const& config, double duration ) { + if( config.showDurations() == ShowDurations::Always ) + return true; + double min = config.minDuration(); + return min >= 0 && duration >= min; + } + std::string serializeFilters( std::vector const& container ) { ReusableStringStream oss; bool first = true; diff --git a/src/catch2/reporters/catch_reporter_bases.hpp b/src/catch2/reporters/catch_reporter_bases.hpp index 5d875027..7e4457e8 100644 --- a/src/catch2/reporters/catch_reporter_bases.hpp +++ b/src/catch2/reporters/catch_reporter_bases.hpp @@ -24,6 +24,8 @@ namespace Catch { // Returns double formatted as %.3f (format expected on output) std::string getFormattedDuration( double duration ); + bool shouldShowDuration( IConfig const &, double duration ); + std::string serializeFilters( std::vector const& container ); struct StreamingReporterBase : IStreamingReporter { diff --git a/src/catch2/reporters/catch_reporter_compact.cpp b/src/catch2/reporters/catch_reporter_compact.cpp index 4d8166d8..741db305 100644 --- a/src/catch2/reporters/catch_reporter_compact.cpp +++ b/src/catch2/reporters/catch_reporter_compact.cpp @@ -286,8 +286,9 @@ private: } void CompactReporter::sectionEnded(SectionStats const& _sectionStats) { - if (m_config->showDurations() == ShowDurations::Always) { - stream << getFormattedDuration(_sectionStats.durationInSeconds) << " s: " << _sectionStats.sectionInfo.name << std::endl; + double dur = _sectionStats.durationInSeconds; + if ( shouldShowDuration( *m_config, dur ) ) { + stream << getFormattedDuration( dur ) << " s: " << _sectionStats.sectionInfo.name << std::endl; } } diff --git a/src/catch2/reporters/catch_reporter_console.cpp b/src/catch2/reporters/catch_reporter_console.cpp index 848d519c..5dd258b4 100644 --- a/src/catch2/reporters/catch_reporter_console.cpp +++ b/src/catch2/reporters/catch_reporter_console.cpp @@ -420,8 +420,9 @@ void ConsoleReporter::sectionEnded(SectionStats const& _sectionStats) { stream << "\nNo assertions in test case"; stream << " '" << _sectionStats.sectionInfo.name << "'\n" << std::endl; } - if (m_config->showDurations() == ShowDurations::Always) { - stream << getFormattedDuration(_sectionStats.durationInSeconds) << " s: " << _sectionStats.sectionInfo.name << std::endl; + double dur = _sectionStats.durationInSeconds; + if (shouldShowDuration(*m_config, dur)) { + stream << getFormattedDuration(dur) << " s: " << _sectionStats.sectionInfo.name << std::endl; } if (m_headerPrinted) { m_headerPrinted = false; diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index a5fdf802..72ece878 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -28,6 +28,7 @@ set(TEST_SOURCES ${SELF_TEST_DIR}/IntrospectiveTests/Xml.tests.cpp ${SELF_TEST_DIR}/IntrospectiveTests/ToString.tests.cpp ${SELF_TEST_DIR}/IntrospectiveTests/UniquePtr.tests.cpp + ${SELF_TEST_DIR}/TimingTests/Sleep.tests.cpp ${SELF_TEST_DIR}/UsageTests/Approx.tests.cpp ${SELF_TEST_DIR}/UsageTests/BDD.tests.cpp ${SELF_TEST_DIR}/UsageTests/Benchmark.tests.cpp @@ -201,6 +202,9 @@ set_tests_properties(TagAlias PROPERTIES add_test(NAME RandomTestOrdering COMMAND ${PYTHON_EXECUTABLE} ${CATCH_DIR}/tests/TestScripts/testRandomOrder.py $) +add_test(NAME TestTimeThreshold COMMAND ${PYTHON_EXECUTABLE} + ${CATCH_DIR}/tests/TestScripts/testTimeThreshold.py $) + add_test(NAME CheckConvenienceHeaders COMMAND ${PYTHON_EXECUTABLE} ${CATCH_DIR}/tools/scripts/checkConvenienceHeaders.py diff --git a/tests/SelfTest/TimingTests/Sleep.tests.cpp b/tests/SelfTest/TimingTests/Sleep.tests.cpp new file mode 100644 index 00000000..6ecc5fd2 --- /dev/null +++ b/tests/SelfTest/TimingTests/Sleep.tests.cpp @@ -0,0 +1,23 @@ +/* + * Copyright 2011 Two Blue Cubes Ltd. All rights reserved. + * + * Distributed under the Boost Software License, Version 1.0. (See accompanying + * file LICENSE_1_0.txt or copy at http://www.boost.org/LICENSE_1_0.txt) + */ + +#include + +#include +#include + +TEST_CASE( "sleep_for_100ms", "[.min_duration_test][approvals]" ) +{ + std::this_thread::sleep_for( std::chrono::milliseconds( 100 ) ); + CHECK( true ); +} + +TEST_CASE( "sleep_for_200ms", "[.min_duration_test][approvals]" ) +{ + std::this_thread::sleep_for( std::chrono::milliseconds( 200 ) ); + CHECK( true ); +} diff --git a/tests/TestScripts/testTimeThreshold.py b/tests/TestScripts/testTimeThreshold.py new file mode 100644 index 00000000..51804aae --- /dev/null +++ b/tests/TestScripts/testTimeThreshold.py @@ -0,0 +1,41 @@ +#!/usr/bin/env python3 + +import subprocess +import sys + +def run_tests_with_threshold(self_test_exe, threshold): + cmd = [self_test_exe, '--min-duration', str(threshold), + '[min_duration_test]'] + process = subprocess.Popen( + cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) + stdout, stderr = process.communicate() + if stderr: + raise RuntimeError("Unexpected error output:\n" + + stderr.decode()) + if process.returncode != 0: + raise RuntimeError("Unexpected failure to run tests\n") + result = stdout.split(b'\n') + report_lines = [s.split() for s in result if b' s: ' in s] + tests_reported = [l[2] for l in report_lines] + times_reported = [float(l[0]) for l in report_lines] + return tests_reported, times_reported + +def check_times_at_least(times_reported, minimum): + for time in times_reported: + assert time >= minimum, ( + 'Time {} was less that requested minimum {}' .format( + time, minimum)) + +def main(): + self_test_exe, = sys.argv[1:] + tests, times = run_tests_with_threshold(self_test_exe, '0.15') + assert tests == [b'sleep_for_200ms'], ( + "Unexpected tests reported %s" % tests) + check_times_at_least(times, 0.15) + tests,times = run_tests_with_threshold(self_test_exe, '0') + assert tests == [b'sleep_for_100ms', b'sleep_for_200ms'], ( + "Unexpected tests reported %s" % tests) + check_times_at_least(times, 0) + +if __name__ == '__main__': + sys.exit(main())