[analyzer] Add time-trace scopes for high-level analyzer steps (llvm#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

Author: necto

clang/docs/analyzer/developer-docs.rst

@@ -11,3 +11,4 @@ Contents:
    developer-docs/InitializerLists
    developer-docs/nullability
    developer-docs/RegionStore
+   developer-docs/PerformanceInvestigation

clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst

@@ -0,0 +1,47 @@
+=========================
+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.
+
+Here is an example of a time trace produced with
+
+.. code-block:: bash
+   :caption: Clang Static Analyzer invocation to generate a time trace of string.c analysis.
+
+   clang -cc1 -nostdsysteminc -analyze -analyzer-constraints=range \
+         -setup-static-analyzer -analyzer-checker=core,unix,alpha.unix.cstring,debug.ExprInspection \
+         -verify ./clang/test/Analysis/string.c \
+         -ftime-trace=trace.json -ftime-trace-granularity=1
+
+.. image:: ../images/speedscope.png
+
+On the speedscope screenshot above, under the first time ruler is the bird's-eye view of the entire trace that spans a little over 60 milliseconds.
+Under the second ruler (focused on the 18.09-18.13ms time point) you can see a narrowed-down portion.
+The second box ("HandleCode memset...") that spans entire screen (and actually extends beyond it) corresponds to the analysis of ``memset16_region_cast()`` entry point that is defined in the "string.c" test file on line 1627.
+Below it, you can find multiple sub-scopes each corresponding to processing of a single exploded node.
+
+- First: a ``PostStmt`` for some statement on line 1634. This scope has a selected subscope "CheckerManager::runCheckersForCallEvent (Pre)" that takes 5 microseconds.
+- Four other nodes, too small to be discernible at this zoom level
+- Last on this screenshot: another ``PostStmt`` for a statement on line 1635.
+
+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 can use ``-analyze-function=get_global_options`` together with ``-ftime-trace`` to narrow down analysis to a specific entry point.

clang/docs/analyzer/images/speedscope.png

@@ -85,6 +85,9 @@ class ProgramPoint {
               LoopExitKind,
               EpsilonKind};
 
+  static StringRef getProgramPointKindName(Kind K);
+  std::optional<SourceLocation> getSourceLocation() const;
+
 private:
   const void *Data1;
   llvm::PointerIntPair<const void *, 2, unsigned> Data2;

clang/include/clang/Analysis/ProgramPoint.h

@@ -49,6 +49,121 @@ LLVM_DUMP_METHOD void ProgramPoint::dump() const {
   return printJson(llvm::errs());
 }
 
+StringRef ProgramPoint::getProgramPointKindName(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:
+    // If needed, the source and or destination beginning can be used to get
+    // source location.
+    return std::nullopt;
+  case BlockEntranceKind:
+    // If needed, first statement of the block can be used.
+    return std::nullopt;
+  case BlockExitKind:
+    if (const auto *B = castAs<BlockExit>().getBlock()) {
+      if (const auto *T = B->getTerminatorStmt()) {
+        return T->getBeginLoc();
+      }
+    }
+    return std::nullopt;
+  case PreStmtKind:
+  case PreStmtPurgeDeadSymbolsKind:
+  case PostStmtPurgeDeadSymbolsKind:
+  case PostStmtKind:
+  case PreLoadKind:
+  case PostLoadKind:
+  case PreStoreKind:
+  case PostStoreKind:
+  case PostConditionKind:
+  case PostLValueKind:
+  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();

clang/lib/Analysis/ProgramPoint.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,34 @@ 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(), std::move(File),
+          static_cast<int>(Loc.getLineNumber())};
+}
+
 } // namespace
 
 //===----------------------------------------------------------------------===//
@@ -2892,6 +2921,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,7 +3149,9 @@ BugReport *PathSensitiveBugReporter::findReportInEquivalenceClass(
   return exampleReport;
 }
 
-void BugReporter::FlushReport(BugReportEquivClass& EQ) {
+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)

clang/lib/StaticAnalyzer/Core/BugReporter.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,29 @@ 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 (const 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{std::move(Name), Fname.str(),
+                                 static_cast<int>(Line)};
+}
+
 } // end anonymous namespace
 
 // TODO: Introduce stable IDs for checkers and check for those here
@@ -177,6 +202,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);
   }