llvmbot wrote:
<!--LLVM PR SUMMARY COMMENT--> @llvm/pr-subscribers-clang-analysis @llvm/pr-subscribers-clang Author: Arseniy Zaostrovnykh (necto) <details> <summary>Changes</summary> 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 --- 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 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] `````````` </details> https://github.com/llvm/llvm-project/pull/125508 _______________________________________________ cfe-commits mailing list cfe-commits@lists.llvm.org https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
