refs #14599 - do not implicitly print in TimerResults::stop() (#8400)

Author: firewave

cli/cppcheckexecutor.cpp

@@ -267,7 +267,8 @@ int CppCheckExecutor::check(int argc, const char* const argv[])
         return EXIT_SUCCESS;
     }
 
-    Timer realTimeClock("", settings.showtime, nullptr, Timer::Type::OVERALL);
+    TimerResults overallTimerResults;
+    Timer realTimeClock("Overall time", settings.showtime, &overallTimerResults, Timer::Type::OVERALL);
 
     settings.loadSummaries();
 
@@ -276,6 +277,9 @@ int CppCheckExecutor::check(int argc, const char* const argv[])
 
     const int ret = check_wrapper(settings, supprs);
 
+    realTimeClock.stop();
+    overallTimerResults.showResults(settings.showtime, false, true);
+
     return ret;
 }
 

lib/cppcheck.cpp

@@ -923,7 +923,8 @@ unsigned int CppCheck::checkInternal(const FileWithDetails& file, const std::str
     if (Settings::terminated())
         return mLogger->exitcode();
 
-    const Timer fileTotalTimer{file.spath(), mSettings.showtime, nullptr, Timer::Type::FILE};
+    TimerResults checkTimeResults;
+    Timer fileTotalTimer{"Check time: " + file.spath(), mSettings.showtime, &checkTimeResults, Timer::Type::FILE};
 
     if (!mSettings.quiet) {
         std::string fixedpath = Path::toNativeSeparators(file.spath());
@@ -1295,6 +1296,9 @@ unsigned int CppCheck::checkInternal(const FileWithDetails& file, const std::str
     if (mTimerResults && (mSettings.showtime == ShowTime::FILE || mSettings.showtime == ShowTime::TOP5_FILE))
         mTimerResults->showResults(mSettings.showtime);
 
+    fileTotalTimer.stop();
+    checkTimeResults.showResults(mSettings.showtime, false, true);
+
     return mLogger->exitcode();
 }
 

lib/timer.cpp

@@ -19,6 +19,7 @@
 #include "timer.h"
 
 #include <algorithm>
+#include <cassert>
 #include <cstddef>
 #include <iostream>
 #include <utility>
@@ -37,9 +38,9 @@ namespace {
 
 // TODO: this does not include any file context when SHOWTIME_FILE thus rendering it useless - should we include the logging with the progress logging?
 // that could also get rid of the broader locking
-void TimerResults::showResults(ShowTime mode) const
+void TimerResults::showResults(ShowTime mode, bool metrics, bool format) const
 {
-    if (mode == ShowTime::NONE || mode == ShowTime::FILE_TOTAL)
+    if (mode == ShowTime::NONE)
         return;
     std::vector<dataElementType> data;
 
@@ -54,14 +55,19 @@ void TimerResults::showResults(ShowTime mode) const
     // lock the whole logging operation to avoid multiple threads printing their results at the same time
     std::lock_guard<std::mutex> l(stdCoutLock);
 
-    std::cout << std::endl;
-
     size_t ordinal = 1; // maybe it would be nice to have an ordinal in output later!
     for (auto iter=data.cbegin(); iter!=data.cend(); ++iter) {
         const double sec = iter->second.getSeconds().count();
         const double secAverage = sec / static_cast<double>(iter->second.mNumberOfResults);
         if ((mode != ShowTime::TOP5_FILE && mode != ShowTime::TOP5_SUMMARY) || (ordinal<=5)) {
-            std::cout << iter->first << ": " << sec << "s (avg. " << secAverage << "s - " << iter->second.mNumberOfResults  << " result(s))" << std::endl;
+            std::cout << iter->first << ": ";
+            if (format)
+                std::cout << TimerResultsData::durationToString(iter->second.mDuration);
+            else
+                std::cout << sec << "s";
+            if (metrics)
+                std::cout << " (avg. " << secAverage << "s - " << iter->second.mNumberOfResults  << " result(s))";
+            std::cout << std::endl;
         }
         ++ordinal;
     }
@@ -107,12 +113,11 @@ void Timer::stop()
         return;
     }
     if (mStart != TimePoint{}) {
-        auto diff = std::chrono::duration_cast<std::chrono::milliseconds>(Clock::now() - mStart);
         if (!mResults) {
-            // TODO: do not print implicitly
-            std::lock_guard<std::mutex> l(stdCoutLock);
-            std::cout << (mType == Type::OVERALL ? "Overall time: " : "Check time: " + mName + ": ") << TimerResultsData::durationToString(diff) << std::endl;
-        } else {
+            assert(false);
+        }
+        else {
+            auto diff = std::chrono::duration_cast<std::chrono::milliseconds>(Clock::now() - mStart);
             mResults->addResults(mName, diff);
         }
     }

lib/timer.h

@@ -60,7 +60,7 @@ class CPPCHECKLIB WARN_UNUSED TimerResults : public TimerResultsIntf {
 public:
     TimerResults() = default;
 
-    void showResults(ShowTime mode) const;
+    void showResults(ShowTime mode, bool metrics = true, bool format = false) const;
     void addResults(const std::string& str, std::chrono::milliseconds duration) override;
 
     void reset();

test/cli/other_test.py

@@ -983,17 +983,14 @@ def __test_showtime(tmp_path, showtime, exp_res, exp_last, extra_args=None):
     assert exitcode == 0
     lines = stdout.splitlines()
     exp_len = exp_res
-    if exp_res:
-        exp_len += 1  # empty line at the beginning - only added when individual results exist
     if 'cppcheck internal API usage' in stdout:
         exp_len += 1
     exp_len += 1  # last line
     assert len(lines) == exp_len
-    if exp_res:
-        assert lines[0] == ''
     for i in range(1, exp_res):
         assert 'avg.' in lines[i]
     assert lines[exp_len-1].startswith(exp_last)
+    assert not 'avg.' in lines[exp_len-1]
     assert stderr == ''
 
 

test/testprocessexecutor.cpp

@@ -247,10 +247,9 @@ class TestProcessExecutorBase : public TestFixture {
               "int main() {}",
               dinit(CheckOptions,
                     $.showtime = ShowTime::TOP5_FILE));
-        // for each file: top5 results + overall + empty line
         const std::string output_s = GET_REDIRECT_OUTPUT;
-        // for each file: top5 results + overall + empty line
-        TODO_ASSERT_EQUALS(static_cast<long long>(5 + 1 + 1) * 2, 0, cppcheck::count_all_of(output_s, '\n'));
+        // for each file: top5 results + check time
+        TODO_ASSERT_EQUALS(static_cast<long long>(5 + 1) * 2, 0, cppcheck::count_all_of(output_s, '\n'));
     }
 
     void showtime_file() {

test/testsingleexecutor.cpp

@@ -241,8 +241,8 @@ class TestSingleExecutorBase : public TestFixture {
               dinit(CheckOptions,
                     $.showtime = ShowTime::TOP5_FILE));
         const std::string output_s = GET_REDIRECT_OUTPUT;
-        // for each file: top5 results + overall + total
-        ASSERT_EQUALS((5 + 1 + 1) * 2LL, cppcheck::count_all_of(output_s, '\n'));
+        // for each file: top5 results + check time
+        ASSERT_EQUALS((5 + 1) * 2LL, cppcheck::count_all_of(output_s, '\n'));
     }
 
     void showtime_file() {

test/testthreadexecutor.cpp

@@ -249,8 +249,8 @@ class TestThreadExecutorBase : public TestFixture {
               dinit(CheckOptions,
                     $.showtime = ShowTime::TOP5_FILE));
         const std::string output_s = GET_REDIRECT_OUTPUT;
-        // for each file: top5 results + newline + overall
-        ASSERT_EQUALS((5 + 1 + 1) * 2LL, cppcheck::count_all_of(output_s, '\n'));
+        // for each file: top5 results + check time
+        ASSERT_EQUALS((5 + 1) * 2LL, cppcheck::count_all_of(output_s, '\n'));
     }
 
     void showtime_file() {