Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[analyzer] Add time-trace scopes for high-level analyzer steps #125508

Merged
merged 17 commits into from
Feb 5, 2025

Conversation

necto
Copy link
Contributor

@necto necto commented Feb 3, 2025

Specifically, add a scope for

  • each work-list step,
  • each entry point,
  • each checker run within a step, and
  • bug-suppression phase at the end of the analysis of an entry-point.

These scopes add no perceptible run-time overhead when time-tracing is disabled. You can enable it and generate a time trace using the -ftime-trace=file.json option.

See also the RFC.

--
CPP-6065

Also detail:
- each checker run within each step
- bug-suppression at the end of an entry-point analysis
@llvmbot llvmbot added clang Clang issues not falling into any other category clang:static analyzer clang:analysis labels Feb 3, 2025
@llvmbot
Copy link
Member

llvmbot commented Feb 3, 2025

@llvm/pr-subscribers-clang-analysis

@llvm/pr-subscribers-clang

Author: Arseniy Zaostrovnykh (necto)

Changes

Specifically, add a scope for

  • each work-list step,
  • each entry point,
  • each checker run within a step, and
  • bug-suppression phase at the end of the analysis of an entry-point.

These scopes add no perceptible run-time overhead when time-tracing is disabled. You can enable it and generate a time trace using the -ftime-trace=file.json option.

See also the RFC.

--
CPP-6065


Patch is 30.82 KiB, truncated to 20.00 KiB below, full version: https://github.com/llvm/llvm-project/pull/125508.diff

11 Files Affected:

  • (modified) clang/docs/analyzer/developer-docs.rst (+1)
  • (added) clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst (+38)
  • (added) clang/docs/analyzer/images/speedscope.png ()
  • (modified) clang/include/clang/Analysis/ProgramPoint.h (+3)
  • (modified) clang/lib/Analysis/ProgramPoint.cpp (+121)
  • (modified) clang/lib/StaticAnalyzer/Core/BugReporter.cpp (+35-2)
  • (modified) clang/lib/StaticAnalyzer/Core/BugSuppression.cpp (+27)
  • (modified) clang/lib/StaticAnalyzer/Core/CheckerManager.cpp (+63-14)
  • (modified) clang/lib/StaticAnalyzer/Core/CoreEngine.cpp (+35-2)
  • (modified) clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp (+40-8)
  • (added) clang/test/Analysis/ftime-trace.cpp (+56)
diff --git a/clang/docs/analyzer/developer-docs.rst b/clang/docs/analyzer/developer-docs.rst
index 1b8133ffa8920be..60c0e71ad847c78 100644
--- a/clang/docs/analyzer/developer-docs.rst
+++ b/clang/docs/analyzer/developer-docs.rst
@@ -11,3 +11,4 @@ Contents:
    developer-docs/InitializerLists
    developer-docs/nullability
    developer-docs/RegionStore
+   developer-docs/PerformanceInvestigation
diff --git a/clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst b/clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst
new file mode 100644
index 000000000000000..78ba804dd64c8b0
--- /dev/null
+++ b/clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst
@@ -0,0 +1,38 @@
+=========================
+Performance Investigation
+=========================
+
+Multiple factors contribute to the time it takes to analyze a file with Clang Static Analyzer.
+A translation unit contains multiple entry points, each of which take multiple steps to analyze.
+
+You can add the ``-ftime-trace=file.json`` option to break down the analysis time into individual entry points and steps within each entry point.
+You can explore the generated JSON file in a Chromium browser using the ``chrome://tracing`` URL,
+or using `speedscope <https://speedscope.app>`_.
+Once you narrow down to specific analysis steps you are interested in, you can more effectively employ heavier profilers,
+such as `Perf <https://perfwiki.github.io/main/>`_ and `Callgrind <https://valgrind.org/docs/manual/cl-manual.html>`_.
+
+Each analysis step has a time scope in the trace, corresponds to processing of an exploded node, and is designated with a ``ProgramPoint``.
+If the ``ProgramPoint`` is associated with a location, you can see it on the scope metadata label.
+
+.. image:: ../images/speedscope.png
+
+On the screenshot above, under the first time ruler is the birds-eye view of the entire trace that spans a little over 8 seconds.
+Under the second ruler (focused on the 4.27s time point) you can see a narrowed-down portion.
+The second box (of light-green color) that spans entire screen (and actually extends beyond it) corresponds to the analysis of ``get_global_options()`` entry point that is defined in the "options.cc" file on line 303646
+(the line number is huge because the file was preprocessed).
+Below it, you can find multiple sub-scopes each corresponding to processing of a single exploded node.
+
+1. A ``PostStmt`` for some statement on line 2337. This step spent most of the time in the ``ExprEngine::removeDead`` call.
+2. (Selected): another ``PostStmt`` for a return statement
+3. A ``BlockEdge``, and so on...
+
+In addition to the ``-ftime-trace`` option, you can use ``-ftime-trace-granularity`` to fine-tune the time trace.
+
+- ``-ftime-trace-granularity=NN`` dumps only time scopes that are longer than NN microseconds.
+- ``-ftime-trace-verbose`` enables some additional dumps in the frontend related to template instantiations.
+  At the moment, it has no effect on the traces from the static analyzer.
+
+Note: Both Chrome-tracing and speedscope tools might struggle with time traces above 100 MB in size.
+Luckily, in most cases the default max-steps boundary of 225 000 produces the traces of approximately that size
+for a single entry point.
+You should use ``-analyze-function=get_global_options`` together with ``-ftime-trace`` to narrow down analysis to a specific entry point.
diff --git a/clang/docs/analyzer/images/speedscope.png b/clang/docs/analyzer/images/speedscope.png
new file mode 100644
index 000000000000000..54b64041468cbe4
Binary files /dev/null and b/clang/docs/analyzer/images/speedscope.png differ
diff --git a/clang/include/clang/Analysis/ProgramPoint.h b/clang/include/clang/Analysis/ProgramPoint.h
index b9339570e1ae70f..f4b044333b8a8c8 100644
--- a/clang/include/clang/Analysis/ProgramPoint.h
+++ b/clang/include/clang/Analysis/ProgramPoint.h
@@ -85,6 +85,9 @@ class ProgramPoint {
               LoopExitKind,
               EpsilonKind};
 
+  static const char *kindToStr(Kind K);
+  std::optional<SourceLocation> getSourceLocation() const;
+
 private:
   const void *Data1;
   llvm::PointerIntPair<const void *, 2, unsigned> Data2;
diff --git a/clang/lib/Analysis/ProgramPoint.cpp b/clang/lib/Analysis/ProgramPoint.cpp
index 7945c5c2fc27fc6..faf6b71cf18c9e3 100644
--- a/clang/lib/Analysis/ProgramPoint.cpp
+++ b/clang/lib/Analysis/ProgramPoint.cpp
@@ -49,6 +49,127 @@ LLVM_DUMP_METHOD void ProgramPoint::dump() const {
   return printJson(llvm::errs());
 }
 
+const char *ProgramPoint::kindToStr(Kind K) {
+  switch (K) {
+  case BlockEdgeKind:
+    return "BlockEdge";
+  case BlockEntranceKind:
+    return "BlockEntrance";
+  case BlockExitKind:
+    return "BlockExit";
+  case PreStmtKind:
+    return "PreStmt";
+  case PreStmtPurgeDeadSymbolsKind:
+    return "PreStmtPurgeDeadSymbols";
+  case PostStmtPurgeDeadSymbolsKind:
+    return "PostStmtPurgeDeadSymbols";
+  case PostStmtKind:
+    return "PostStmt";
+  case PreLoadKind:
+    return "PreLoad";
+  case PostLoadKind:
+    return "PostLoad";
+  case PreStoreKind:
+    return "PreStore";
+  case PostStoreKind:
+    return "PostStore";
+  case PostConditionKind:
+    return "PostCondition";
+  case PostLValueKind:
+    return "PostLValue";
+  case PostAllocatorCallKind:
+    return "PostAllocatorCall";
+  case PostInitializerKind:
+    return "PostInitializer";
+  case CallEnterKind:
+    return "CallEnter";
+  case CallExitBeginKind:
+    return "CallExitBegin";
+  case CallExitEndKind:
+    return "CallExitEnd";
+  case FunctionExitKind:
+    return "FunctionExit";
+  case PreImplicitCallKind:
+    return "PreImplicitCall";
+  case PostImplicitCallKind:
+    return "PostImplicitCall";
+  case LoopExitKind:
+    return "LoopExit";
+  case EpsilonKind:
+    return "Epsilon";
+  }
+  llvm_unreachable("Unknown ProgramPoint kind");
+}
+
+std::optional<SourceLocation> ProgramPoint::getSourceLocation() const {
+  switch (getKind()) {
+  case BlockEdgeKind:
+    // return castAs<BlockEdge>().getSrc()->getTerminatorStmt()->getBeginLoc();
+    return std::nullopt;
+  case BlockEntranceKind:
+    // return castAs<BlockEntrance>().getBlock()->getLabel()->getBeginLoc();
+    return std::nullopt;
+  case BlockExitKind:
+    // return
+    // castAs<BlockExit>().getBlock()->getTerminatorStmt()->getBeginLoc();
+    return std::nullopt;
+  case PreStmtKind:
+    [[fallthrough]];
+  case PreStmtPurgeDeadSymbolsKind:
+    [[fallthrough]];
+  case PostStmtPurgeDeadSymbolsKind:
+    [[fallthrough]];
+  case PostStmtKind:
+    [[fallthrough]];
+  case PreLoadKind:
+    [[fallthrough]];
+  case PostLoadKind:
+    [[fallthrough]];
+  case PreStoreKind:
+    [[fallthrough]];
+  case PostStoreKind:
+    [[fallthrough]];
+  case PostConditionKind:
+    [[fallthrough]];
+  case PostLValueKind:
+    [[fallthrough]];
+  case PostAllocatorCallKind:
+    if (const Stmt *S = castAs<StmtPoint>().getStmt())
+      return S->getBeginLoc();
+    return std::nullopt;
+  case PostInitializerKind:
+    if (const auto *Init = castAs<PostInitializer>().getInitializer())
+      return Init->getSourceLocation();
+    return std::nullopt;
+  case CallEnterKind:
+    if (const Stmt *S = castAs<CallEnter>().getCallExpr())
+      return S->getBeginLoc();
+    return std::nullopt;
+  case CallExitBeginKind:
+    if (const Stmt *S = castAs<CallExitBegin>().getReturnStmt())
+      return S->getBeginLoc();
+    return std::nullopt;
+  case CallExitEndKind:
+    return std::nullopt;
+  case FunctionExitKind:
+    if (const auto *B = castAs<FunctionExitPoint>().getBlock();
+        B && B->getTerminatorStmt())
+      return B->getTerminatorStmt()->getBeginLoc();
+    return std::nullopt;
+  case PreImplicitCallKind:
+    return castAs<ImplicitCallPoint>().getLocation();
+  case PostImplicitCallKind:
+    return castAs<ImplicitCallPoint>().getLocation();
+  case LoopExitKind:
+    if (const Stmt *S = castAs<LoopExit>().getLoopStmt())
+      return S->getBeginLoc();
+    return std::nullopt;
+  case EpsilonKind:
+    return std::nullopt;
+  }
+  llvm_unreachable("Unknown ProgramPoint kind");
+}
+
 void ProgramPoint::printJson(llvm::raw_ostream &Out, const char *NL) const {
   const ASTContext &Context =
       getLocationContext()->getAnalysisDeclContext()->getASTContext();
diff --git a/clang/lib/StaticAnalyzer/Core/BugReporter.cpp b/clang/lib/StaticAnalyzer/Core/BugReporter.cpp
index 2904eab0097dc8a..525496baf9ce8e5 100644
--- a/clang/lib/StaticAnalyzer/Core/BugReporter.cpp
+++ b/clang/lib/StaticAnalyzer/Core/BugReporter.cpp
@@ -62,6 +62,7 @@
 #include "llvm/Support/Compiler.h"
 #include "llvm/Support/ErrorHandling.h"
 #include "llvm/Support/MemoryBuffer.h"
+#include "llvm/Support/TimeProfiler.h"
 #include "llvm/Support/raw_ostream.h"
 #include <algorithm>
 #include <cassert>
@@ -287,6 +288,35 @@ class PathDiagnosticBuilder : public BugReporterContext {
   const PathSensitiveBugReport *getBugReport() const { return R; }
 };
 
+std::string timeTraceName(const BugReportEquivClass &EQ) {
+  if (!llvm::timeTraceProfilerEnabled()) {
+    return "";
+  }
+  const auto &bugReports = EQ.getReports();
+  if (bugReports.empty())
+    return "Empty Equivalence Class";
+  const BugReport *R = bugReports.front().get();
+  const auto &BT = R->getBugType();
+  return ("Flushing EQC " + BT.getDescription()).str();
+}
+
+llvm::TimeTraceMetadata timeTraceMetadata(const BugReportEquivClass &EQ) {
+  // Must be called only when constructing non-bogus TimeTraceScope
+  assert(llvm::timeTraceProfilerEnabled());
+
+  const auto &bugReports = EQ.getReports();
+  if (bugReports.empty())
+    return {};
+  const BugReport *R = bugReports.front().get();
+  const auto &BT = R->getBugType();
+  auto Loc = R->getLocation().asLocation();
+  std::string File = "";
+  if (const auto *Entry = Loc.getFileEntry())
+    File = Entry->tryGetRealPathName().str();
+  return {BT.getCheckerName().str(), File,
+          static_cast<int>(Loc.getLineNumber())};
+}
+
 } // namespace
 
 //===----------------------------------------------------------------------===//
@@ -2892,6 +2922,7 @@ std::optional<PathDiagnosticBuilder> PathDiagnosticBuilder::findValidReport(
 
     if (R->isValid()) {
       if (Reporter.getAnalyzerOptions().ShouldCrosscheckWithZ3) {
+        llvm::TimeTraceScope TCS{"Crosscheck with Z3"};
         // If crosscheck is enabled, remove all visitors, add the refutation
         // visitor and check again
         R->clearVisitors();
@@ -3119,8 +3150,10 @@ BugReport *PathSensitiveBugReporter::findReportInEquivalenceClass(
   return exampleReport;
 }
 
-void BugReporter::FlushReport(BugReportEquivClass& EQ) {
-  SmallVector<BugReport*, 10> bugReports;
+void BugReporter::FlushReport(BugReportEquivClass &EQ) {
+  llvm::TimeTraceScope TCS{timeTraceName(EQ),
+                           [&EQ]() { return timeTraceMetadata(EQ); }};
+  SmallVector<BugReport *, 10> bugReports;
   BugReport *report = findReportInEquivalenceClass(EQ, bugReports);
   if (!report)
     return;
diff --git a/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp b/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp
index 05c99c4a844e9e6..0cefdb1e50cec8e 100644
--- a/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp
+++ b/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp
@@ -9,6 +9,8 @@
 #include "clang/StaticAnalyzer/Core/BugReporter/BugSuppression.h"
 #include "clang/AST/DynamicRecursiveASTVisitor.h"
 #include "clang/StaticAnalyzer/Core/BugReporter/BugReporter.h"
+#include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/TimeProfiler.h"
 
 using namespace clang;
 using namespace ento;
@@ -119,6 +121,28 @@ class CacheInitializer : public DynamicRecursiveASTVisitor {
   Ranges &Result;
 };
 
+std::string timeScopeName(const Decl *DeclWithIssue) {
+  if (!llvm::timeTraceProfilerEnabled())
+    return "";
+  return llvm::formatv(
+             "BugSuppression::isSuppressed init suppressions cache for {0}",
+             DeclWithIssue->getDeclKindName())
+      .str();
+}
+
+llvm::TimeTraceMetadata getDeclTimeTraceMetadata(const Decl *DeclWithIssue) {
+  assert(DeclWithIssue);
+  assert(llvm::timeTraceProfilerEnabled());
+  std::string name = "<noname>";
+  if (auto ND = dyn_cast<NamedDecl>(DeclWithIssue)) {
+    name = ND->getNameAsString();
+  }
+  const auto &SM = DeclWithIssue->getASTContext().getSourceManager();
+  auto line = SM.getPresumedLineNumber(DeclWithIssue->getBeginLoc());
+  auto fname = SM.getFilename(DeclWithIssue->getBeginLoc());
+  return llvm::TimeTraceMetadata{name, fname.str(), static_cast<int>(line)};
+}
+
 } // end anonymous namespace
 
 // TODO: Introduce stable IDs for checkers and check for those here
@@ -177,6 +201,9 @@ bool BugSuppression::isSuppressed(const PathDiagnosticLocation &Location,
       std::make_pair(DeclWithIssue, CachedRanges{}));
   Ranges &SuppressionRanges = InsertionResult.first->second;
   if (InsertionResult.second) {
+    llvm::TimeTraceScope TimeScope(
+        timeScopeName(DeclWithIssue),
+        [DeclWithIssue]() { return getDeclTimeTraceMetadata(DeclWithIssue); });
     // We haven't checked this declaration for suppressions yet!
     CacheInitializer::initialize(DeclWithIssue, SuppressionRanges);
   }
diff --git a/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp b/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp
index 9f7a0fcc2edb363..421c8f81af5fe9f 100644
--- a/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp
+++ b/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp
@@ -27,6 +27,7 @@
 #include "llvm/Support/Casting.h"
 #include "llvm/Support/ErrorHandling.h"
 #include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/TimeProfiler.h"
 #include <cassert>
 #include <optional>
 #include <vector>
@@ -134,6 +135,14 @@ static void expandGraphWithCheckers(CHECK_CTX checkCtx,
 
 namespace {
 
+std::string checkerScopeName(StringRef name, const CheckerBase *checker) {
+  if (!llvm::timeTraceProfilerEnabled())
+    return "";
+  std::string checkerName =
+      checker ? checker->getCheckerName().getName().str() : "<unknown>";
+  return (name + ":" + checkerName).str();
+}
+
   struct CheckStmtContext {
     using CheckersTy = SmallVectorImpl<CheckerManager::CheckStmtFunc>;
 
@@ -153,6 +162,7 @@ namespace {
 
     void runChecker(CheckerManager::CheckStmtFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
+      llvm::TimeTraceScope TimeScope(checkerScopeName("Stmt", checkFn.Checker));
       // FIXME: Remove respondsToCallback from CheckerContext;
       ProgramPoint::Kind K =  IsPreVisit ? ProgramPoint::PreStmtKind :
                                            ProgramPoint::PostStmtKind;
@@ -172,8 +182,11 @@ void CheckerManager::runCheckersForStmt(bool isPreVisit,
                                         const Stmt *S,
                                         ExprEngine &Eng,
                                         bool WasInlined) {
-  CheckStmtContext C(isPreVisit, getCachedStmtCheckersFor(S, isPreVisit),
-                     S, Eng, WasInlined);
+  CheckStmtContext C(isPreVisit, getCachedStmtCheckersFor(S, isPreVisit), S,
+                     Eng, WasInlined);
+  llvm::TimeTraceScope TimeScope(
+      isPreVisit ? "CheckerManager::runCheckersForStmt (Pre)"
+                 : "CheckerManager::runCheckersForStmt (Post)");
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -200,6 +213,8 @@ namespace {
 
     void runChecker(CheckerManager::CheckObjCMessageFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
+      llvm::TimeTraceScope TimeScope(
+          checkerScopeName("ObjCMsg", checkFn.Checker));
       bool IsPreVisit;
 
       switch (Kind) {
@@ -230,6 +245,7 @@ void CheckerManager::runCheckersForObjCMessage(ObjCMessageVisitKind visitKind,
                                                bool WasInlined) {
   const auto &checkers = getObjCMessageCheckers(visitKind);
   CheckObjCMessageContext C(visitKind, checkers, msg, Eng, WasInlined);
+  llvm::TimeTraceScope TimeScope("CheckerManager::runCheckersForObjCMessage");
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -270,7 +286,8 @@ namespace {
 
     void runChecker(CheckerManager::CheckCallFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
-      const ProgramPoint &L = Call.getProgramPoint(IsPreVisit,checkFn.Checker);
+      llvm::TimeTraceScope TimeScope(checkerScopeName("Call", checkFn.Checker));
+      const ProgramPoint &L = Call.getProgramPoint(IsPreVisit, checkFn.Checker);
       CheckerContext C(Bldr, Eng, Pred, L, WasInlined);
 
       checkFn(*Call.cloneWithState(Pred->getState()), C);
@@ -287,9 +304,11 @@ void CheckerManager::runCheckersForCallEvent(bool isPreVisit,
                                              ExprEngine &Eng,
                                              bool WasInlined) {
   CheckCallContext C(isPreVisit,
-                     isPreVisit ? PreCallCheckers
-                                : PostCallCheckers,
-                     Call, Eng, WasInlined);
+                     isPreVisit ? PreCallCheckers : PostCallCheckers, Call, Eng,
+                     WasInlined);
+  llvm::TimeTraceScope TimeScope(
+      isPreVisit ? "CheckerManager::runCheckersForCallEvent (Pre)"
+                 : "CheckerManager::runCheckersForCallEvent (Post)");
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -317,8 +336,9 @@ namespace {
 
     void runChecker(CheckerManager::CheckLocationFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
-      ProgramPoint::Kind K =  IsLoad ? ProgramPoint::PreLoadKind :
-                                       ProgramPoint::PreStoreKind;
+      llvm::TimeTraceScope TimeScope(checkerScopeName("Loc", checkFn.Checker));
+      ProgramPoint::Kind K =
+          IsLoad ? ProgramPoint::PreLoadKind : ProgramPoint::PreStoreKind;
       const ProgramPoint &L =
         ProgramPoint::getProgramPoint(NodeEx, K,
                                       Pred->getLocationContext(),
@@ -338,8 +358,11 @@ void CheckerManager::runCheckersForLocation(ExplodedNodeSet &Dst,
                                             const Stmt *NodeEx,
                                             const Stmt *BoundEx,
                                             ExprEngine &Eng) {
-  CheckLocationContext C(LocationCheckers, location, isLoad, NodeEx,
-                         BoundEx, Eng);
+  CheckLocationContext C(LocationCheckers, location, isLoad, NodeEx, BoundEx,
+                         Eng);
+  llvm::TimeTraceScope TimeScope(
+      isLoad ? "CheckerManager::runCheckersForLocation (Load)"
+             : "CheckerManager::runCheckersForLocation (Store)");
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -365,6 +388,7 @@ namespace {
 
     void runChecker(CheckerManager::CheckBindFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
+      llvm::TimeTraceScope TimeScope(checkerScopeName("Bind", checkFn.Checker));
       const ProgramPoint &L = PP.withTag(checkFn.Checker);
       CheckerContext C(Bldr, Eng, Pred, L);
 
@@ -372,6 +396,14 @@ namespace {
     }
   };
 
+  llvm::TimeTraceMetadata getTimeTraceBindMetadata(SVal val) {
+    assert(llvm::timeTraceProfilerEnabled());
+    std::string name;
+    llvm::raw_string_ostream OS(name);
+    val.dumpToStream(OS);
+    return llvm::TimeTraceMetadata{OS.str(), ""};
+  }
+
 } // namespace
 
 /// Run checkers for binding of a value to a location.
@@ -381,6 +413,9 @@ void CheckerManager::runCheckersForBind(ExplodedNodeSet &Dst,
                                         const Stmt *S, ExprEngine &Eng,
                                         const ProgramPoint &PP) {
   CheckBindContext C(BindCheckers, location, val, S, Eng, PP);
+  llvm::TimeTraceScope TimeScope{
+      "CheckerManager::runCheckersForBind",
+      [&val]() { return getTimeTraceBindMetadata(val); }};
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -409,6 +444,7 @@ struct CheckBeginFunctionContext {
 
   void runChecker(CheckerManager::CheckBeginFunctionFunc checkFn,
                   NodeBuilder &Bldr, ExplodedNode *Pred) {
+    llvm::TimeTraceScope TimeScope(checkerScopeName("Begin", checkFn.Checker));
     const ProgramPoint &L = PP.withTag(checkFn.Checker);
     CheckerContext C(Bldr, Eng, Pred, L);
 
@@ -425,6 +461,7 @@ void CheckerManager::runCheckersForBeginFunction(ExplodedNodeSet &Dst,
   ExplodedNodeSet Src;
   Src.insert(Pred);
   CheckBeginFunctionContext C(BeginFunctionCheckers, Eng, L);
+  llvm::TimeTrace...
[truncated]

@llvmbot
Copy link
Member

llvmbot commented Feb 3, 2025

@llvm/pr-subscribers-clang-static-analyzer-1

Author: Arseniy Zaostrovnykh (necto)

Changes

Specifically, add a scope for

  • each work-list step,
  • each entry point,
  • each checker run within a step, and
  • bug-suppression phase at the end of the analysis of an entry-point.

These scopes add no perceptible run-time overhead when time-tracing is disabled. You can enable it and generate a time trace using the -ftime-trace=file.json option.

See also the RFC.

--
CPP-6065


Patch is 30.80 KiB, truncated to 20.00 KiB below, full version: https://github.com/llvm/llvm-project/pull/125508.diff

11 Files Affected:

  • (modified) clang/docs/analyzer/developer-docs.rst (+1)
  • (added) clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst (+38)
  • (added) clang/docs/analyzer/images/speedscope.png ()
  • (modified) clang/include/clang/Analysis/ProgramPoint.h (+3)
  • (modified) clang/lib/Analysis/ProgramPoint.cpp (+121)
  • (modified) clang/lib/StaticAnalyzer/Core/BugReporter.cpp (+35-2)
  • (modified) clang/lib/StaticAnalyzer/Core/BugSuppression.cpp (+27)
  • (modified) clang/lib/StaticAnalyzer/Core/CheckerManager.cpp (+63-14)
  • (modified) clang/lib/StaticAnalyzer/Core/CoreEngine.cpp (+35-2)
  • (modified) clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp (+40-8)
  • (added) clang/test/Analysis/ftime-trace.cpp (+56)
diff --git a/clang/docs/analyzer/developer-docs.rst b/clang/docs/analyzer/developer-docs.rst
index 1b8133ffa8920b..60c0e71ad847c7 100644
--- a/clang/docs/analyzer/developer-docs.rst
+++ b/clang/docs/analyzer/developer-docs.rst
@@ -11,3 +11,4 @@ Contents:
    developer-docs/InitializerLists
    developer-docs/nullability
    developer-docs/RegionStore
+   developer-docs/PerformanceInvestigation
diff --git a/clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst b/clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst
new file mode 100644
index 00000000000000..78ba804dd64c8b
--- /dev/null
+++ b/clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst
@@ -0,0 +1,38 @@
+=========================
+Performance Investigation
+=========================
+
+Multiple factors contribute to the time it takes to analyze a file with Clang Static Analyzer.
+A translation unit contains multiple entry points, each of which take multiple steps to analyze.
+
+You can add the ``-ftime-trace=file.json`` option to break down the analysis time into individual entry points and steps within each entry point.
+You can explore the generated JSON file in a Chromium browser using the ``chrome://tracing`` URL,
+or using `speedscope <https://speedscope.app>`_.
+Once you narrow down to specific analysis steps you are interested in, you can more effectively employ heavier profilers,
+such as `Perf <https://perfwiki.github.io/main/>`_ and `Callgrind <https://valgrind.org/docs/manual/cl-manual.html>`_.
+
+Each analysis step has a time scope in the trace, corresponds to processing of an exploded node, and is designated with a ``ProgramPoint``.
+If the ``ProgramPoint`` is associated with a location, you can see it on the scope metadata label.
+
+.. image:: ../images/speedscope.png
+
+On the screenshot above, under the first time ruler is the birds-eye view of the entire trace that spans a little over 8 seconds.
+Under the second ruler (focused on the 4.27s time point) you can see a narrowed-down portion.
+The second box (of light-green color) that spans entire screen (and actually extends beyond it) corresponds to the analysis of ``get_global_options()`` entry point that is defined in the "options.cc" file on line 303646
+(the line number is huge because the file was preprocessed).
+Below it, you can find multiple sub-scopes each corresponding to processing of a single exploded node.
+
+1. A ``PostStmt`` for some statement on line 2337. This step spent most of the time in the ``ExprEngine::removeDead`` call.
+2. (Selected): another ``PostStmt`` for a return statement
+3. A ``BlockEdge``, and so on...
+
+In addition to the ``-ftime-trace`` option, you can use ``-ftime-trace-granularity`` to fine-tune the time trace.
+
+- ``-ftime-trace-granularity=NN`` dumps only time scopes that are longer than NN microseconds.
+- ``-ftime-trace-verbose`` enables some additional dumps in the frontend related to template instantiations.
+  At the moment, it has no effect on the traces from the static analyzer.
+
+Note: Both Chrome-tracing and speedscope tools might struggle with time traces above 100 MB in size.
+Luckily, in most cases the default max-steps boundary of 225 000 produces the traces of approximately that size
+for a single entry point.
+You should use ``-analyze-function=get_global_options`` together with ``-ftime-trace`` to narrow down analysis to a specific entry point.
diff --git a/clang/docs/analyzer/images/speedscope.png b/clang/docs/analyzer/images/speedscope.png
new file mode 100644
index 00000000000000..54b64041468cbe
Binary files /dev/null and b/clang/docs/analyzer/images/speedscope.png differ
diff --git a/clang/include/clang/Analysis/ProgramPoint.h b/clang/include/clang/Analysis/ProgramPoint.h
index b9339570e1ae70..f4b044333b8a8c 100644
--- a/clang/include/clang/Analysis/ProgramPoint.h
+++ b/clang/include/clang/Analysis/ProgramPoint.h
@@ -85,6 +85,9 @@ class ProgramPoint {
               LoopExitKind,
               EpsilonKind};
 
+  static const char *kindToStr(Kind K);
+  std::optional<SourceLocation> getSourceLocation() const;
+
 private:
   const void *Data1;
   llvm::PointerIntPair<const void *, 2, unsigned> Data2;
diff --git a/clang/lib/Analysis/ProgramPoint.cpp b/clang/lib/Analysis/ProgramPoint.cpp
index 7945c5c2fc27fc..faf6b71cf18c9e 100644
--- a/clang/lib/Analysis/ProgramPoint.cpp
+++ b/clang/lib/Analysis/ProgramPoint.cpp
@@ -49,6 +49,127 @@ LLVM_DUMP_METHOD void ProgramPoint::dump() const {
   return printJson(llvm::errs());
 }
 
+const char *ProgramPoint::kindToStr(Kind K) {
+  switch (K) {
+  case BlockEdgeKind:
+    return "BlockEdge";
+  case BlockEntranceKind:
+    return "BlockEntrance";
+  case BlockExitKind:
+    return "BlockExit";
+  case PreStmtKind:
+    return "PreStmt";
+  case PreStmtPurgeDeadSymbolsKind:
+    return "PreStmtPurgeDeadSymbols";
+  case PostStmtPurgeDeadSymbolsKind:
+    return "PostStmtPurgeDeadSymbols";
+  case PostStmtKind:
+    return "PostStmt";
+  case PreLoadKind:
+    return "PreLoad";
+  case PostLoadKind:
+    return "PostLoad";
+  case PreStoreKind:
+    return "PreStore";
+  case PostStoreKind:
+    return "PostStore";
+  case PostConditionKind:
+    return "PostCondition";
+  case PostLValueKind:
+    return "PostLValue";
+  case PostAllocatorCallKind:
+    return "PostAllocatorCall";
+  case PostInitializerKind:
+    return "PostInitializer";
+  case CallEnterKind:
+    return "CallEnter";
+  case CallExitBeginKind:
+    return "CallExitBegin";
+  case CallExitEndKind:
+    return "CallExitEnd";
+  case FunctionExitKind:
+    return "FunctionExit";
+  case PreImplicitCallKind:
+    return "PreImplicitCall";
+  case PostImplicitCallKind:
+    return "PostImplicitCall";
+  case LoopExitKind:
+    return "LoopExit";
+  case EpsilonKind:
+    return "Epsilon";
+  }
+  llvm_unreachable("Unknown ProgramPoint kind");
+}
+
+std::optional<SourceLocation> ProgramPoint::getSourceLocation() const {
+  switch (getKind()) {
+  case BlockEdgeKind:
+    // return castAs<BlockEdge>().getSrc()->getTerminatorStmt()->getBeginLoc();
+    return std::nullopt;
+  case BlockEntranceKind:
+    // return castAs<BlockEntrance>().getBlock()->getLabel()->getBeginLoc();
+    return std::nullopt;
+  case BlockExitKind:
+    // return
+    // castAs<BlockExit>().getBlock()->getTerminatorStmt()->getBeginLoc();
+    return std::nullopt;
+  case PreStmtKind:
+    [[fallthrough]];
+  case PreStmtPurgeDeadSymbolsKind:
+    [[fallthrough]];
+  case PostStmtPurgeDeadSymbolsKind:
+    [[fallthrough]];
+  case PostStmtKind:
+    [[fallthrough]];
+  case PreLoadKind:
+    [[fallthrough]];
+  case PostLoadKind:
+    [[fallthrough]];
+  case PreStoreKind:
+    [[fallthrough]];
+  case PostStoreKind:
+    [[fallthrough]];
+  case PostConditionKind:
+    [[fallthrough]];
+  case PostLValueKind:
+    [[fallthrough]];
+  case PostAllocatorCallKind:
+    if (const Stmt *S = castAs<StmtPoint>().getStmt())
+      return S->getBeginLoc();
+    return std::nullopt;
+  case PostInitializerKind:
+    if (const auto *Init = castAs<PostInitializer>().getInitializer())
+      return Init->getSourceLocation();
+    return std::nullopt;
+  case CallEnterKind:
+    if (const Stmt *S = castAs<CallEnter>().getCallExpr())
+      return S->getBeginLoc();
+    return std::nullopt;
+  case CallExitBeginKind:
+    if (const Stmt *S = castAs<CallExitBegin>().getReturnStmt())
+      return S->getBeginLoc();
+    return std::nullopt;
+  case CallExitEndKind:
+    return std::nullopt;
+  case FunctionExitKind:
+    if (const auto *B = castAs<FunctionExitPoint>().getBlock();
+        B && B->getTerminatorStmt())
+      return B->getTerminatorStmt()->getBeginLoc();
+    return std::nullopt;
+  case PreImplicitCallKind:
+    return castAs<ImplicitCallPoint>().getLocation();
+  case PostImplicitCallKind:
+    return castAs<ImplicitCallPoint>().getLocation();
+  case LoopExitKind:
+    if (const Stmt *S = castAs<LoopExit>().getLoopStmt())
+      return S->getBeginLoc();
+    return std::nullopt;
+  case EpsilonKind:
+    return std::nullopt;
+  }
+  llvm_unreachable("Unknown ProgramPoint kind");
+}
+
 void ProgramPoint::printJson(llvm::raw_ostream &Out, const char *NL) const {
   const ASTContext &Context =
       getLocationContext()->getAnalysisDeclContext()->getASTContext();
diff --git a/clang/lib/StaticAnalyzer/Core/BugReporter.cpp b/clang/lib/StaticAnalyzer/Core/BugReporter.cpp
index 2904eab0097dc8..525496baf9ce8e 100644
--- a/clang/lib/StaticAnalyzer/Core/BugReporter.cpp
+++ b/clang/lib/StaticAnalyzer/Core/BugReporter.cpp
@@ -62,6 +62,7 @@
 #include "llvm/Support/Compiler.h"
 #include "llvm/Support/ErrorHandling.h"
 #include "llvm/Support/MemoryBuffer.h"
+#include "llvm/Support/TimeProfiler.h"
 #include "llvm/Support/raw_ostream.h"
 #include <algorithm>
 #include <cassert>
@@ -287,6 +288,35 @@ class PathDiagnosticBuilder : public BugReporterContext {
   const PathSensitiveBugReport *getBugReport() const { return R; }
 };
 
+std::string timeTraceName(const BugReportEquivClass &EQ) {
+  if (!llvm::timeTraceProfilerEnabled()) {
+    return "";
+  }
+  const auto &bugReports = EQ.getReports();
+  if (bugReports.empty())
+    return "Empty Equivalence Class";
+  const BugReport *R = bugReports.front().get();
+  const auto &BT = R->getBugType();
+  return ("Flushing EQC " + BT.getDescription()).str();
+}
+
+llvm::TimeTraceMetadata timeTraceMetadata(const BugReportEquivClass &EQ) {
+  // Must be called only when constructing non-bogus TimeTraceScope
+  assert(llvm::timeTraceProfilerEnabled());
+
+  const auto &bugReports = EQ.getReports();
+  if (bugReports.empty())
+    return {};
+  const BugReport *R = bugReports.front().get();
+  const auto &BT = R->getBugType();
+  auto Loc = R->getLocation().asLocation();
+  std::string File = "";
+  if (const auto *Entry = Loc.getFileEntry())
+    File = Entry->tryGetRealPathName().str();
+  return {BT.getCheckerName().str(), File,
+          static_cast<int>(Loc.getLineNumber())};
+}
+
 } // namespace
 
 //===----------------------------------------------------------------------===//
@@ -2892,6 +2922,7 @@ std::optional<PathDiagnosticBuilder> PathDiagnosticBuilder::findValidReport(
 
     if (R->isValid()) {
       if (Reporter.getAnalyzerOptions().ShouldCrosscheckWithZ3) {
+        llvm::TimeTraceScope TCS{"Crosscheck with Z3"};
         // If crosscheck is enabled, remove all visitors, add the refutation
         // visitor and check again
         R->clearVisitors();
@@ -3119,8 +3150,10 @@ BugReport *PathSensitiveBugReporter::findReportInEquivalenceClass(
   return exampleReport;
 }
 
-void BugReporter::FlushReport(BugReportEquivClass& EQ) {
-  SmallVector<BugReport*, 10> bugReports;
+void BugReporter::FlushReport(BugReportEquivClass &EQ) {
+  llvm::TimeTraceScope TCS{timeTraceName(EQ),
+                           [&EQ]() { return timeTraceMetadata(EQ); }};
+  SmallVector<BugReport *, 10> bugReports;
   BugReport *report = findReportInEquivalenceClass(EQ, bugReports);
   if (!report)
     return;
diff --git a/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp b/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp
index 05c99c4a844e9e..0cefdb1e50cec8 100644
--- a/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp
+++ b/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp
@@ -9,6 +9,8 @@
 #include "clang/StaticAnalyzer/Core/BugReporter/BugSuppression.h"
 #include "clang/AST/DynamicRecursiveASTVisitor.h"
 #include "clang/StaticAnalyzer/Core/BugReporter/BugReporter.h"
+#include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/TimeProfiler.h"
 
 using namespace clang;
 using namespace ento;
@@ -119,6 +121,28 @@ class CacheInitializer : public DynamicRecursiveASTVisitor {
   Ranges &Result;
 };
 
+std::string timeScopeName(const Decl *DeclWithIssue) {
+  if (!llvm::timeTraceProfilerEnabled())
+    return "";
+  return llvm::formatv(
+             "BugSuppression::isSuppressed init suppressions cache for {0}",
+             DeclWithIssue->getDeclKindName())
+      .str();
+}
+
+llvm::TimeTraceMetadata getDeclTimeTraceMetadata(const Decl *DeclWithIssue) {
+  assert(DeclWithIssue);
+  assert(llvm::timeTraceProfilerEnabled());
+  std::string name = "<noname>";
+  if (auto ND = dyn_cast<NamedDecl>(DeclWithIssue)) {
+    name = ND->getNameAsString();
+  }
+  const auto &SM = DeclWithIssue->getASTContext().getSourceManager();
+  auto line = SM.getPresumedLineNumber(DeclWithIssue->getBeginLoc());
+  auto fname = SM.getFilename(DeclWithIssue->getBeginLoc());
+  return llvm::TimeTraceMetadata{name, fname.str(), static_cast<int>(line)};
+}
+
 } // end anonymous namespace
 
 // TODO: Introduce stable IDs for checkers and check for those here
@@ -177,6 +201,9 @@ bool BugSuppression::isSuppressed(const PathDiagnosticLocation &Location,
       std::make_pair(DeclWithIssue, CachedRanges{}));
   Ranges &SuppressionRanges = InsertionResult.first->second;
   if (InsertionResult.second) {
+    llvm::TimeTraceScope TimeScope(
+        timeScopeName(DeclWithIssue),
+        [DeclWithIssue]() { return getDeclTimeTraceMetadata(DeclWithIssue); });
     // We haven't checked this declaration for suppressions yet!
     CacheInitializer::initialize(DeclWithIssue, SuppressionRanges);
   }
diff --git a/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp b/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp
index 9f7a0fcc2edb36..421c8f81af5fe9 100644
--- a/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp
+++ b/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp
@@ -27,6 +27,7 @@
 #include "llvm/Support/Casting.h"
 #include "llvm/Support/ErrorHandling.h"
 #include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/TimeProfiler.h"
 #include <cassert>
 #include <optional>
 #include <vector>
@@ -134,6 +135,14 @@ static void expandGraphWithCheckers(CHECK_CTX checkCtx,
 
 namespace {
 
+std::string checkerScopeName(StringRef name, const CheckerBase *checker) {
+  if (!llvm::timeTraceProfilerEnabled())
+    return "";
+  std::string checkerName =
+      checker ? checker->getCheckerName().getName().str() : "<unknown>";
+  return (name + ":" + checkerName).str();
+}
+
   struct CheckStmtContext {
     using CheckersTy = SmallVectorImpl<CheckerManager::CheckStmtFunc>;
 
@@ -153,6 +162,7 @@ namespace {
 
     void runChecker(CheckerManager::CheckStmtFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
+      llvm::TimeTraceScope TimeScope(checkerScopeName("Stmt", checkFn.Checker));
       // FIXME: Remove respondsToCallback from CheckerContext;
       ProgramPoint::Kind K =  IsPreVisit ? ProgramPoint::PreStmtKind :
                                            ProgramPoint::PostStmtKind;
@@ -172,8 +182,11 @@ void CheckerManager::runCheckersForStmt(bool isPreVisit,
                                         const Stmt *S,
                                         ExprEngine &Eng,
                                         bool WasInlined) {
-  CheckStmtContext C(isPreVisit, getCachedStmtCheckersFor(S, isPreVisit),
-                     S, Eng, WasInlined);
+  CheckStmtContext C(isPreVisit, getCachedStmtCheckersFor(S, isPreVisit), S,
+                     Eng, WasInlined);
+  llvm::TimeTraceScope TimeScope(
+      isPreVisit ? "CheckerManager::runCheckersForStmt (Pre)"
+                 : "CheckerManager::runCheckersForStmt (Post)");
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -200,6 +213,8 @@ namespace {
 
     void runChecker(CheckerManager::CheckObjCMessageFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
+      llvm::TimeTraceScope TimeScope(
+          checkerScopeName("ObjCMsg", checkFn.Checker));
       bool IsPreVisit;
 
       switch (Kind) {
@@ -230,6 +245,7 @@ void CheckerManager::runCheckersForObjCMessage(ObjCMessageVisitKind visitKind,
                                                bool WasInlined) {
   const auto &checkers = getObjCMessageCheckers(visitKind);
   CheckObjCMessageContext C(visitKind, checkers, msg, Eng, WasInlined);
+  llvm::TimeTraceScope TimeScope("CheckerManager::runCheckersForObjCMessage");
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -270,7 +286,8 @@ namespace {
 
     void runChecker(CheckerManager::CheckCallFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
-      const ProgramPoint &L = Call.getProgramPoint(IsPreVisit,checkFn.Checker);
+      llvm::TimeTraceScope TimeScope(checkerScopeName("Call", checkFn.Checker));
+      const ProgramPoint &L = Call.getProgramPoint(IsPreVisit, checkFn.Checker);
       CheckerContext C(Bldr, Eng, Pred, L, WasInlined);
 
       checkFn(*Call.cloneWithState(Pred->getState()), C);
@@ -287,9 +304,11 @@ void CheckerManager::runCheckersForCallEvent(bool isPreVisit,
                                              ExprEngine &Eng,
                                              bool WasInlined) {
   CheckCallContext C(isPreVisit,
-                     isPreVisit ? PreCallCheckers
-                                : PostCallCheckers,
-                     Call, Eng, WasInlined);
+                     isPreVisit ? PreCallCheckers : PostCallCheckers, Call, Eng,
+                     WasInlined);
+  llvm::TimeTraceScope TimeScope(
+      isPreVisit ? "CheckerManager::runCheckersForCallEvent (Pre)"
+                 : "CheckerManager::runCheckersForCallEvent (Post)");
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -317,8 +336,9 @@ namespace {
 
     void runChecker(CheckerManager::CheckLocationFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
-      ProgramPoint::Kind K =  IsLoad ? ProgramPoint::PreLoadKind :
-                                       ProgramPoint::PreStoreKind;
+      llvm::TimeTraceScope TimeScope(checkerScopeName("Loc", checkFn.Checker));
+      ProgramPoint::Kind K =
+          IsLoad ? ProgramPoint::PreLoadKind : ProgramPoint::PreStoreKind;
       const ProgramPoint &L =
         ProgramPoint::getProgramPoint(NodeEx, K,
                                       Pred->getLocationContext(),
@@ -338,8 +358,11 @@ void CheckerManager::runCheckersForLocation(ExplodedNodeSet &Dst,
                                             const Stmt *NodeEx,
                                             const Stmt *BoundEx,
                                             ExprEngine &Eng) {
-  CheckLocationContext C(LocationCheckers, location, isLoad, NodeEx,
-                         BoundEx, Eng);
+  CheckLocationContext C(LocationCheckers, location, isLoad, NodeEx, BoundEx,
+                         Eng);
+  llvm::TimeTraceScope TimeScope(
+      isLoad ? "CheckerManager::runCheckersForLocation (Load)"
+             : "CheckerManager::runCheckersForLocation (Store)");
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -365,6 +388,7 @@ namespace {
 
     void runChecker(CheckerManager::CheckBindFunc checkFn,
                     NodeBuilder &Bldr, ExplodedNode *Pred) {
+      llvm::TimeTraceScope TimeScope(checkerScopeName("Bind", checkFn.Checker));
       const ProgramPoint &L = PP.withTag(checkFn.Checker);
       CheckerContext C(Bldr, Eng, Pred, L);
 
@@ -372,6 +396,14 @@ namespace {
     }
   };
 
+  llvm::TimeTraceMetadata getTimeTraceBindMetadata(SVal val) {
+    assert(llvm::timeTraceProfilerEnabled());
+    std::string name;
+    llvm::raw_string_ostream OS(name);
+    val.dumpToStream(OS);
+    return llvm::TimeTraceMetadata{OS.str(), ""};
+  }
+
 } // namespace
 
 /// Run checkers for binding of a value to a location.
@@ -381,6 +413,9 @@ void CheckerManager::runCheckersForBind(ExplodedNodeSet &Dst,
                                         const Stmt *S, ExprEngine &Eng,
                                         const ProgramPoint &PP) {
   CheckBindContext C(BindCheckers, location, val, S, Eng, PP);
+  llvm::TimeTraceScope TimeScope{
+      "CheckerManager::runCheckersForBind",
+      [&val]() { return getTimeTraceBindMetadata(val); }};
   expandGraphWithCheckers(C, Dst, Src);
 }
 
@@ -409,6 +444,7 @@ struct CheckBeginFunctionContext {
 
   void runChecker(CheckerManager::CheckBeginFunctionFunc checkFn,
                   NodeBuilder &Bldr, ExplodedNode *Pred) {
+    llvm::TimeTraceScope TimeScope(checkerScopeName("Begin", checkFn.Checker));
     const ProgramPoint &L = PP.withTag(checkFn.Checker);
     CheckerContext C(Bldr, Eng, Pred, L);
 
@@ -425,6 +461,7 @@ void CheckerManager::runCheckersForBeginFunction(ExplodedNodeSet &Dst,
   ExplodedNodeSet Src;
   Src.insert(Pred);
   CheckBeginFunctionContext C(BeginFunctionCheckers, Eng, L);
+  llvm::TimeTraceScope TimeScope(...
[truncated]

Copy link

github-actions bot commented Feb 3, 2025

✅ With the latest revision this PR passed the C/C++ code formatter.

@firewave
Copy link

firewave commented Feb 3, 2025

Does this also work when CSA is called through clang-tidy? The analyzer profiling data in missing in the --enable-check-profile output - see #73673?

Copy link
Collaborator

@Xazax-hun Xazax-hun left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I haven't finished reviewing yet but some nits inline.

@necto
Copy link
Contributor Author

necto commented Feb 4, 2025

Does this also work when CSA is called through clang-tidy? The analyzer profiling data in missing in the --enable-check-profile output - see #73673?

As far as I know, it does not work out of the box with clang-tidy. Time tracing works only if you setup a profiler singleton instance with llvm::timeTraceProfilerInitialize, and it is invoked from the clang driver (clang/tools/driver/cc1_main.cpp) and some other non-clang tools, but not from clang-tidy. It should be relatively easy to add, but I don't want to extend the scope of this PR.

Copy link
Collaborator

@Xazax-hun Xazax-hun left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Some nits inline for style and removing allocations. Overall looks good for me.

@firewave
Copy link

firewave commented Feb 4, 2025

It should be relatively easy to add, but I don't want to extend the scope of this PR.

Thanks for the explanation. Yes, please don't extend the scope of the change.

Copy link
Collaborator

@Xazax-hun Xazax-hun left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are some lowercase variable names still, but otherwise it still looks good to me. Feel free to commit after those are fixed.

Copy link
Contributor

@balazs-benics-sonarsource balazs-benics-sonarsource left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I had a look at the PR, and it looks awesome.
Could you please update the attached speedscope image?
It looks like it's out of sync with the implementation, for example if you look at the "Loc PostStmt { ... stuff here ...}" , it appears to include the ProgramPoint dump, and according to your implementation it should only have "Loc ". Am I right?

@necto
Copy link
Contributor Author

necto commented Feb 5, 2025

I had a look at the PR, and it looks awesome. Could you please update the attached speedscope image? It looks like it's out of sync with the implementation, for example if you look at the "Loc PostStmt { ... stuff here ...}" , it appears to include the ProgramPoint dump, and according to your implementation it should only have "Loc ". Am I right?

speedscope puts the "details" onto the scope labels in addition to their name, unlike chrome-tracing that only displays the name, so that's the up-to-date display

@necto
Copy link
Contributor Author

necto commented Feb 5, 2025

I had a look at the PR, and it looks awesome. Could you please update the attached speedscope image? It looks like it's out of sync with the implementation, for example if you look at the "Loc PostStmt { ... stuff here ...}" , it appears to include the ProgramPoint dump, and according to your implementation it should only have "Loc ". Am I right?

speedscope puts the "details" onto the scope labels in addition to their name, unlike chrome-tracing that only displays the name, so that's the up-to-date display

@steakhal, As agreed out-of-band, I removed the potentially unbounded ProgramPoint dumps from the trace, and replaced them with just the statement kind for StmtKind program points. I've updated the doc accordingly, please take another look.

Copy link
Contributor

@balazs-benics-sonarsource balazs-benics-sonarsource left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks even better now. Thanks.
I found one final nit remaining.

@balazs-benics-sonarsource
Copy link
Contributor

LGTM, I'll merge this PR once the premerge checks are green. Should be ready in a couple of hours. Thanks for the PR again!

@steakhal steakhal merged commit c1d5be8 into llvm:main Feb 5, 2025
9 checks passed
@necto necto deleted the az/ftime-trace branch February 5, 2025 16:22
@steakhal
Copy link
Contributor

steakhal commented Feb 6, 2025

FYI others had issues with this commit, fixed by #126039.

Icohedron pushed a commit to Icohedron/llvm-project that referenced this pull request Feb 11, 2025
…125508)

Specifically, add a scope for 
- each work-list step,
- each entry point,
- each checker run within a step, and
- bug-suppression phase at the end of the analysis of an entry-point.

These scopes add no perceptible run-time overhead when time-tracing is
disabled. You can enable it and generate a time trace using the
`-ftime-trace=file.json` option.

See also the RFC:
https://discourse.llvm.org/t/analyzer-rfc-ftime-trace-time-scopes-for-steps-and-entry-points/84343

--
CPP-6065
steakhal added a commit to steakhal/llvm-project that referenced this pull request Feb 22, 2025
llvm-sync bot pushed a commit to arm/arm-toolchain that referenced this pull request Feb 24, 2025
joaosaffran pushed a commit to joaosaffran/llvm-project that referenced this pull request Feb 27, 2025
YutongZhuu pushed a commit to YutongZhuu/llvm-project that referenced this pull request Mar 8, 2025
YutongZhuu pushed a commit to YutongZhuu/llvm-project that referenced this pull request Mar 8, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
clang:analysis clang:static analyzer clang Clang issues not falling into any other category
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants