testrunner: added option -t to print timing information about the tests (danmar#8336)

Author: firewave

.github/workflows/CI-windows.yml

@@ -219,7 +219,7 @@ jobs:
 
       - name: Run Debug test
         if: matrix.config == 'debug'
-        run: .\bin\debug\testrunner.exe || exit /b !errorlevel!
+        run: .\bin\debug\testrunner.exe -t || exit /b !errorlevel!
 
       - name: Build CLI release configuration using MSBuild
         if: matrix.config == 'release'

.github/workflows/sanitizers.yml

@@ -114,7 +114,7 @@ jobs:
           cmake --build cmake.output --target gui-tests -- -j $(nproc)
 
       - name: Run tests
-        run: ./cmake.output/bin/testrunner
+        run: ./cmake.output/bin/testrunner -t
 
       - name: Run cfg tests
         run: |

.github/workflows/valgrind.yml

@@ -57,7 +57,7 @@ jobs:
             TestProcessExecutorFiles \
             TestSuppressions::suppressionsSettingsProcessesFiles \
             TestSuppressions::suppressionsSettingsProcessesFS"
-          valgrind --error-limit=yes --leak-check=full --num-callers=50 --show-reachable=yes --track-origins=yes --suppressions=valgrind/testrunner.supp --gen-suppressions=all -s --log-fd=9 --error-exitcode=42 ./testrunner -x $excluded_tests 9>memcheck.log || ec=1
+          valgrind --error-limit=yes --leak-check=full --num-callers=50 --show-reachable=yes --track-origins=yes --suppressions=valgrind/testrunner.supp --gen-suppressions=all -s --log-fd=9 --error-exitcode=42 ./testrunner -t -x $excluded_tests 9>memcheck.log || ec=1
           cat memcheck.log
           exit $ec
         # TODO: debuginfod.ubuntu.com is currently not responding to any requests causing it to run into a 40(!) minute timeout

Makefile

@@ -722,7 +722,7 @@ cli/stacktrace.o: cli/stacktrace.cpp cli/stacktrace.h lib/config.h lib/utils.h
 cli/threadexecutor.o: cli/threadexecutor.cpp cli/executor.h cli/threadexecutor.h lib/addoninfo.h lib/check.h lib/checkers.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/filesettings.h lib/library.h lib/mathlib.h lib/path.h lib/platform.h lib/regex.h lib/settings.h lib/standards.h lib/suppressions.h lib/timer.h lib/utils.h
 	$(CXX) ${INCLUDE_FOR_CLI} $(CPPFLAGS) $(CXXFLAGS) -c -o $@ cli/threadexecutor.cpp
 
-test/fixture.o: test/fixture.cpp externals/tinyxml2/tinyxml2.h lib/addoninfo.h lib/check.h lib/checkers.h lib/color.h lib/config.h lib/errorlogger.h lib/errortypes.h lib/library.h lib/mathlib.h lib/path.h lib/platform.h lib/regex.h lib/settings.h lib/standards.h lib/tokenize.h lib/tokenlist.h lib/utils.h lib/xml.h test/fixture.h test/helpers.h test/options.h test/redirect.h
+test/fixture.o: test/fixture.cpp externals/tinyxml2/tinyxml2.h lib/addoninfo.h lib/check.h lib/checkers.h lib/color.h lib/config.h lib/errorlogger.h lib/errortypes.h lib/library.h lib/mathlib.h lib/path.h lib/platform.h lib/regex.h lib/settings.h lib/standards.h lib/timer.h lib/tokenize.h lib/tokenlist.h lib/utils.h lib/xml.h test/fixture.h test/helpers.h test/options.h test/redirect.h
 	$(CXX) ${INCLUDE_FOR_TEST} ${CFLAGS_FOR_TEST} $(CPPFLAGS) $(CXXFLAGS) -c -o $@ test/fixture.cpp
 
 test/helpers.o: test/helpers.cpp cli/filelister.h externals/simplecpp/simplecpp.h externals/tinyxml2/tinyxml2.h lib/addoninfo.h lib/checkers.h lib/config.h lib/errortypes.h lib/filesettings.h lib/library.h lib/mathlib.h lib/path.h lib/pathmatch.h lib/platform.h lib/preprocessor.h lib/regex.h lib/settings.h lib/standards.h lib/tokenize.h lib/tokenlist.h lib/utils.h lib/xml.h test/helpers.h
@@ -731,7 +731,7 @@ test/helpers.o: test/helpers.cpp cli/filelister.h externals/simplecpp/simplecpp.
 test/main.o: test/main.cpp externals/simplecpp/simplecpp.h lib/addoninfo.h lib/check.h lib/checkers.h lib/color.h lib/config.h lib/errorlogger.h lib/errortypes.h lib/library.h lib/mathlib.h lib/platform.h lib/preprocessor.h lib/regex.h lib/settings.h lib/standards.h lib/utils.h test/fixture.h test/options.h
 	$(CXX) ${INCLUDE_FOR_TEST} ${CFLAGS_FOR_TEST} $(CPPFLAGS) $(CXXFLAGS) -c -o $@ test/main.cpp
 
-test/options.o: test/options.cpp test/options.h
+test/options.o: test/options.cpp lib/config.h lib/timer.h test/options.h
 	$(CXX) ${INCLUDE_FOR_TEST} ${CFLAGS_FOR_TEST} $(CPPFLAGS) $(CXXFLAGS) -c -o $@ test/options.cpp
 
 test/test64bit.o: test/test64bit.cpp lib/addoninfo.h lib/check.h lib/check64bit.h lib/checkers.h lib/color.h lib/config.h lib/errorlogger.h lib/errortypes.h lib/library.h lib/mathlib.h lib/path.h lib/platform.h lib/regex.h lib/settings.h lib/standards.h lib/tokenize.h lib/tokenlist.h lib/utils.h test/fixture.h test/helpers.h

test/fixture.cpp

@@ -23,6 +23,7 @@
 #include "library.h"
 #include "options.h"
 #include "redirect.h"
+#include "timer.h"
 
 #include <algorithm>
 #include <cstdio>
@@ -88,6 +89,7 @@ TestFixture::TestFixture(const char * const _name)
     : classname(_name)
 {}
 
+TestFixture::~TestFixture() = default;
 
 bool TestFixture::prepareTest(const char testname[])
 {
@@ -106,19 +108,25 @@ bool TestFixture::prepareTest(const char testname[])
     // Tests will be executed - prepare them
     mTestname = testname;
     ++countTests;
+    std::string fullTestName =  classname + "::" + mTestname;
     if (quiet_tests) {
         std::putchar('.'); // Use putchar to write through redirection of std::cout/cerr
         std::fflush(stdout);
     } else {
-        std::cout << classname << "::" << mTestname << std::endl;
+        std::cout << fullTestName << std::endl;
     }
+    if (timer_results)
+        mTimer.reset(new Timer(fullTestName, ShowTime::TOP5_SUMMARY, timer_results));
     return !dry_run;
 }
 
 void TestFixture::teardownTest()
 {
     teardownTestInternal();
 
+    if (mTimer)
+        mTimer->stop();
+
     {
         const std::string s = errout_str();
         if (!s.empty())
@@ -385,6 +393,7 @@ void TestFixture::processOptions(const options& args)
     dry_run = args.dry_run();
     exclude_tests = args.exclude_tests();
     exename = args.exe();
+    timer_results = args.timer_results();
 }
 
 std::size_t TestFixture::runTests(const options& args)
@@ -410,7 +419,15 @@ std::size_t TestFixture::runTests(const options& args)
                 tests = it->second;
         }
 
-        TestFixture* fixture = test->create();
+        TestFixture* fixture;
+        const auto f = [&](){
+            fixture = test->create();
+        };
+        // TODO: Timer::run() needs proper handling if no results should be collected
+        if (args.timer_results())
+            Timer::run(test->classname + " - create", ShowTime::TOP5_SUMMARY, args.timer_results(), f);
+        else
+            f();
         fixture->processOptions(args);
         fixture->run(tests);
     }

test/fixture.h

@@ -43,6 +43,8 @@
 
 class options;
 class Tokenizer;
+class Timer;
+class TimerResultsIntf;
 
 class TestFixture : public ErrorLogger {
 private:
@@ -61,6 +63,7 @@ class TestFixture : public ErrorLogger {
     bool quiet_tests{};
     bool dry_run{};
     bool exclude_tests{};
+    TimerResultsIntf* timer_results{};
     bool mNewTemplate{};
 
     virtual void run() = 0;
@@ -286,6 +289,8 @@ class TestFixture : public ErrorLogger {
     std::ostringstream mOutput;
     std::ostringstream mErrout;
 
+    std::unique_ptr<Timer> mTimer;
+
     void reportOut(const std::string &outmsg, Color c = Color::Reset) override;
     void reportErr(const ErrorMessage &msg) override;
     void reportMetric(const std::string &metric) override
@@ -299,6 +304,7 @@ class TestFixture : public ErrorLogger {
     const std::string classname;
 
     explicit TestFixture(const char * _name);
+    ~TestFixture() override;
 
     static std::size_t runTests(const options& args);
 };

test/options.cpp

@@ -16,6 +16,8 @@
 
 #include "options.h"
 
+#include "timer.h"
+
 options::options(int argc, const char* const argv[])
     : mExe(argv[0])
 {
@@ -34,6 +36,8 @@ options::options(int argc, const char* const argv[])
                 mDryRun = true;
             else if (arg == "-x")
                 mExcludeTests = true;
+            else if (arg == "-t")
+                mTimerResults.reset(new TimerResults);
             else
                 mErrors.emplace_back("unknown option '" + arg + "'");
             continue; // command-line switch
@@ -52,6 +56,15 @@ options::options(int argc, const char* const argv[])
     }
 }
 
+options::~options()
+{
+    // TODO: allow more than 5 results to be shown
+    // TODO: provide higher resolution in output
+    // TODO: disable the metrics
+    if (mTimerResults)
+        mTimerResults->showResults(ShowTime::TOP5_FILE);
+}
+
 bool options::quiet() const
 {
     return mQuiet;
@@ -87,6 +100,11 @@ bool options::exclude_tests() const
     return mExcludeTests;
 }
 
+TimerResultsIntf* options::timer_results() const
+{
+    return mTimerResults.get();
+}
+
 const std::vector<std::string>& options::errors() const
 {
     return mErrors;

test/options.h

@@ -18,10 +18,14 @@
 #define OPTIONS_H
 
 #include <map>
+#include <memory>
 #include <set>
 #include <string>
 #include <vector>
 
+class TimerResultsIntf;
+class TimerResults;
+
 /**
  * @brief Class to parse command-line parameters for ./testrunner .
  * Has getters for available switches and parameters.
@@ -31,6 +35,7 @@ class options {
 public:
     /** Call from main() to populate object */
     options(int argc, const char* const argv[]);
+    ~options();
     /** Don't print the name of each method being tested. */
     bool quiet() const;
     /** Print help. */
@@ -41,6 +46,8 @@ class options {
     bool dry_run() const;
     /** Exclude provided lists of tests. */
     bool exclude_tests() const;
+    /** The timer results. */
+    TimerResultsIntf* timer_results() const;
     /** Which tests should be run. */
     const std::map<std::string, std::set<std::string>>& which_tests() const;
 
@@ -61,6 +68,7 @@ class options {
     bool mSummary{true};
     bool mDryRun{};
     bool mExcludeTests{};
+    std::unique_ptr<TimerResults> mTimerResults;
     std::string mExe;
 };
 

test/testoptions.cpp

@@ -45,6 +45,7 @@ class TestOptions : public TestFixture {
         TEST_CASE(summary);
         TEST_CASE(dry_run);
         TEST_CASE(exclude_tests);
+        TEST_CASE(timer_results);
     }
 
 
@@ -167,6 +168,12 @@ class TestOptions : public TestFixture {
         ASSERT_EQUALS(true, args.exclude_tests());
         ASSERT(args.errors().empty());
     }
+
+    void timer_results() const {
+        const char* argv[] = {"./test_runner", "TestClass::TestMethod", "-t"};
+        options args(getArrayLength(argv), argv);
+        ASSERT(!!args.timer_results());
+    }
 };
 
 REGISTER_TEST(TestOptions)