From b33061b01d5157e50e7764f53dfa1710261c58f3 Mon Sep 17 00:00:00 2001 From: John Bytheway Date: Mon, 13 Apr 2020 08:34:27 -0400 Subject: [PATCH 1/2] 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 ++++ include/internal/catch_commandline.cpp | 3 +++ include/internal/catch_config.cpp | 1 + include/internal/catch_config.hpp | 2 ++ include/internal/catch_interfaces_config.h | 1 + include/reporters/catch_reporter_bases.cpp | 7 +++++++ include/reporters/catch_reporter_bases.hpp | 2 ++ include/reporters/catch_reporter_compact.cpp | 5 +++-- include/reporters/catch_reporter_console.cpp | 5 +++-- projects/CMakeLists.txt | 3 +++ single_include/catch2/catch.hpp | 1 + 11 files changed, 30 insertions(+), 4 deletions(-) diff --git a/docs/command-line.md b/docs/command-line.md index 1741eb8f84..77e969b0eb 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/include/internal/catch_commandline.cpp b/include/internal/catch_commandline.cpp index a4010850d0..673d3b70bc 100644 --- a/include/internal/catch_commandline.cpp +++ b/include/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/include/internal/catch_config.cpp b/include/internal/catch_config.cpp index 21cd62965b..252bec62ef 100644 --- a/include/internal/catch_config.cpp +++ b/include/internal/catch_config.cpp @@ -64,6 +64,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/include/internal/catch_config.hpp b/include/internal/catch_config.hpp index 64d2c035f9..fd7de5b2d4 100644 --- a/include/internal/catch_config.hpp +++ b/include/internal/catch_config.hpp @@ -52,6 +52,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; @@ -103,6 +104,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/include/internal/catch_interfaces_config.h b/include/internal/catch_interfaces_config.h index 8fb986be46..e9c2cf9662 100644 --- a/include/internal/catch_interfaces_config.h +++ b/include/internal/catch_interfaces_config.h @@ -69,6 +69,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/include/reporters/catch_reporter_bases.cpp b/include/reporters/catch_reporter_bases.cpp index fcbafef58b..271f90ca24 100644 --- a/include/reporters/catch_reporter_bases.cpp +++ b/include/reporters/catch_reporter_bases.cpp @@ -41,6 +41,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/include/reporters/catch_reporter_bases.hpp b/include/reporters/catch_reporter_bases.hpp index 66a891ffd4..f53794f4d1 100644 --- a/include/reporters/catch_reporter_bases.hpp +++ b/include/reporters/catch_reporter_bases.hpp @@ -25,6 +25,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 ); template diff --git a/include/reporters/catch_reporter_compact.cpp b/include/reporters/catch_reporter_compact.cpp index 017f521f48..e9c44ea6f2 100644 --- a/include/reporters/catch_reporter_compact.cpp +++ b/include/reporters/catch_reporter_compact.cpp @@ -275,8 +275,9 @@ class AssertionPrinter { } 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/include/reporters/catch_reporter_console.cpp b/include/reporters/catch_reporter_console.cpp index 0fa399d586..4f74ccb320 100644 --- a/include/reporters/catch_reporter_console.cpp +++ b/include/reporters/catch_reporter_console.cpp @@ -418,8 +418,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/projects/CMakeLists.txt b/projects/CMakeLists.txt index 08badb809a..1e50e9cc05 100644 --- a/projects/CMakeLists.txt +++ b/projects/CMakeLists.txt @@ -454,6 +454,9 @@ set_tests_properties(TestsInFile::InvalidTestNames-2 PROPERTIES PASS_REGULAR_EXP add_test(NAME RandomTestOrdering COMMAND ${PYTHON_EXECUTABLE} ${CATCH_DIR}/projects/TestScripts/testRandomOrder.py $) +add_test(NAME TestTimeThreshold COMMAND ${PYTHON_EXECUTABLE} + ${CATCH_DIR}/projects/TestScripts/testTimeThreshold.py $) + if (CATCH_USE_VALGRIND) add_test(NAME ValgrindRunTests COMMAND valgrind --leak-check=full --error-exitcode=1 $) add_test(NAME ValgrindListTests COMMAND valgrind --leak-check=full --error-exitcode=1 $ --list-tests --verbosity high) diff --git a/single_include/catch2/catch.hpp b/single_include/catch2/catch.hpp index 5ebd1a2d2a..909b5d663d 100644 --- a/single_include/catch2/catch.hpp +++ b/single_include/catch2/catch.hpp @@ -4522,6 +4522,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; From 336e27c18876654c4b339466202ced60312619cc Mon Sep 17 00:00:00 2001 From: John Bytheway Date: Mon, 13 Apr 2020 08:37:23 -0400 Subject: [PATCH 2/2] Test for --min-duration --- projects/CMakeLists.txt | 1 + projects/SelfTest/TimingTests/Sleep.tests.cpp | 23 +++++++++++ projects/TestScripts/testTimeThreshold.py | 41 +++++++++++++++++++ 3 files changed, 65 insertions(+) create mode 100644 projects/SelfTest/TimingTests/Sleep.tests.cpp create mode 100644 projects/TestScripts/testTimeThreshold.py diff --git a/projects/CMakeLists.txt b/projects/CMakeLists.txt index 1e50e9cc05..cde25cbd3b 100644 --- a/projects/CMakeLists.txt +++ b/projects/CMakeLists.txt @@ -27,6 +27,7 @@ set(TEST_SOURCES ${SELF_TEST_DIR}/IntrospectiveTests/StringManip.tests.cpp ${SELF_TEST_DIR}/IntrospectiveTests/Xml.tests.cpp ${SELF_TEST_DIR}/IntrospectiveTests/ToString.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 diff --git a/projects/SelfTest/TimingTests/Sleep.tests.cpp b/projects/SelfTest/TimingTests/Sleep.tests.cpp new file mode 100644 index 0000000000..5b9398748d --- /dev/null +++ b/projects/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 "catch.hpp" + +#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/projects/TestScripts/testTimeThreshold.py b/projects/TestScripts/testTimeThreshold.py new file mode 100644 index 0000000000..51804aaeb6 --- /dev/null +++ b/projects/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())