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/cmdlineparser.cpp

@@ -1393,17 +1393,17 @@ CmdLineParser::Result CmdLineParser::parseFromArgs(int argc, const char* const a
         else if (std::strncmp(argv[i], "--showtime=", 11) == 0) {
             const std::string showtimeMode = argv[i] + 11;
             if (showtimeMode == "file")
-                mSettings.showtime = SHOWTIME_MODES::SHOWTIME_FILE;
+                mSettings.showtime = ShowTime::FILE;
             else if (showtimeMode == "file-total")
-                mSettings.showtime = SHOWTIME_MODES::SHOWTIME_FILE_TOTAL;
+                mSettings.showtime = ShowTime::FILE_TOTAL;
             else if (showtimeMode == "summary")
-                mSettings.showtime = SHOWTIME_MODES::SHOWTIME_SUMMARY;
+                mSettings.showtime = ShowTime::SUMMARY;
             else if (showtimeMode == "top5_file")
-                mSettings.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_FILE;
+                mSettings.showtime = ShowTime::TOP5_FILE;
             else if (showtimeMode == "top5_summary")
-                mSettings.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY;
+                mSettings.showtime = ShowTime::TOP5_SUMMARY;
             else if (showtimeMode == "none")
-                mSettings.showtime = SHOWTIME_MODES::SHOWTIME_NONE;
+                mSettings.showtime = ShowTime::NONE;
             else if (showtimeMode.empty()) {
                 mLogger.printError("no mode provided for --showtime");
                 return Result::Fail;

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(Timer::OVERALL, settings.showtime);
+
     settings.loadSummaries();
 
     mFiles = parser.getFiles();

cli/processexecutor.cpp

@@ -450,7 +450,7 @@ unsigned int ProcessExecutor::check()
     }
 
     // TODO: wee need to get the timing information from the subprocess
-    if (mSettings.showtime == SHOWTIME_MODES::SHOWTIME_SUMMARY || mSettings.showtime == SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY)
+    if (mSettings.showtime == ShowTime::SUMMARY || mSettings.showtime == ShowTime::TOP5_SUMMARY)
         CppCheck::printTimerResults(mSettings.showtime);
 
     return result;

cli/singleexecutor.cpp

@@ -70,7 +70,7 @@ unsigned int SingleExecutor::check()
     if (mCppcheck.analyseWholeProgram())
         result++;
 
-    if (mSettings.showtime == SHOWTIME_MODES::SHOWTIME_SUMMARY || mSettings.showtime == SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY)
+    if (mSettings.showtime == ShowTime::SUMMARY || mSettings.showtime == ShowTime::TOP5_SUMMARY)
         CppCheck::printTimerResults(mSettings.showtime);
 
     return result;

cli/threadexecutor.cpp

@@ -214,7 +214,7 @@ unsigned int ThreadExecutor::check()
         return v + f.get();
     });
 
-    if (mSettings.showtime == SHOWTIME_MODES::SHOWTIME_SUMMARY || mSettings.showtime == SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY)
+    if (mSettings.showtime == ShowTime::SUMMARY || mSettings.showtime == ShowTime::TOP5_SUMMARY)
         CppCheck::printTimerResults(mSettings.showtime);
 
     return result;

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());
@@ -1155,7 +1155,7 @@ unsigned int CppCheck::checkInternal(const FileWithDetails& file, const std::str
 
                 Tokenizer tokenizer(std::move(tokenlist), mErrorLogger);
                 try {
-                    if (mSettings.showtime != SHOWTIME_MODES::SHOWTIME_NONE)
+                    if (mSettings.showtime != ShowTime::NONE)
                         tokenizer.setTimerResults(&s_timerResults);
                     tokenizer.setDirectives(directives); // TODO: how to avoid repeated copies?
 
@@ -1311,7 +1311,7 @@ unsigned int CppCheck::checkInternal(const FileWithDetails& file, const std::str
     // TODO: clear earlier?
     mLogger->clear();
 
-    if (mSettings.showtime == SHOWTIME_MODES::SHOWTIME_FILE || mSettings.showtime == SHOWTIME_MODES::SHOWTIME_TOP5_FILE)
+    if (mSettings.showtime == ShowTime::FILE || mSettings.showtime == ShowTime::TOP5_FILE)
         printTimerResults(mSettings.showtime);
 
     return mLogger->exitcode();
@@ -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());
+        });
     }
 }
 
@@ -1934,7 +1936,7 @@ void CppCheck::resetTimerResults()
     s_timerResults.reset();
 }
 
-void CppCheck::printTimerResults(SHOWTIME_MODES mode)
+void CppCheck::printTimerResults(ShowTime mode)
 {
     s_timerResults.showResults(mode);
 }

lib/cppcheck.h

@@ -33,7 +33,7 @@
 #include <vector>
 
 class TokenList;
-enum class SHOWTIME_MODES : std::uint8_t;
+enum class ShowTime : std::uint8_t;
 struct FileSettings;
 class CheckUnusedFunctions;
 class Tokenizer;
@@ -143,7 +143,7 @@ class CPPCHECKLIB CppCheck {
     unsigned int analyseWholeProgram(const std::string &buildDir, const std::list<FileWithDetails> &files, const std::list<FileSettings>& fileSettings, const std::string& ctuInfo);
 
     static void resetTimerResults();
-    static void printTimerResults(SHOWTIME_MODES mode);
+    static void printTimerResults(ShowTime mode);
 
 private:
     void purgedConfigurationMessage(const std::string &file, const std::string& configuration);

lib/settings.h

@@ -51,7 +51,7 @@ class Regex;
 #endif
 
 struct Suppressions;
-enum class SHOWTIME_MODES : std::uint8_t;
+enum class ShowTime : std::uint8_t;
 namespace ValueFlow {
     class Value;
 }
@@ -410,7 +410,7 @@ class CPPCHECKLIB WARN_UNUSED Settings {
     SimpleEnableGroup<Checks> checks;
 
     /** @brief show timing information (--showtime=file|summary|top5) */
-    SHOWTIME_MODES showtime{};
+    ShowTime showtime{};
 
     /** Struct contains standards settings */
     Standards standards;

lib/timer.cpp

@@ -25,11 +25,13 @@
 #include <utility>
 #include <vector>
 
+constexpr char Timer::OVERALL[];
+
 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
@@ -38,12 +40,10 @@ 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_MODES mode) const
+void TimerResults::showResults(ShowTime mode) const
 {
-    if (mode == SHOWTIME_MODES::SHOWTIME_NONE || mode == SHOWTIME_MODES::SHOWTIME_FILE_TOTAL)
+    if (mode == ShowTime::NONE || mode == ShowTime::FILE_TOTAL)
         return;
-
-    TimerResultsData overallData;
     std::vector<dataElementType> data;
 
     {
@@ -61,38 +61,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)) {
+        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;
         }
         ++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, std::chrono::milliseconds duration)
 {
     std::lock_guard<std::mutex> l(mResultsSync);
 
-    mResults[str].mClocks += clocks;
+    mResults[str].mDuration += duration;
     mResults[str].mNumberOfResults++;
 }
 
@@ -102,17 +84,11 @@ void TimerResults::reset()
     mResults.clear();
 }
 
-Timer::Timer(std::string str, SHOWTIME_MODES showtimeMode, TimerResultsIntf* timerResults)
+Timer::Timer(std::string str, ShowTime 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 +98,42 @@ 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::NONE) && mStartTimePoint != TimePoint{}) {
+        auto diff = std::chrono::duration_cast<std::chrono::milliseconds>(Clock::now() - mStartTimePoint);
+        if (!mTimerResults) {
+            if (mStr == OVERALL
+                && (mShowTimeMode != ShowTime::TOP5_SUMMARY && mShowTimeMode != ShowTime::TOP5_FILE && mShowTimeMode != ShowTime::SUMMARY))
+                return;
+            if (mStr != OVERALL
+                && (mShowTimeMode != ShowTime::FILE && mShowTimeMode != ShowTime::FILE_TOTAL))
+                return;
             std::lock_guard<std::mutex> l(stdCoutLock);
-            std::cout << "Check time: " << mStr << ": " << sec << "s" << std::endl;
+            std::cout << (mStr == OVERALL ? "Overall time: " : "Check time: " + mStr + ": ")<< TimerResultsData::durationToString(diff) << std::endl;
         } else {
-            if (mTimerResults)
-                mTimerResults->addResults(mStr, diff);
+            mTimerResults->addResults(mStr, diff);
         }
     }
+    mShowTimeMode = ShowTime::NONE; // prevent multiple stops
+}
 
-    mStopped = true;
+std::string TimerResultsData::durationToString(std::chrono::milliseconds 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");
 }