[clang] c1d5be8 - [analyzer] Add time-trace scopes for high-level analyzer steps (#125508)
via cfe-commits
cfe-commits at lists.llvm.org
Wed Feb 5 08:22:22 PST 2025
Author: Arseniy Zaostrovnykh
Date: 2025-02-05T17:22:18+01:00
New Revision: c1d5be8f7fa24b95e652593f9a780005e6604920
URL: https://github.com/llvm/llvm-project/commit/c1d5be8f7fa24b95e652593f9a780005e6604920
DIFF: https://github.com/llvm/llvm-project/commit/c1d5be8f7fa24b95e652593f9a780005e6604920.diff
LOG: [analyzer] Add time-trace scopes for high-level analyzer steps (#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
Added:
clang/docs/analyzer/developer-docs/PerformanceInvestigation.rst
clang/docs/analyzer/images/speedscope.png
clang/test/Analysis/ftime-trace.cpp
Modified:
clang/docs/analyzer/developer-docs.rst
clang/include/clang/Analysis/ProgramPoint.h
clang/lib/Analysis/ProgramPoint.cpp
clang/lib/StaticAnalyzer/Core/BugReporter.cpp
clang/lib/StaticAnalyzer/Core/BugSuppression.cpp
clang/lib/StaticAnalyzer/Core/CheckerManager.cpp
clang/lib/StaticAnalyzer/Core/CoreEngine.cpp
clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp
Removed:
################################################################################
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..3ee6e117a84652
--- /dev/null
+++ b/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.
diff --git a/clang/docs/analyzer/images/speedscope.png b/clang/docs/analyzer/images/speedscope.png
new file mode 100644
index 00000000000000..767725d68f740b
Binary files /dev/null and b/clang/docs/analyzer/images/speedscope.png
diff er
diff --git a/clang/include/clang/Analysis/ProgramPoint.h b/clang/include/clang/Analysis/ProgramPoint.h
index b9339570e1ae70..1df1f1cb892e41 100644
--- a/clang/include/clang/Analysis/ProgramPoint.h
+++ b/clang/include/clang/Analysis/ProgramPoint.h
@@ -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;
diff --git a/clang/lib/Analysis/ProgramPoint.cpp b/clang/lib/Analysis/ProgramPoint.cpp
index 7945c5c2fc27fc..e508681410b0b4 100644
--- a/clang/lib/Analysis/ProgramPoint.cpp
+++ b/clang/lib/Analysis/ProgramPoint.cpp
@@ -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();
diff --git a/clang/lib/StaticAnalyzer/Core/BugReporter.cpp b/clang/lib/StaticAnalyzer/Core/BugReporter.cpp
index 2904eab0097dc8..4100812c4623e9 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,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)
diff --git a/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp b/clang/lib/StaticAnalyzer/Core/BugSuppression.cpp
index 05c99c4a844e9e..5b5f9df9cb0dce 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,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);
}
diff --git a/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp b/clang/lib/StaticAnalyzer/Core/CheckerManager.cpp
index 9f7a0fcc2edb36..53929d370e2fe2 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 "";
+ StringRef CheckerName =
+ Checker ? Checker->getCheckerName().getName() : "<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;
@@ -174,6 +184,9 @@ void CheckerManager::runCheckersForStmt(bool isPreVisit,
bool 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,6 +286,7 @@ namespace {
void runChecker(CheckerManager::CheckCallFunc checkFn,
NodeBuilder &Bldr, ExplodedNode *Pred) {
+ llvm::TimeTraceScope TimeScope(checkerScopeName("Call", checkFn.Checker));
const ProgramPoint &L = Call.getProgramPoint(IsPreVisit,checkFn.Checker);
CheckerContext C(Bldr, Eng, Pred, L, WasInlined);
@@ -290,6 +307,9 @@ void CheckerManager::runCheckersForCallEvent(bool isPreVisit,
isPreVisit ? PreCallCheckers
: PostCallCheckers,
Call, Eng, WasInlined);
+ llvm::TimeTraceScope TimeScope(
+ isPreVisit ? "CheckerManager::runCheckersForCallEvent (Pre)"
+ : "CheckerManager::runCheckersForCallEvent (Post)");
expandGraphWithCheckers(C, Dst, Src);
}
@@ -317,6 +337,7 @@ namespace {
void runChecker(CheckerManager::CheckLocationFunc checkFn,
NodeBuilder &Bldr, ExplodedNode *Pred) {
+ llvm::TimeTraceScope TimeScope(checkerScopeName("Loc", checkFn.Checker));
ProgramPoint::Kind K = IsLoad ? ProgramPoint::PreLoadKind :
ProgramPoint::PreStoreKind;
const ProgramPoint &L =
@@ -340,6 +361,9 @@ void CheckerManager::runCheckersForLocation(ExplodedNodeSet &Dst,
ExprEngine &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 +389,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 +397,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 +414,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 +445,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 +462,7 @@ void CheckerManager::runCheckersForBeginFunction(ExplodedNodeSet &Dst,
ExplodedNodeSet Src;
Src.insert(Pred);
CheckBeginFunctionContext C(BeginFunctionCheckers, Eng, L);
+ llvm::TimeTraceScope TimeScope("CheckerManager::runCheckersForBeginFunction");
expandGraphWithCheckers(C, Dst, Src);
}
@@ -444,6 +482,7 @@ void CheckerManager::runCheckersForEndFunction(NodeBuilderContext &BC,
const ProgramPoint &L =
FunctionExitPoint(RS, Pred->getLocationContext(), checkFn.Checker);
CheckerContext C(Bldr, Eng, Pred, L);
+ llvm::TimeTraceScope TimeScope(checkerScopeName("End", checkFn.Checker));
checkFn(RS, C);
}
}
@@ -466,6 +505,8 @@ namespace {
void runChecker(CheckerManager::CheckBranchConditionFunc checkFn,
NodeBuilder &Bldr, ExplodedNode *Pred) {
+ llvm::TimeTraceScope TimeScope(
+ checkerScopeName("BranchCond", checkFn.Checker));
ProgramPoint L = PostCondition(Condition, Pred->getLocationContext(),
checkFn.Checker);
CheckerContext C(Bldr, Eng, Pred, L);
@@ -483,6 +524,8 @@ void CheckerManager::runCheckersForBranchCondition(const Stmt *Condition,
ExplodedNodeSet Src;
Src.insert(Pred);
CheckBranchConditionContext C(BranchConditionCheckers, Condition, Eng);
+ llvm::TimeTraceScope TimeScope(
+ "CheckerManager::runCheckersForBranchCondition");
expandGraphWithCheckers(C, Dst, Src);
}
@@ -506,6 +549,8 @@ namespace {
void runChecker(CheckerManager::CheckNewAllocatorFunc checkFn,
NodeBuilder &Bldr, ExplodedNode *Pred) {
+ llvm::TimeTraceScope TimeScope(
+ checkerScopeName("Allocator", checkFn.Checker));
ProgramPoint L =
PostAllocatorCall(Call.getOriginExpr(), Pred->getLocationContext());
CheckerContext C(Bldr, Eng, Pred, L, WasInlined);
@@ -524,6 +569,7 @@ void CheckerManager::runCheckersForNewAllocator(const CXXAllocatorCall &Call,
ExplodedNodeSet Src;
Src.insert(Pred);
CheckNewAllocatorContext C(NewAllocatorCheckers, Call, WasInlined, Eng);
+ llvm::TimeTraceScope TimeScope("CheckerManager::runCheckersForNewAllocator");
expandGraphWithCheckers(C, Dst, Src);
}
@@ -555,6 +601,8 @@ namespace {
void runChecker(CheckerManager::CheckDeadSymbolsFunc checkFn,
NodeBuilder &Bldr, ExplodedNode *Pred) {
+ llvm::TimeTraceScope TimeScope(
+ checkerScopeName("DeadSymbols", checkFn.Checker));
const ProgramPoint &L = ProgramPoint::getProgramPoint(S, ProgarmPointKind,
Pred->getLocationContext(), checkFn.Checker);
CheckerContext C(Bldr, Eng, Pred, L);
@@ -576,6 +624,7 @@ void CheckerManager::runCheckersForDeadSymbols(ExplodedNodeSet &Dst,
ExprEngine &Eng,
ProgramPoint::Kind K) {
CheckDeadSymbolsContext C(DeadSymbolsCheckers, SymReaper, S, Eng, K);
+ llvm::TimeTraceScope TimeScope("CheckerManager::runCheckersForDeadSymbols");
expandGraphWithCheckers(C, Dst, Src);
}
diff --git a/clang/lib/StaticAnalyzer/Core/CoreEngine.cpp b/clang/lib/StaticAnalyzer/Core/CoreEngine.cpp
index 775a22e18c6199..bf1fd7c2356dc8 100644
--- a/clang/lib/StaticAnalyzer/Core/CoreEngine.cpp
+++ b/clang/lib/StaticAnalyzer/Core/CoreEngine.cpp
@@ -30,6 +30,8 @@
#include "llvm/ADT/Statistic.h"
#include "llvm/Support/Casting.h"
#include "llvm/Support/ErrorHandling.h"
+#include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/TimeProfiler.h"
#include <algorithm>
#include <cassert>
#include <memory>
@@ -179,8 +181,41 @@ bool CoreEngine::ExecuteWorkList(const LocationContext *L, unsigned MaxSteps,
return WList->hasWork();
}
-void CoreEngine::dispatchWorkItem(ExplodedNode* Pred, ProgramPoint Loc,
- const WorkListUnit& WU) {
+static std::string timeTraceScopeName(const ProgramPoint &Loc) {
+ if (llvm::timeTraceProfilerEnabled()) {
+ return llvm::formatv("Loc {0}",
+ ProgramPoint::getProgramPointKindName(Loc.getKind()))
+ .str();
+ }
+ return "";
+}
+
+static llvm::TimeTraceMetadata timeTraceMetadata(const ExplodedNode *Pred,
+ const ProgramPoint &Loc) {
+ // If time-trace profiler is not enabled, this function is never called.
+ assert(llvm::timeTraceProfilerEnabled());
+ std::string Detail = "";
+ if (const auto SP = Loc.getAs<StmtPoint>()) {
+ if (const Stmt *S = SP->getStmt())
+ Detail = S->getStmtClassName();
+ }
+ auto SLoc = Loc.getSourceLocation();
+ if (!SLoc)
+ return llvm::TimeTraceMetadata{Detail, ""};
+ const auto &SM = Pred->getLocationContext()
+ ->getAnalysisDeclContext()
+ ->getASTContext()
+ .getSourceManager();
+ auto Line = SM.getPresumedLineNumber(*SLoc);
+ auto Fname = SM.getFilename(*SLoc);
+ return llvm::TimeTraceMetadata{Detail, Fname.str(), static_cast<int>(Line)};
+}
+
+void CoreEngine::dispatchWorkItem(ExplodedNode *Pred, ProgramPoint Loc,
+ const WorkListUnit &WU) {
+ llvm::TimeTraceScope tcs{timeTraceScopeName(Loc), [Loc, Pred]() {
+ return timeTraceMetadata(Pred, Loc);
+ }};
// Dispatch on the location type.
switch (Loc.getKind()) {
case ProgramPoint::BlockEdgeKind:
diff --git a/clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp b/clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp
index 91c9b085f68292..189d7d6bede8e6 100644
--- a/clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp
+++ b/clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp
@@ -39,6 +39,7 @@
#include "llvm/Support/FileSystem.h"
#include "llvm/Support/Path.h"
#include "llvm/Support/Program.h"
+#include "llvm/Support/TimeProfiler.h"
#include "llvm/Support/Timer.h"
#include "llvm/Support/raw_ostream.h"
#include <memory>
@@ -358,9 +359,40 @@ class AnalysisConsumer : public AnalysisASTConsumer,
/// Print \p S to stderr if \c Opts.AnalyzerDisplayProgress is set.
void reportAnalyzerProgress(StringRef S);
-}; // namespace
-} // end anonymous namespace
+};
+std::string timeTraceScopeDeclName(StringRef FunName, const Decl *D) {
+ if (llvm::timeTraceProfilerEnabled()) {
+ if (const NamedDecl *ND = dyn_cast<NamedDecl>(D))
+ return (FunName + " " + ND->getQualifiedNameAsString()).str();
+ return (FunName + " <anonymous> ").str();
+ }
+ return "";
+}
+
+llvm::TimeTraceMetadata timeTraceScopeDeclMetadata(const Decl *D) {
+ // If time-trace profiler is not enabled, this function is never called.
+ assert(llvm::timeTraceProfilerEnabled());
+ if (const auto &Loc = D->getBeginLoc(); Loc.isValid()) {
+ const auto &SM = D->getASTContext().getSourceManager();
+ std::string DeclName = AnalysisDeclContext::getFunctionName(D);
+ return llvm::TimeTraceMetadata{
+ std::move(DeclName), SM.getFilename(Loc).str(),
+ static_cast<int>(SM.getExpansionLineNumber(Loc))};
+ }
+ return llvm::TimeTraceMetadata{"", ""};
+}
+
+void flushReports(llvm::Timer *BugReporterTimer, BugReporter &BR) {
+ llvm::TimeTraceScope TCS{"Flushing reports"};
+ // Display warnings.
+ if (BugReporterTimer)
+ BugReporterTimer->startTimer();
+ BR.FlushReports();
+ if (BugReporterTimer)
+ BugReporterTimer->stopTimer();
+}
+} // namespace
//===----------------------------------------------------------------------===//
// AnalysisConsumer implementation.
@@ -658,6 +690,8 @@ AnalysisConsumer::getModeForDecl(Decl *D, AnalysisMode Mode) {
void AnalysisConsumer::HandleCode(Decl *D, AnalysisMode Mode,
ExprEngine::InliningModes IMode,
SetOfConstDecls *VisitedCallees) {
+ llvm::TimeTraceScope TCS(timeTraceScopeDeclName("HandleCode", D),
+ [D]() { return timeTraceScopeDeclMetadata(D); });
if (!D->hasBody())
return;
Mode = getModeForDecl(D, Mode);
@@ -742,12 +776,7 @@ void AnalysisConsumer::RunPathSensitiveChecks(Decl *D,
if (Mgr->options.visualizeExplodedGraphWithGraphViz)
Eng.ViewGraph(Mgr->options.TrimGraph);
- // Display warnings.
- if (BugReporterTimer)
- BugReporterTimer->startTimer();
- Eng.getBugReporter().FlushReports();
- if (BugReporterTimer)
- BugReporterTimer->stopTimer();
+ flushReports(BugReporterTimer.get(), Eng.getBugReporter());
}
//===----------------------------------------------------------------------===//
diff --git a/clang/test/Analysis/ftime-trace.cpp b/clang/test/Analysis/ftime-trace.cpp
new file mode 100644
index 00000000000000..2c369a9bf781e2
--- /dev/null
+++ b/clang/test/Analysis/ftime-trace.cpp
@@ -0,0 +1,56 @@
+// RUN: %clang_analyze_cc1 -analyzer-checker=core %s -ftime-trace=%t.raw.json -ftime-trace-granularity=0 -verify
+// RUN: %python -c 'import json, sys; print(json.dumps(json.load(sys.stdin), indent=4))' < %t.raw.json > %t.formatted.json
+// RUN: FileCheck --input-file=%t.formatted.json --check-prefix=CHECK %s
+
+// The trace file is rather large, but it should contain at least the duration of the analysis of 'f':
+//
+// CHECK: "name": "HandleCode f",
+// CHECK-NEXT: "args": {
+// CHECK-NEXT: "detail": "f()",
+// CHECK-NEXT: "file": "{{.+}}ftime-trace.cpp",
+// CHECK-NEXT: "line": {{[0-9]+}}
+// CHECK-NEXT: }
+
+// If any reports are found, "flushing" their equivalence class (EQC) is a separate action:
+//
+// CHECK: "name": "Flushing EQC Division by zero",
+// CHECK-NEXT: "args": {
+// CHECK-NEXT: "detail": "core.DivideZero",
+// CHECK-NEXT: "file": "{{.+}}ftime-trace.cpp",
+// CHECK-NEXT: "line": {{[0-9]+}}
+// CHECK-NEXT: }
+
+// The trace also contains durations of each step, but they are so short that they are not reliably present
+// in each run. However, they are also aggregated into Total *, for example:
+//
+// CHECK: "name": "Total Loc PostStmt",
+// CHECK-NEXT: "args": {
+// CHECK-NEXT: "count": {{[0-9]+}},
+// CHECK-NEXT: "avg ms": {{[0-9]+}}
+// CHECK-NEXT: }
+
+// Additionally, the trace lists checker hook points (again, relying on totals here):
+//
+// CHECK: "name": "Total CheckerManager::runCheckersForStmt (Pre)",
+// CHECK-NEXT: "args": {
+// CHECK-NEXT: "count": {{[0-9]+}},
+// CHECK-NEXT: "avg ms": {{[0-9]+}}
+// CHECK-NEXT: }
+
+// Finally, each checker call back is also present:
+//
+// CHECK: "name": "Total Stmt:core.DivideZero",
+// CHECK-NEXT: "args": {
+// CHECK-NEXT: "count": {{[0-9]+}},
+// CHECK-NEXT: "avg ms": {{[0-9]+}}
+// CHECK-NEXT: }
+
+bool coin();
+int f() {
+ int x = 0;
+ int y = 0;
+ while (coin()) {
+ x = 1;
+ }
+ return x / y; // expected-warning{{Division by zero}}
+}
More information about the cfe-commits
mailing list