Fix #14206 --showtime does not account for addons

Makefile

@@ -688,7 +688,7 @@ frontend/frontend.o: frontend/frontend.cpp frontend/frontend.h lib/addoninfo.h l
 cli/cmdlineparser.o: cli/cmdlineparser.cpp cli/cmdlinelogger.h cli/cmdlineparser.h cli/filelister.h externals/tinyxml2/tinyxml2.h lib/addoninfo.h lib/check.h lib/checkers.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/filesettings.h lib/importproject.h lib/library.h lib/mathlib.h lib/path.h lib/pathmatch.h lib/platform.h lib/regex.h lib/settings.h lib/standards.h lib/suppressions.h lib/timer.h lib/utils.h lib/xml.h
 	$(CXX) ${INCLUDE_FOR_CLI} $(CPPFLAGS) $(CXXFLAGS) -c -o $@ cli/cmdlineparser.cpp
 
-cli/cppcheckexecutor.o: cli/cppcheckexecutor.cpp cli/cmdlinelogger.h cli/cmdlineparser.h cli/cppcheckexecutor.h cli/executor.h cli/processexecutor.h cli/sehwrapper.h cli/signalhandler.h cli/singleexecutor.h cli/threadexecutor.h externals/picojson/picojson.h lib/addoninfo.h lib/analyzerinfo.h lib/check.h lib/checkers.h lib/checkersreport.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/filesettings.h lib/json.h lib/library.h lib/mathlib.h lib/path.h lib/platform.h lib/sarifreport.h lib/settings.h lib/standards.h lib/suppressions.h lib/utils.h
+cli/cppcheckexecutor.o: cli/cppcheckexecutor.cpp cli/cmdlinelogger.h cli/cmdlineparser.h cli/cppcheckexecutor.h cli/executor.h cli/processexecutor.h cli/sehwrapper.h cli/signalhandler.h cli/singleexecutor.h cli/threadexecutor.h externals/picojson/picojson.h lib/addoninfo.h lib/analyzerinfo.h lib/check.h lib/checkers.h lib/checkersreport.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/filesettings.h lib/json.h lib/library.h lib/mathlib.h lib/path.h lib/platform.h lib/sarifreport.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/cppcheckexecutor.cpp
 
 cli/executor.o: cli/executor.cpp cli/executor.h lib/addoninfo.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/settings.h lib/standards.h lib/suppressions.h lib/utils.h

cli/cppcheckexecutor.cpp

@@ -38,6 +38,7 @@
 #include "settings.h"
 #include "singleexecutor.h"
 #include "suppressions.h"
+#include "timer.h"
 #include "utils.h"
 
 #if defined(HAS_THREADING_MODEL_THREAD)
@@ -270,6 +271,8 @@ int CppCheckExecutor::check(int argc, const char* const argv[])
         return EXIT_SUCCESS;
     }
 
+    Timer realTimeClock("Summary", settings.showtime);
+
     settings.loadSummaries();
 
     mFiles = parser.getFiles();

lib/cppcheck.cpp

@@ -895,7 +895,7 @@ unsigned int CppCheck::checkInternal(const FileWithDetails& file, const std::str
     if (Settings::terminated())
         return mLogger->exitcode();
 
-    const Timer fileTotalTimer(mSettings.showtime == SHOWTIME_MODES::SHOWTIME_FILE_TOTAL, file.spath());
+    const Timer fileTotalTimer{file.spath(), mSettings.showtime};
 
     if (!mSettings.quiet) {
         std::string fixedpath = Path::toNativeSeparators(file.spath());
@@ -1505,7 +1505,9 @@ void CppCheck::executeAddons(const std::string& dumpFile, const FileWithDetails&
 {
     if (!dumpFile.empty()) {
         std::vector<std::string> f{dumpFile};
-        executeAddons(f, file.spath());
+        Timer::run("CppCheck::executeAddons", mSettings.showtime, &s_timerResults, [&]() {
+            executeAddons(f, file.spath());
+        });
     }
 }
 

lib/timer.cpp

@@ -29,7 +29,7 @@ namespace {
     using dataElementType = std::pair<std::string, TimerResultsData>;
     bool more_second_sec(const dataElementType& lhs, const dataElementType& rhs)
     {
-        return lhs.second.seconds() > rhs.second.seconds();
+        return lhs.second.getSeconds() > rhs.second.getSeconds();
     }
 
     // TODO: remove and print through (synchronized) ErrorLogger instead
@@ -42,8 +42,6 @@ void TimerResults::showResults(SHOWTIME_MODES mode) const
 {
     if (mode == SHOWTIME_MODES::SHOWTIME_NONE || mode == SHOWTIME_MODES::SHOWTIME_FILE_TOTAL)
         return;
-
-    TimerResultsData overallData;
     std::vector<dataElementType> data;
 
     {
@@ -61,38 +59,20 @@ void TimerResults::showResults(SHOWTIME_MODES mode) const
 
     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.seconds();
+        const double sec = iter->second.getSeconds().count();
         const double secAverage = sec / static_cast<double>(iter->second.mNumberOfResults);
-        bool hasParent = false;
-        {
-            // Do not use valueFlow.. in "Overall time" because those are included in Tokenizer already
-            if (startsWith(iter->first,"valueFlow"))
-                hasParent = true;
-
-            // Do not use inner timers in "Overall time"
-            const std::string::size_type pos = iter->first.rfind("::");
-            if (pos != std::string::npos)
-                hasParent = std::any_of(data.cbegin(), data.cend(), [iter,pos](const dataElementType& d) {
-                    return d.first.size() == pos && iter->first.compare(0, d.first.size(), d.first) == 0;
-                });
-        }
-        if (!hasParent)
-            overallData.mClocks += iter->second.mClocks;
         if ((mode != SHOWTIME_MODES::SHOWTIME_TOP5_FILE && mode != SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY) || (ordinal<=5)) {
             std::cout << iter->first << ": " << sec << "s (avg. " << secAverage << "s - " << iter->second.mNumberOfResults  << " result(s))" << std::endl;
         }
         ++ordinal;
     }
-
-    const double secOverall = overallData.seconds();
-    std::cout << "Overall time: " << secOverall << "s" << std::endl;
 }
 
-void TimerResults::addResults(const std::string& str, std::clock_t clocks)
+void TimerResults::addResults(const std::string& str, Duration duration)
 {
     std::lock_guard<std::mutex> l(mResultsSync);
 
-    mResults[str].mClocks += clocks;
+    mResults[str].mDuration += duration;
     mResults[str].mNumberOfResults++;
 }
 
@@ -105,14 +85,8 @@ void TimerResults::reset()
 Timer::Timer(std::string str, SHOWTIME_MODES showtimeMode, TimerResultsIntf* timerResults)
     : mStr(std::move(str))
     , mTimerResults(timerResults)
-    , mStart(std::clock())
     , mShowTimeMode(showtimeMode)
-    , mStopped(showtimeMode == SHOWTIME_MODES::SHOWTIME_NONE || showtimeMode == SHOWTIME_MODES::SHOWTIME_FILE_TOTAL)
-{}
-
-Timer::Timer(bool fileTotal, std::string filename)
-    : mStr(std::move(filename))
-    , mStopped(!fileTotal)
+    , mStartTimePoint(Clock::now())
 {}
 
 Timer::~Timer()
@@ -122,23 +96,41 @@ Timer::~Timer()
 
 void Timer::stop()
 {
-    if ((mShowTimeMode != SHOWTIME_MODES::SHOWTIME_NONE) && !mStopped) {
-        const std::clock_t end = std::clock();
-        const std::clock_t diff = end - mStart;
-
-        if (mShowTimeMode == SHOWTIME_MODES::SHOWTIME_FILE) {
-            const double sec = static_cast<double>(diff) / CLOCKS_PER_SEC;
-            std::lock_guard<std::mutex> l(stdCoutLock);
-            std::cout << mStr << ": " << sec << "s" << std::endl;
-        } else if (mShowTimeMode == SHOWTIME_MODES::SHOWTIME_FILE_TOTAL) {
-            const double sec = static_cast<double>(diff) / CLOCKS_PER_SEC;
+    if ((mShowTimeMode != SHOWTIME_MODES::SHOWTIME_NONE) && mStartTimePoint != TimePoint{}) {
+        Duration diff = std::chrono::duration_cast<Duration>(Clock::now() - mStartTimePoint);
+        if (!mTimerResults) {
+            if (mStr == "Summary"
+                && (mShowTimeMode != SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY && mShowTimeMode != SHOWTIME_MODES::SHOWTIME_TOP5_FILE && mShowTimeMode != SHOWTIME_MODES::SHOWTIME_SUMMARY))
+                return;
+            if (mStr != "Summary"
+                && (mShowTimeMode != SHOWTIME_MODES::SHOWTIME_FILE && mShowTimeMode != SHOWTIME_MODES::SHOWTIME_FILE_TOTAL))
+                return;
             std::lock_guard<std::mutex> l(stdCoutLock);
-            std::cout << "Check time: " << mStr << ": " << sec << "s" << std::endl;
+            std::cout << (mStr == "Summary" ? "Overall time: " : "Check time: " + mStr + ": ")<< durationToString(diff) << std::endl;
         } else {
-            if (mTimerResults)
-                mTimerResults->addResults(mStr, diff);
+            mTimerResults->addResults(mStr, diff);
         }
     }
+}
 
-    mStopped = true;
+std::string Timer::durationToString(Duration duration)
+{
+    // Extract hours
+    auto hours = std::chrono::duration_cast<std::chrono::hours>(duration);
+    duration -= hours; // Subtract the extracted hours
+
+    // Extract minutes
+    auto minutes = std::chrono::duration_cast<std::chrono::minutes>(duration);
+    duration -= minutes; // Subtract the extracted minutes
+
+    // Extract seconds
+    std::chrono::duration<double> seconds = std::chrono::duration_cast<std::chrono::duration<double>>(duration);
+
+    std::string ellapsedTime;
+    if (hours.count() > 0)
+        ellapsedTime += std::to_string(hours.count()) + "h ";
+    if (minutes.count() > 0)
+        ellapsedTime += std::to_string(minutes.count()) + "m ";
+    std::string secondsStr{std::to_string(seconds.count())};
+    return (ellapsedTime + secondsStr.substr(0, secondsStr.length() - 3) + "s ");
 }

lib/timer.h

@@ -22,6 +22,7 @@
 
 #include "config.h"
 
+#include <chrono>
 #include <cstdint>
 #include <ctime>
 #include <functional>
@@ -30,6 +31,10 @@
 #include <string>
 #include <utility>
 
+using Clock = std::chrono::high_resolution_clock;
+using TimePoint = std::chrono::time_point<Clock>;
+using Duration = std::chrono::milliseconds;
+
 enum class SHOWTIME_MODES : std::uint8_t {
     SHOWTIME_NONE,
     SHOWTIME_FILE,
@@ -43,16 +48,15 @@ class CPPCHECKLIB TimerResultsIntf {
 public:
     virtual ~TimerResultsIntf() = default;
 
-    virtual void addResults(const std::string& str, std::clock_t clocks) = 0;
+    virtual void addResults(const std::string& timerName, Duration duation) = 0;
 };
 
 struct TimerResultsData {
-    std::clock_t mClocks{};
+    Duration mDuration;
     long mNumberOfResults{};
 
-    double seconds() const {
-        const double ret = static_cast<double>(static_cast<unsigned long>(mClocks)) / static_cast<double>(CLOCKS_PER_SEC);
-        return ret;
+    std::chrono::duration<double> getSeconds() const {
+        return std::chrono::duration_cast<std::chrono::duration<double>>(mDuration);
     }
 };
 
@@ -61,7 +65,7 @@ class CPPCHECKLIB TimerResults : public TimerResultsIntf {
     TimerResults() = default;
 
     void showResults(SHOWTIME_MODES mode) const;
-    void addResults(const std::string& str, std::clock_t clocks) override;
+    void addResults(const std::string& str, Duration duration) override;
 
     void reset();
 
@@ -73,14 +77,15 @@ class CPPCHECKLIB TimerResults : public TimerResultsIntf {
 class CPPCHECKLIB Timer {
 public:
     Timer(std::string str, SHOWTIME_MODES showtimeMode, TimerResultsIntf* timerResults = nullptr);
-    Timer(bool fileTotal, std::string filename);
     ~Timer();
 
     Timer(const Timer&) = delete;
     Timer& operator=(const Timer&) = delete;
 
     void stop();
 
+    static std::string durationToString(Duration duration);
+
     static void run(std::string str, SHOWTIME_MODES showtimeMode, TimerResultsIntf* timerResults, const std::function<void()>& f) {
         Timer t(std::move(str), showtimeMode, timerResults);
         f();
@@ -89,9 +94,9 @@ class CPPCHECKLIB Timer {
 private:
     const std::string mStr;
     TimerResultsIntf* mTimerResults{};
-    std::clock_t mStart = std::clock();
     const SHOWTIME_MODES mShowTimeMode = SHOWTIME_MODES::SHOWTIME_FILE_TOTAL;
-    bool mStopped{};
+    TimePoint mStartTimePoint;
 };
+
 //---------------------------------------------------------------------------
 #endif // timerH

lib/valueflow.cpp

@@ -112,7 +112,6 @@
 #include <algorithm>
 #include <array>
 #include <cassert>
-#include <chrono>
 #include <cstdint>
 #include <cstdlib>
 #include <cstring>

test/testprocessexecutor.cpp

@@ -248,7 +248,7 @@ class TestProcessExecutorBase : public TestFixture {
                     $.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY));
         const std::string output_s = GET_REDIRECT_OUTPUT;
         // once: top5 results + overall + empty line
-        TODO_ASSERT_EQUALS(5 + 1 + 1, 2, cppcheck::count_all_of(output_s, '\n'));
+        TODO_ASSERT_EQUALS(5 + 1 + 1, 1, cppcheck::count_all_of(output_s, '\n'));
         // should only report the top5 once
         ASSERT(output_s.find("1 result(s)") == std::string::npos);
         TODO_ASSERT(output_s.find("2 result(s)") != std::string::npos);

test/testsingleexecutor.cpp

@@ -242,8 +242,8 @@ class TestSingleExecutorBase : public TestFixture {
               dinit(CheckOptions,
                     $.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_FILE));
         const std::string output_s = GET_REDIRECT_OUTPUT;
-        // for each file: top5 results + overall + empty line
-        ASSERT_EQUALS((5 + 1 + 1) * 2LL, cppcheck::count_all_of(output_s, '\n'));
+        // for each file: top5 results + overall
+        ASSERT_EQUALS((5 + 1) * 2LL, cppcheck::count_all_of(output_s, '\n'));
     }
 
     void showtime_top5_summary() {
@@ -253,8 +253,8 @@ class TestSingleExecutorBase : public TestFixture {
               dinit(CheckOptions,
                     $.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY));
         const std::string output_s = GET_REDIRECT_OUTPUT;
-        // once: top5 results + overall + empty line
-        ASSERT_EQUALS(5 + 1 + 1, cppcheck::count_all_of(output_s, '\n'));
+        // once: top5 results + overall
+        ASSERT_EQUALS(5 + 1, cppcheck::count_all_of(output_s, '\n'));
         // should only report the top5 once
         ASSERT(output_s.find("1 result(s)") == std::string::npos);
         ASSERT(output_s.find("2 result(s)") != std::string::npos);
@@ -267,7 +267,7 @@ class TestSingleExecutorBase : public TestFixture {
               dinit(CheckOptions,
                     $.showtime = SHOWTIME_MODES::SHOWTIME_FILE));
         const std::string output_s = GET_REDIRECT_OUTPUT;
-        ASSERT_EQUALS(2, cppcheck::count_all_of(output_s, "Overall time:"));
+        ASSERT_EQUALS(0, cppcheck::count_all_of(output_s, "Overall time:"));
     }
 
     void showtime_summary() {

test/testthreadexecutor.cpp

@@ -233,10 +233,9 @@ class TestThreadExecutorBase : public TestFixture {
               "int main() {}",
               dinit(CheckOptions,
                     $.showtime = SHOWTIME_MODES::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
-        ASSERT_EQUALS((5 + 1 + 1) * 2LL, cppcheck::count_all_of(output_s, '\n'));
+        // for each file: top5 results + overall
+        ASSERT_EQUALS((5 + 1) * 2LL, cppcheck::count_all_of(output_s, '\n'));
     }
 
     void showtime_top5_summary() {
@@ -246,8 +245,8 @@ class TestThreadExecutorBase : public TestFixture {
               dinit(CheckOptions,
                     $.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY));
         const std::string output_s = GET_REDIRECT_OUTPUT;
-        // once: top5 results + overall + empty line
-        ASSERT_EQUALS(5 + 1 + 1, cppcheck::count_all_of(output_s, '\n'));
+        // once: top5 results + overall
+        ASSERT_EQUALS(5 + 1, cppcheck::count_all_of(output_s, '\n'));
         // should only report the top5 once
         ASSERT(output_s.find("1 result(s)") == std::string::npos);
         ASSERT(output_s.find("2 result(s)") != std::string::npos);
@@ -260,7 +259,7 @@ class TestThreadExecutorBase : public TestFixture {
               dinit(CheckOptions,
                     $.showtime = SHOWTIME_MODES::SHOWTIME_FILE));
         const std::string output_s = GET_REDIRECT_OUTPUT;
-        ASSERT_EQUALS(2, cppcheck::count_all_of(output_s, "Overall time:"));
+        ASSERT_EQUALS(0, cppcheck::count_all_of(output_s, "Overall time:"));
     }
 
     void showtime_summary() {

test/testtimer.cpp

@@ -34,11 +34,10 @@ class TestTimer : public TestFixture {
 
     void result() const {
         TimerResultsData t1;
-        t1.mClocks = ~static_cast<std::clock_t>(0);
-        ASSERT(t1.seconds() > 100.0);
+        t1.mDuration = Duration{1234};
+        ASSERT(t1.getSeconds().count() > 1.233 && t1.getSeconds().count() < 1.235);
 
-        t1.mClocks = CLOCKS_PER_SEC * 5 / 2;
-        ASSERT(std::fabs(t1.seconds()-2.5) < 0.01);
+        // TODO : more tests
     }
 };