[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);

716

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

221–238

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.

716

+1

[RithikSharma]

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

119–121

This sounds great, I have updated the patch.

221–238

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

716

Makes sense to me, thanks.

[NoQ]

Looks good except one possible bug.

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

195

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

195

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

221–238

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.

738–746

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

738–746

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 ↗

(On Diff #357525)

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;
 
+  /// Saves timer's last value
+  llvm::TimeRecord LastSyntaxTimerValue;
+  llvm::TimeRecord LastPathTimerValue;
+
   /// 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 {

 #define ANALYSIS_CONSTRAINTS(NAME, CMDFLAG, DESC, CREATEFN)     \
       case NAME##Model: CreateConstraintMgr = CREATEFN; break;
 #include "clang/StaticAnalyzer/Core/Analyses.def"
     }
   }
 
   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()) {
       llvm::errs() << "ANALYZE";
 
       if (Mode == AM_Syntax)
         llvm::errs() << " (Syntax)";
       else if (Mode == AM_Path) {
         llvm::errs() << " (Path, ";
         switch (IMode) {
         case ExprEngine::Inline_Minimal:
           llvm::errs() << " Inline_Minimal";
           break;
         case ExprEngine::Inline_Regular:
           llvm::errs() << " Inline_Regular";
           break;
         }
         llvm::errs() << ")";
       } else
         assert(Mode == (AM_Syntax | AM_Path) && "Unexpected mode!");
 
-      llvm::errs() << ": " << Loc.getFilename() << ' ' << getFunctionName(D)
-                   << '\n';
+      llvm::errs() << ": " << Loc.getFilename() << ' ' << getFunctionName(D);
+
+      if (Mode == AM_Syntax)
+        llvm::errs() << " : "
+                     << llvm::format(
+                            "%1.1f",
+                            (SyntaxCheckTimer->getTotalTime().getWallTime() -
+                             LastSyntaxTimerValue.getWallTime()) *
+                                1000)
+                     << " ms";
+      else if (Mode == AM_Path)
+        llvm::errs() << " : "
+                     << llvm::format(
+                            "%1.1f",
+                            (ExprEngineTimer->getTotalTime().getWallTime() -
+                             LastPathTimerValue.getWallTime()) *
+                                1000)
+                     << " ms";
+
+      llvm::errs() << " \n";
     }
   }
 
   void Initialize(ASTContext &Context) override {
     Ctx = &Context;
     checkerMgr = std::make_unique<CheckerManager>(*Ctx, *Opts, PP, Plugins,
                                                   CheckerRegistrationFns);
 
#include "clang/StaticAnalyzer/Core/Analyses.def"
 
   /// Visitors for the RecursiveASTVisitor.
   bool shouldWalkTypesOfTypeLocs() const { return false; }
 
   /// Handle callbacks for arbitrary Decls.
   bool VisitDecl(Decl *D) {
     AnalysisMode Mode = getModeForDecl(D, RecVisitorMode);
     if (Mode & AM_Syntax) {
-      if (SyntaxCheckTimer)
+      if (SyntaxCheckTimer) {
+        LastSyntaxTimerValue = SyntaxCheckTimer->getTotalTime();
         SyntaxCheckTimer->startTimer();
+      }
       checkerMgr->runCheckersOnASTDecl(D, *Mgr, *RecVisitorBR);
       if (SyntaxCheckTimer)
         SyntaxCheckTimer->stopTimer();
     }
     return true;
   }
 
   bool VisitVarDecl(VarDecl *VD) {
static bool isBisonFile(ASTContext &C) {
   if (Buffer.startswith("/* A Bison parser, made by"))
     return true;
   return false;
 }
 
 void AnalysisConsumer::runAnalysisOnTranslationUnit(ASTContext &C) {
   BugReporter BR(*Mgr);
   TranslationUnitDecl *TU = C.getTranslationUnitDecl();
-  if (SyntaxCheckTimer)
+  if (SyntaxCheckTimer){
+       LastSyntaxTimerValue = SyntaxCheckTimer->getTotalTime();
     SyntaxCheckTimer->startTimer();
+  }
   checkerMgr->runCheckersOnASTDecl(TU, *Mgr, BR);
   if (SyntaxCheckTimer)
     SyntaxCheckTimer->stopTimer();
 
   // Run the AST-only checks using the order in which functions are defined.
   // If inlining is not turned on, use the simplest function order for path
   // sensitive analyzes as well.
   RecVisitorMode = AM_Syntax;
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());
 
   BugReporter BR(*Mgr);
 
   if (Mode & AM_Syntax) {
-    if (SyntaxCheckTimer)
+    if (SyntaxCheckTimer){
+         LastSyntaxTimerValue = SyntaxCheckTimer->getTotalTime();
       SyntaxCheckTimer->startTimer();
+    }
     checkerMgr->runCheckersOnASTBody(D, *Mgr, BR);
     if (SyntaxCheckTimer)
       SyntaxCheckTimer->stopTimer();
   }
 
   BR.FlushReports();
 
   if ((Mode & AM_Path) && checkerMgr->hasPathSensitiveCheckers()) {
     RunPathSensitiveChecks(D, IMode, VisitedCallees);
     if (IMode != ExprEngine::Inline_Minimal)
       NumFunctionsAnalyzed++;
   }
+  DisplayFunction(D, Mode, IMode);
 }
 
 //===----------------------------------------------------------------------===//
 // 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)
+  if (ExprEngineTimer){
+       LastPathTimerValue = ExprEngineTimer->getTotalTime();
     ExprEngineTimer->startTimer();
+  }
   Eng.ExecuteWorkList(Mgr->getAnalysisDeclContextManager().getStackFrame(D),
                       Mgr->options.MaxNodesPerTopLevelFunction);
   if (ExprEngineTimer)
     ExprEngineTimer->stopTimer();
 
   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.