[clang] cad9b7f - [analyzer] Print time taken to analyze each function

[via cfe-commits]

Author: SharmaRithik
Date: 2021-07-13T04:52:47Z
New Revision: cad9b7f708e2b2d19d7890494980c5e427d6d4ea

URL: https://github.com/llvm/llvm-project/commit/cad9b7f708e2b2d19d7890494980c5e427d6d4ea
DIFF: https://github.com/llvm/llvm-project/commit/cad9b7f708e2b2d19d7890494980c5e427d6d4ea.diff

LOG: [analyzer] Print time taken to analyze each function
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
Authored By: RithikSharma
Reviewer: NoQ, xazax.hun, teemperor, vsavchenko
Reviewed By: NoQ
Differential Revision: https://reviews.llvm.org/D105565

Added: 
    

Modified: 
    clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp
    clang/test/Analysis/analyzer-display-progress.cpp

Removed: 
    


################################################################################
diff  --git a/clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp b/clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp
index 03b5c04f553f..31de49033ac2 100644
--- a/clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp
+++ b/clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp
@@ -128,7 +128,8 @@ class AnalysisConsumer : public AnalysisASTConsumer,
         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>(
@@ -138,6 +139,9 @@ class AnalysisConsumer : public AnalysisASTConsumer,
       BugReporterTimer = std::make_unique<llvm::Timer>(
           "bugreporter", "Path-sensitive report post-processing time",
           *AnalyzerTimers);
+    }
+
+    if (Opts->PrintStats || Opts->ShouldSerializeStats) {
       llvm::EnableStatistics(/* PrintOnExit= */ false);
     }
 
@@ -183,6 +187,14 @@ class AnalysisConsumer : public AnalysisASTConsumer,
     }
   }
 
+  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)
@@ -210,7 +222,7 @@ class AnalysisConsumer : public AnalysisASTConsumer,
         assert(Mode == (AM_Syntax | AM_Path) && "Unexpected mode!");
 
       llvm::errs() << ": " << Loc.getFilename() << ' '
-                   << AnalysisDeclContext::getFunctionName(D) << '\n';
+                   << AnalysisDeclContext::getFunctionName(D);
     }
   }
 
@@ -608,19 +620,26 @@ void AnalysisConsumer::HandleCode(Decl *D, AnalysisMode Mode,
   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();
@@ -651,12 +670,19 @@ void AnalysisConsumer::RunPathSensitiveChecks(Decl *D,
   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);

diff  --git a/clang/test/Analysis/analyzer-display-progress.cpp b/clang/test/Analysis/analyzer-display-progress.cpp
index b54044a0a361..6767b3770abf 100644
--- a/clang/test/Analysis/analyzer-display-progress.cpp
+++ b/clang/test/Analysis/analyzer-display-progress.cpp
@@ -20,11 +20,11 @@ namespace ns {
   };
 }
 
-// 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]+}}