[analyzer] Print time taken to analyze each function

[RithikSharma]

Summary

This patch is a part of an attempt to obtain more timer data from the analyzer. In this patch, we try to use LLVM::TimeRecord to save time before starting the analysis and to print the time that a specific function takes while getting analyzed.

The timer data is printed along with the -analyzer-display-progress outputs.

ANALYZE (Syntax): test.c functionName : 0.4 ms 
ANALYZE (Path,  Inline_Regular): test.c functionName : 2.6 ms

[NoQ]

Yay! Did you figure out how to update the tests?

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

119–121

I don't think this problem requires "global mutable state"(tm). What prevents you from doing it with just local variables? I.e., something like:

DisplayFunction();
TimeRecord T1 = ExprEngineTimer->getTotalTime();
RunPathSensitiveChecks();
TimeRecord T2 = ExprEngineTimer->getTotalTime();
T2 -= T1;
PrintTime(T2);

652

Delaying DisplayFunction() until the analysis is finished is unfortunate because if something goes wrong during analysis (eg., a debugger breakpoint hits), we wouldn't have a fancy print for which function was analyzed. Can we print the function first but have another print later for the timer?

[steakhal]

Good to see some progress in this direction.

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

226–243

I think this is somewhat shorter.

TBH I don't know if the if guarding this block is strictly necessary. An assertion might be enough IDK.

Let me digress a bit if we are at this code.
It was always so annoying that this display progress printed *only* the function name.
On the other hand the -analyze-function expected not only the function name but the parameters as well for C++ code (I know it's for overload stuff but it's so inconvenient.) It's even worse because it matched in a verbatim manner, where it's whitespace sensitive.
I'm thinking of cleaning this up now.

652

+1

[RithikSharma]

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

119–121

This sounds great, I have updated the patch.

226–243

Thanks, this time I moved all the code in a function, to make it more easier.

652

Makes sense to me, thanks.

[NoQ]

Looks good except one possible bug.

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

192

I don't think we need an extra \n here. This would print an indefinite number of newlines every time -analyzer-stats is requested.

[RithikSharma]

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

192

Thanks, I've updated the patch.

[NoQ]

Code looks great now!

One last thing, can you also add a tiny test to this patch? We already have a tiny explicit test for -analyzer-display-progress itself test/Analysis/analyzer-display-progress.cpp. It keeps passing because FileCheck matches sub-strings rather than entire strings. So you could extend it to say something like

// CHECK: analyzer-display-progress.cpp f() : {{[0-9]+}}ms

[RithikSharma]

Thanks, it was essential. I have updated the patch.

[steakhal]

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

226–243

nvm it turns out that the opposite is true. Sorry for spamming here.
It seems like the display-progress prints the right string representation and the crash dump is flawed.
D105708 will resolve this inconvenience.

673–686

I think we could unconditionally record the execution time but conditionally display it.
It would make it possible to make the start time const and initialize it properly.
The time spent on the worklist algorithm should dominate this regardless.

As a general note, I prefer not to modify a variable unless I have a good reason to do so.
I think you could simply pass the ExprEngineEndTime - ExprEngineStartTime expression as the parameter for DisplayTime().

The same applies to the syntax timer as well.

[NoQ]

Thanks a lot! I think this patch is good to land as-is.

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

673–686

I think you could simply pass the ExprEngineEndTime - ExprEngineStartTime expression as the parameter for DisplayTime().

There's no overloaded operator-() on llvm::TimeRecord :(

I think there should be. Maybe we could make another patch about it.

clang/test/Analysis/analyzer-display-progress.cpp

23–30

ms! :)

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

public:
   std::unique_ptr<AnalysisManager> Mgr;
 
   /// Time the analyzes time of each translation unit.
   std::unique_ptr<llvm::TimerGroup> AnalyzerTimers;
   std::unique_ptr<llvm::Timer> SyntaxCheckTimer;
   std::unique_ptr<llvm::Timer> ExprEngineTimer;
   std::unique_ptr<llvm::Timer> BugReporterTimer;
 
   /// The information about analyzed functions shared throughout the
   /// translation unit.
   FunctionSummariesTy FunctionSummaries;
 
   AnalysisConsumer(CompilerInstance &CI, const std::string &outdir,
                    AnalyzerOptionsRef opts, ArrayRef<std::string> plugins,
                    CodeInjector *injector)
       : RecVisitorMode(0), RecVisitorBR(nullptr), Ctx(nullptr),
         PP(CI.getPreprocessor()), OutDir(outdir), Opts(std::move(opts)),
         Plugins(plugins), Injector(injector), CTU(CI),
         MacroExpansions(CI.getLangOpts()) {
     DigestAnalyzerOptions();
-    if (Opts->PrintStats || Opts->ShouldSerializeStats) {
+    if (Opts->AnalyzerDisplayProgress || Opts->PrintStats ||
+        Opts->ShouldSerializeStats) {
       AnalyzerTimers = std::make_unique<llvm::TimerGroup>(
           "analyzer", "Analyzer timers");
       SyntaxCheckTimer = std::make_unique<llvm::Timer>(
           "syntaxchecks", "Syntax-based analysis time", *AnalyzerTimers);
       ExprEngineTimer = std::make_unique<llvm::Timer>(
           "exprengine", "Path exploration time", *AnalyzerTimers);
       BugReporterTimer = std::make_unique<llvm::Timer>(
           "bugreporter", "Path-sensitive report post-processing time",
           *AnalyzerTimers);
+    }
+
+    if (Opts->PrintStats || Opts->ShouldSerializeStats) {
       llvm::EnableStatistics(/* PrintOnExit= */ false);
     }
 
     if (Opts->ShouldDisplayMacroExpansions)
       MacroExpansions.registerForPreprocessor(PP);
   }
 
   ~AnalysisConsumer() override {
#include "clang/StaticAnalyzer/Core/Analyses.def"
     default:
       llvm_unreachable("Unknown constraint manager.");
 #define ANALYSIS_CONSTRAINTS(NAME, CMDFLAG, DESC, CREATEFN)     \
       case NAME##Model: CreateConstraintMgr = CREATEFN; break;
 #include "clang/StaticAnalyzer/Core/Analyses.def"
     }
   }
 
+  void DisplayTime(llvm::TimeRecord &Time) {
+    if (!Opts->AnalyzerDisplayProgress) {
+      return;
+    }
+    llvm::errs() << " : " << llvm::format("%1.1f", Time.getWallTime() * 1000)
+                 << " ms\n";
+  }
+
   void DisplayFunction(const Decl *D, AnalysisMode Mode,
                        ExprEngine::InliningModes IMode) {
     if (!Opts->AnalyzerDisplayProgress)
       return;
 
     SourceManager &SM = Mgr->getASTContext().getSourceManager();
     PresumedLoc Loc = SM.getPresumedLoc(D->getLocation());
     if (Loc.isValid()) {
if (Loc.isValid()) {
           llvm::errs() << " Inline_Regular";
           break;
         }
         llvm::errs() << ")";
       } else
         assert(Mode == (AM_Syntax | AM_Path) && "Unexpected mode!");
 
       llvm::errs() << ": " << Loc.getFilename() << ' '
-                   << AnalysisDeclContext::getFunctionName(D) << '\n';
+                   << AnalysisDeclContext::getFunctionName(D);
     }
   }
 
   void Initialize(ASTContext &Context) override {
     Ctx = &Context;
     checkerMgr = std::make_unique<CheckerManager>(*Ctx, *Opts, PP, Plugins,
                                                   CheckerRegistrationFns);
 
     Mgr = std::make_unique<AnalysisManager>(*Ctx, PP, PathConsumers,
                                             CreateStoreMgr, CreateConstraintMgr,
                                             checkerMgr.get(), *Opts, Injector);
   }
 
   /// Store the top level decls in the set to be processed later on.
   /// (Doing this pre-processing avoids deserialization of data from PCH.)
   bool HandleTopLevelDecl(DeclGroupRef D) override;
   void HandleTopLevelDeclInObjCContainer(DeclGroupRef D) override;
 
   void HandleTranslationUnit(ASTContext &C) override;
 
   /// Determine which inlining mode should be used when this function is
   /// analyzed. This allows to redefine the default inlining policies when
   /// analyzing a given function.
   ExprEngine::InliningModes
     getInliningModeForFunction(const Decl *D, const SetOfConstDecls &Visited);
 
if (Mode == AM_None)
     return;
 
   // Clear the AnalysisManager of old AnalysisDeclContexts.
   Mgr->ClearContexts();
   // Ignore autosynthesized code.
   if (Mgr->getAnalysisDeclContext(D)->isBodyAutosynthesized())
     return;
 
-  DisplayFunction(D, Mode, IMode);
   CFG *DeclCFG = Mgr->getCFG(D);
   if (DeclCFG)
     MaxCFGSize.updateMax(DeclCFG->size());
 
+  DisplayFunction(D, Mode, IMode);
   BugReporter BR(*Mgr);
 
   if (Mode & AM_Syntax) {
-    if (SyntaxCheckTimer)
+    llvm::TimeRecord CheckerStartTime;
+    if (SyntaxCheckTimer) {
+      CheckerStartTime = SyntaxCheckTimer->getTotalTime();
       SyntaxCheckTimer->startTimer();
+    }
     checkerMgr->runCheckersOnASTBody(D, *Mgr, BR);
-    if (SyntaxCheckTimer)
+    if (SyntaxCheckTimer) {
       SyntaxCheckTimer->stopTimer();
+      llvm::TimeRecord CheckerEndTime = SyntaxCheckTimer->getTotalTime();
+      CheckerEndTime -= CheckerStartTime;
+      DisplayTime(CheckerEndTime);
+    }
   }
 
   BR.FlushReports();
 
   if ((Mode & AM_Path) && checkerMgr->hasPathSensitiveCheckers()) {
     RunPathSensitiveChecks(D, IMode, VisitedCallees);
     if (IMode != ExprEngine::Inline_Minimal)
       NumFunctionsAnalyzed++;
   }
 }
 
 //===----------------------------------------------------------------------===//
 // Path-sensitive checking.
 //===----------------------------------------------------------------------===//
 
 void AnalysisConsumer::RunPathSensitiveChecks(Decl *D,
                                               ExprEngine::InliningModes IMode,
                                               SetOfConstDecls *VisitedCallees) {
   // Construct the analysis engine.  First check if the CFG is valid.
   // FIXME: Inter-procedural analysis will need to handle invalid CFGs.
   if (!Mgr->getCFG(D))
     return;
 
   // See if the LiveVariables analysis scales.
   if (!Mgr->getAnalysisDeclContext(D)->getAnalysis<RelaxedLiveVariables>())
     return;
 
   ExprEngine Eng(CTU, *Mgr, VisitedCallees, &FunctionSummaries, IMode);
 
   // Execute the worklist algorithm.
-  if (ExprEngineTimer)
+  llvm::TimeRecord ExprEngineStartTime;
+  if (ExprEngineTimer) {
+    ExprEngineStartTime = ExprEngineTimer->getTotalTime();
     ExprEngineTimer->startTimer();
+  }
   Eng.ExecuteWorkList(Mgr->getAnalysisDeclContextManager().getStackFrame(D),
                       Mgr->options.MaxNodesPerTopLevelFunction);
-  if (ExprEngineTimer)
+  if (ExprEngineTimer) {
     ExprEngineTimer->stopTimer();
+    llvm::TimeRecord ExprEngineEndTime = ExprEngineTimer->getTotalTime();
+    ExprEngineEndTime -= ExprEngineStartTime;
+    DisplayTime(ExprEngineEndTime);
+  }
 
   if (!Mgr->options.DumpExplodedGraphTo.empty())
     Eng.DumpGraph(Mgr->options.TrimGraph, Mgr->options.DumpExplodedGraphTo);
 
   // Visualize the exploded graph.
   if (Mgr->options.visualizeExplodedGraphWithGraphViz)
     Eng.ViewGraph(Mgr->options.TrimGraph);
 
   // Display warnings.

clang/test/Analysis/analyzer-display-progress.cpp

 namespace ns {
   struct SomeStruct {
     void f(int) {}
     void f(float, ::SomeStruct) {}
     void f(float, SomeStruct) {}
   };
 }
 
-// CHECK: analyzer-display-progress.cpp f()
-// CHECK: analyzer-display-progress.cpp g()
-// CHECK: analyzer-display-progress.cpp h()
-// CHECK: analyzer-display-progress.cpp SomeStruct::f()
-// CHECK: analyzer-display-progress.cpp SomeOtherStruct::f()
-// CHECK: analyzer-display-progress.cpp ns::SomeStruct::f(int)
-// CHECK: analyzer-display-progress.cpp ns::SomeStruct::f(float, ::SomeStruct)
-// CHECK: analyzer-display-progress.cpp ns::SomeStruct::f(float, struct ns::SomeStruct)
+// CHECK: analyzer-display-progress.cpp f() : {{[0-9]+}}
+// CHECK: analyzer-display-progress.cpp g() : {{[0-9]+}}
+// CHECK: analyzer-display-progress.cpp h() : {{[0-9]+}}
+// CHECK: analyzer-display-progress.cpp SomeStruct::f() : {{[0-9]+}}
+// CHECK: analyzer-display-progress.cpp SomeOtherStruct::f() : {{[0-9]+}}
+// CHECK: analyzer-display-progress.cpp ns::SomeStruct::f(int) : {{[0-9]+}}
+// CHECK: analyzer-display-progress.cpp ns::SomeStruct::f(float, ::SomeStruct) : {{[0-9]+}}
+// CHECK: analyzer-display-progress.cpp ns::SomeStruct::f(float, struct ns::SomeStruct) : {{[0-9]+}}