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}} +} _______________________________________________ cfe-commits mailing list cfe-commits@lists.llvm.org https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
