refs #4452 / refs #11705 - improved --showtime= behavior and testing

.github/workflows/CI-unixish.yml

@@ -384,10 +384,6 @@ jobs:
         env:
           STRICT: 1
 
-      - name: Run showtimetop5 tests
-        run: |
-          ./tools/test_showtimetop5.sh
-
       - name: Run --dump test
         run: |
           ./cppcheck test/testpreprocessor.cpp --dump
@@ -470,7 +466,7 @@ jobs:
 
       - name: Self check
         run: |
-          selfcheck_options="-q -j$(nproc) --std=c++11 --template=selfcheck --showtime=top5 -D__CPPCHECK__ -D__GNUC__ -DCHECK_INTERNAL -DHAVE_RULES --error-exitcode=1 --inline-suppr --suppressions-list=.selfcheck_suppressions --library=gnu --library=cppcheck-lib -Ilib -Iexternals/simplecpp/ -Iexternals/tinyxml2/ --inconclusive --enable=style,performance,portability,warning,missingInclude,internal --exception-handling --debug-warnings --check-level=exhaustive"
+          selfcheck_options="-q -j$(nproc) --std=c++11 --template=selfcheck --showtime=top5_summary -D__CPPCHECK__ -D__GNUC__ -DCHECK_INTERNAL -DHAVE_RULES --error-exitcode=1 --inline-suppr --suppressions-list=.selfcheck_suppressions --library=gnu --library=cppcheck-lib -Ilib -Iexternals/simplecpp/ -Iexternals/tinyxml2/ --inconclusive --enable=style,performance,portability,warning,missingInclude,internal --exception-handling --debug-warnings --check-level=exhaustive"
           ec=0
 
           # TODO: add --check-config          

.github/workflows/asan.yml

@@ -89,7 +89,7 @@ jobs:
       - name: Self check
         if: false
         run: |
-          selfcheck_options="-q -j$(nproc) --std=c++11 --template=selfcheck --showtime=top5 -D__CPPCHECK__ -D__GNUC__ -DCHECK_INTERNAL -DHAVE_RULES --error-exitcode=1 --inline-suppr --suppressions-list=.selfcheck_suppressions --library=cppcheck-lib --library=gnu -Ilib -Iexternals/simplecpp/ -Iexternals/tinyxml2/ --inconclusive --enable=style,performance,portability,warning,missingInclude,internal --exception-handling --debug-warnings"
+          selfcheck_options="-q -j$(nproc) --std=c++11 --template=selfcheck --showtime=top5_summary -D__CPPCHECK__ -D__GNUC__ -DCHECK_INTERNAL -DHAVE_RULES --error-exitcode=1 --inline-suppr --suppressions-list=.selfcheck_suppressions --library=cppcheck-lib --library=gnu -Ilib -Iexternals/simplecpp/ -Iexternals/tinyxml2/ --inconclusive --enable=style,performance,portability,warning,missingInclude,internal --exception-handling --debug-warnings"
           ec=0
           ./cmake.output/bin/cppcheck $selfcheck_options --addon=naming.json cli lib || ec=1
           ./cmake.output/bin/cppcheck $selfcheck_options -DQT_VERSION=0x050000 -DQ_MOC_OUTPUT_REVISION=67 -DQT_CHARTS_LIB --library=qt --addon=naming.json -Icmake.output/gui -Igui gui/*.cpp cmake.output/gui/*.cpp || ec=1

.github/workflows/tsan.yml

@@ -89,7 +89,7 @@ jobs:
       - name: Self check
         if: false
         run: |
-          selfcheck_options="-q -j$(nproc) --std=c++11 --template=selfcheck --showtime=top5 -D__CPPCHECK__ -D__GNUC__ -DCHECK_INTERNAL -DHAVE_RULES --error-exitcode=0 --inline-suppr --suppressions-list=.selfcheck_suppressions --library=gnu --library=cppcheck-lib -Ilib -Iexternals/simplecpp/ -Iexternals/tinyxml2/ --inconclusive --enable=style,performance,portability,warning,missingInclude,internal --exception-handling --debug-warnings"
+          selfcheck_options="-q -j$(nproc) --std=c++11 --template=selfcheck --showtime=top5_summary -D__CPPCHECK__ -D__GNUC__ -DCHECK_INTERNAL -DHAVE_RULES --error-exitcode=0 --inline-suppr --suppressions-list=.selfcheck_suppressions --library=gnu --library=cppcheck-lib -Ilib -Iexternals/simplecpp/ -Iexternals/tinyxml2/ --inconclusive --enable=style,performance,portability,warning,missingInclude,internal --exception-handling --debug-warnings"
           ec=0
           ./cmake.output/bin/cppcheck $selfcheck_options --addon=naming.json -DCHECK_INTERNAL cli lib || ec=1
           ./cmake.output/bin/cppcheck $selfcheck_options -DQT_VERSION=0x050000 -DQ_MOC_OUTPUT_REVISION=67 -DQT_CHARTS_LIB --library=qt --addon=naming.json -Icmake.output/gui -Igui gui/*.cpp cmake.output/gui/*.cpp || ec=1

.github/workflows/ubsan.yml

@@ -85,7 +85,7 @@ jobs:
       # TODO: only fail the step on sanitizer issues - since we use processes it will only fail the underlying process which will result in an cppcheckError
       - name: Self check
         run: |
-          selfcheck_options="-q -j$(nproc) --std=c++11 --template=selfcheck --showtime=top5 -D__CPPCHECK__ -D__GNUC__ -DCHECK_INTERNAL -DHAVE_RULES --error-exitcode=1 --inline-suppr --suppressions-list=.selfcheck_suppressions --library=gnu --library=cppcheck-lib -Ilib -Iexternals/simplecpp/ -Iexternals/tinyxml2/ --inconclusive --enable=style,performance,portability,warning,missingInclude,internal --exception-handling --debug-warnings"
+          selfcheck_options="-q -j$(nproc) --std=c++11 --template=selfcheck --showtime=top5_summary -D__CPPCHECK__ -D__GNUC__ -DCHECK_INTERNAL -DHAVE_RULES --error-exitcode=1 --inline-suppr --suppressions-list=.selfcheck_suppressions --library=gnu --library=cppcheck-lib -Ilib -Iexternals/simplecpp/ -Iexternals/tinyxml2/ --inconclusive --enable=style,performance,portability,warning,missingInclude,internal --exception-handling --debug-warnings"
           ec=0
           ./cmake.output/bin/cppcheck $selfcheck_options --addon=naming.json cli lib || ec=1
           ./cmake.output/bin/cppcheck $selfcheck_options -DQT_VERSION=0x050000 -DQ_MOC_OUTPUT_REVISION=67 -DQT_CHARTS_LIB --library=qt --addon=naming.json -Icmake.output/gui -Igui gui/*.cpp cmake.output/gui/*.cpp || ec=1

Makefile

@@ -660,19 +660,19 @@ cli/filelister.o: cli/filelister.cpp cli/filelister.h lib/config.h lib/path.h li
 cli/main.o: cli/main.cpp cli/cppcheckexecutor.h lib/color.h lib/config.h lib/errorlogger.h lib/errortypes.h
 	$(CXX) ${INCLUDE_FOR_CLI} $(CPPFLAGS) $(CXXFLAGS) -c -o $@ cli/main.cpp
 
-cli/processexecutor.o: cli/processexecutor.cpp cli/cppcheckexecutor.h cli/executor.h cli/processexecutor.h lib/analyzerinfo.h lib/check.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/platform.h lib/settings.h lib/standards.h lib/suppressions.h lib/utils.h
+cli/processexecutor.o: cli/processexecutor.cpp cli/cppcheckexecutor.h cli/executor.h cli/processexecutor.h lib/analyzerinfo.h lib/check.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/platform.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/processexecutor.cpp
 
-cli/singleexecutor.o: cli/singleexecutor.cpp cli/executor.h cli/singleexecutor.h lib/analyzerinfo.h lib/check.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/platform.h lib/settings.h lib/standards.h lib/suppressions.h lib/utils.h
+cli/singleexecutor.o: cli/singleexecutor.cpp cli/executor.h cli/singleexecutor.h lib/analyzerinfo.h lib/check.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/platform.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/singleexecutor.cpp
 
 cli/stacktrace.o: cli/stacktrace.cpp cli/stacktrace.h lib/config.h lib/utils.h
 	$(CXX) ${INCLUDE_FOR_CLI} $(CPPFLAGS) $(CXXFLAGS) -c -o $@ cli/stacktrace.cpp
 
-cli/threadexecutor.o: cli/threadexecutor.cpp cli/cppcheckexecutor.h cli/executor.h cli/threadexecutor.h lib/analyzerinfo.h lib/check.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/platform.h lib/settings.h lib/standards.h lib/suppressions.h lib/utils.h
+cli/threadexecutor.o: cli/threadexecutor.cpp cli/cppcheckexecutor.h cli/executor.h cli/threadexecutor.h lib/analyzerinfo.h lib/check.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/platform.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/check.h lib/color.h lib/config.h lib/errorlogger.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/platform.h lib/settings.h lib/standards.h lib/suppressions.h lib/utils.h test/fixture.h test/options.h test/redirect.h
+test/fixture.o: test/fixture.cpp externals/tinyxml2/tinyxml2.h lib/analyzerinfo.h lib/check.h lib/color.h lib/config.h lib/cppcheck.h lib/errorlogger.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/platform.h lib/settings.h lib/standards.h lib/suppressions.h lib/utils.h test/fixture.h test/options.h test/redirect.h
 	$(CXX) ${INCLUDE_FOR_TEST} $(CPPFLAGS) $(CXXFLAGS) -c -o $@ test/fixture.cpp
 
 test/helpers.o: test/helpers.cpp cli/filelister.h externals/simplecpp/simplecpp.h lib/config.h lib/errortypes.h lib/importproject.h lib/library.h lib/mathlib.h lib/path.h lib/pathmatch.h lib/platform.h lib/preprocessor.h lib/settings.h lib/standards.h lib/suppressions.h lib/templatesimplifier.h lib/token.h lib/tokenize.h lib/tokenlist.h lib/utils.h lib/vfvalue.h test/helpers.h

cli/cmdlineparser.cpp

@@ -817,12 +817,22 @@ bool CmdLineParser::parseFromArgs(int argc, const char* const argv[])
                     mSettings.showtime = SHOWTIME_MODES::SHOWTIME_FILE_TOTAL;
                 else if (showtimeMode == "summary")
                     mSettings.showtime = SHOWTIME_MODES::SHOWTIME_SUMMARY;
-                else if (showtimeMode == "top5")
-                    mSettings.showtime = SHOWTIME_MODES::SHOWTIME_TOP5;
-                else if (showtimeMode.empty())
+                else if (showtimeMode == "top5") {
+                    mSettings.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_FILE;
+                    mLogger.printMessage("--showtime=top5 is deprecated and will be removed in Cppcheck 2.14. Please use --showtime=top5_file or --showtime=top5_summary instead.");
+                }
+                else if (showtimeMode == "top5_file")
+                    mSettings.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_FILE;
+                else if (showtimeMode == "top5_summary")
+                    mSettings.showtime = SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY;
+                else if (showtimeMode == "none")
                     mSettings.showtime = SHOWTIME_MODES::SHOWTIME_NONE;
+                else if (showtimeMode.empty()) {
+                    mLogger.printError("no mode provided for --showtime");
+                    return false;
+                }
                 else {
-                    mLogger.printError("unrecognized showtime mode: \"" + showtimeMode + "\". Supported modes: file, file-total, summary, top5.");
+                    mLogger.printError("unrecognized --showtime mode: '" + showtimeMode + "'. Supported modes: file, file-total, summary, top5, top5_file, top5_summary.");
                     return false;
                 }
             }
@@ -1268,6 +1278,22 @@ void CmdLineParser::printHelp()
     "    --rule-file=<file>   Use given rule file. For more information, see:\n"
     "                         http://sourceforge.net/projects/cppcheck/files/Articles/\n"
 #endif
+    "    --showtime=<mode>    Show timing information.\n"
+    "                         The available modes are:\n"
+    "                          * none\n"
+    "                                 Show nothing (default)\n"
+    "                          * file\n"
+    "                                 Show for each processed file\n"
+    "                          * file-total\n"
+    "                                 Show total time only for each processed file\n"
+    "                          * summary\n"
+    "                                 Show a summary at the end\n"
+    "                          * top5_file\n"
+    "                                 Show the top 5 for each processed file\n"
+    "                          * top5_summary\n"
+    "                                 Show the top 5 summary at the end\n"
+    "                          * top5\n"
+    "                                 Alias for top5_file (deprecated)\n"
     "    --std=<id>           Set standard.\n"
     "                         The available options are:\n"
     "                          * c89\n"

cli/processexecutor.cpp

@@ -28,6 +28,7 @@
 #include "importproject.h"
 #include "settings.h"
 #include "suppressions.h"
+#include "timer.h"
 
 #include <algorithm>
 #include <numeric>
@@ -375,6 +376,9 @@ 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)
+        CppCheck::printTimerResults(mSettings.showtime);
 
     return result;
 }

cli/singleexecutor.cpp

@@ -22,6 +22,7 @@
 #include "importproject.h"
 #include "library.h"
 #include "settings.h"
+#include "timer.h"
 
 #include <cassert>
 #include <list>
@@ -110,5 +111,8 @@ unsigned int SingleExecutor::check()
     if (mCppcheck.analyseWholeProgram())
         result++;
 
+    if (mSettings.showtime == SHOWTIME_MODES::SHOWTIME_SUMMARY || mSettings.showtime == SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY)
+        CppCheck::printTimerResults(mSettings.showtime);
+
     return result;
 }

cli/threadexecutor.cpp

@@ -24,6 +24,7 @@
 #include "errorlogger.h"
 #include "importproject.h"
 #include "settings.h"
+#include "timer.h"
 
 #include <algorithm>
 #include <cassert>
@@ -191,7 +192,12 @@ unsigned int ThreadExecutor::check()
         }
     }
 
-    return std::accumulate(threadFutures.begin(), threadFutures.end(), 0U, [](unsigned int v, std::future<unsigned int>& f) {
+    unsigned int result = std::accumulate(threadFutures.begin(), threadFutures.end(), 0U, [](unsigned int v, std::future<unsigned int>& f) {
         return v + f.get();
     });
+
+    if (mSettings.showtime == SHOWTIME_MODES::SHOWTIME_SUMMARY || mSettings.showtime == SHOWTIME_MODES::SHOWTIME_TOP5_SUMMARY)
+        CppCheck::printTimerResults(mSettings.showtime);
+
+    return result;
 }

lib/cppcheck.cpp

@@ -467,7 +467,6 @@ CppCheck::~CppCheck()
         delete mFileInfo.back();
         mFileInfo.pop_back();
     }
-    s_timerResults.showResults(mSettings.showtime);
 
     if (mPlistFile.is_open()) {
         mPlistFile << ErrorLogger::plistFooter();
@@ -1100,6 +1099,9 @@ unsigned int CppCheck::checkFile(const std::string& filename, const std::string
 
     mErrorList.clear();
 
+    if (mSettings.showtime == SHOWTIME_MODES::SHOWTIME_FILE || mSettings.showtime == SHOWTIME_MODES::SHOWTIME_TOP5_FILE)
+        printTimerResults(mSettings.showtime);
+
     return mExitCode;
 }
 
@@ -1903,3 +1905,14 @@ void CppCheck::removeCtuInfoFiles(const std::map<std::string, std::size_t> &file
         }
     }
 }
+
+// cppcheck-suppress unusedFunction - only used in tests
+void CppCheck::resetTimerResults()
+{
+    s_timerResults.reset();
+}
+
+void CppCheck::printTimerResults(SHOWTIME_MODES mode)
+{
+    s_timerResults.showResults(mode);
+}

lib/cppcheck.h

@@ -143,6 +143,9 @@ class CPPCHECKLIB CppCheck : ErrorLogger {
     /** Remove *.ctu-info files */
     void removeCtuInfoFiles(const std::map<std::string, std::size_t>& files); // cppcheck-suppress functionConst // has side effects
 
+    static void resetTimerResults();
+    static void printTimerResults(SHOWTIME_MODES mode);
+
 private:
 #ifdef HAVE_RULES
     /** Are there "simple" rules */

lib/timer.cpp

@@ -24,38 +24,41 @@
 #include <iostream>
 #include <utility>
 #include <vector>
-/*
-    TODO:
-    - rename "file" to "single"
-    - add unit tests
-        - for --showtime (needs input file)
-        - for Timer* classes
- */
 
 namespace {
     using dataElementType = std::pair<std::string, struct TimerResultsData>;
     bool more_second_sec(const dataElementType& lhs, const dataElementType& rhs)
     {
         return lhs.second.seconds() > rhs.second.seconds();
     }
+
+    // TODO: remove and print through (synchronized) ErrorLogger instead
+    std::mutex stdCoutLock;
 }
 
+// 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
 {
     if (mode == SHOWTIME_MODES::SHOWTIME_NONE || mode == SHOWTIME_MODES::SHOWTIME_FILE_TOTAL)
         return;
 
-    std::cout << std::endl;
     TimerResultsData overallData;
-
     std::vector<dataElementType> data;
+
     {
         std::lock_guard<std::mutex> l(mResultsSync);
+
         data.reserve(mResults.size());
         data.insert(data.begin(), mResults.cbegin(), mResults.cend());
     }
     std::sort(data.begin(), data.end(), more_second_sec);
 
+    // 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 (std::vector<dataElementType>::const_iterator iter=data.cbegin(); iter!=data.cend(); ++iter) {
         const double sec = iter->second.seconds();
@@ -75,7 +78,7 @@ void TimerResults::showResults(SHOWTIME_MODES mode) const
         }
         if (!hasParent)
             overallData.mClocks += iter->second.mClocks;
-        if ((mode != SHOWTIME_MODES::SHOWTIME_TOP5) || (ordinal<=5)) {
+        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;
@@ -93,6 +96,12 @@ void TimerResults::addResults(const std::string& str, std::clock_t clocks)
     mResults[str].mNumberOfResults++;
 }
 
+void TimerResults::reset()
+{
+    std::lock_guard<std::mutex> l(mResultsSync);
+    mResults.clear();
+}
+
 Timer::Timer(std::string str, SHOWTIME_MODES showtimeMode, TimerResultsIntf* timerResults)
     : mStr(std::move(str))
     , mTimerResults(timerResults)
@@ -119,9 +128,11 @@ void Timer::stop()
 
         if (mShowTimeMode == SHOWTIME_MODES::SHOWTIME_FILE) {
             const double sec = (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 = (double)diff / CLOCKS_PER_SEC;
+            std::lock_guard<std::mutex> l(stdCoutLock);
             std::cout << "Check time: " << mStr << ": " << sec << "s" << std::endl;
         } else {
             if (mTimerResults)

lib/timer.h

@@ -32,7 +32,8 @@ enum class SHOWTIME_MODES {
     SHOWTIME_FILE,
     SHOWTIME_FILE_TOTAL,
     SHOWTIME_SUMMARY,
-    SHOWTIME_TOP5
+    SHOWTIME_TOP5_SUMMARY,
+    SHOWTIME_TOP5_FILE
 };
 
 class CPPCHECKLIB TimerResultsIntf {
@@ -59,6 +60,8 @@ class CPPCHECKLIB TimerResults : public TimerResultsIntf {
     void showResults(SHOWTIME_MODES mode) const;
     void addResults(const std::string& str, std::clock_t clocks) override;
 
+    void reset();
+
 private:
     std::map<std::string, struct TimerResultsData> mResults;
     mutable std::mutex mResultsSync;