[analyzer][WIP] Print time taken to analyze checker callbacks

[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 print the time that a specific checker callback takes while getting analyzed.

This patch currently handles ASTDecl.

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

Running checker callbacks on: function : 0.0 ms
ANALYZE (Syntax): test.c function : 1.8 ms
Running checker callbacks on: function1 : 0.0 ms
ANALYZE (Syntax): test.c function1 : 0.1 ms
ANALYZE (Path,  Inline_Regular): test.c function1 : 1.0 ms
ANALYZE (Path,  Inline_Regular): test.c function : 0.1 ms

clang/include/clang/Analysis/AnalysisDeclContext.h

template <typename T> T *getAnalysis() {
     if (!data)
       data = T::create(*this);
     return static_cast<T *>(data.get());
   }
 
   /// \returns Whether the root namespace of \p D is the \c std C++ namespace.
   static bool isInStdNamespace(const Decl *D);
 
-  static std::string getFunctionName(const Decl *D);
+  static std::string getFunctionOrDeclName(const Decl *D);
 
 private:
   std::unique_ptr<ManagedAnalysis> &getAnalysisImpl(const void *tag);
 
   LocationContextManager &getLocationContextManager();
 };
 
 /// It wraps the AnalysisDeclContext to represent both the call stack with

clang/lib/Analysis/AnalysisDeclContext.cpp

while (const DeclContext *Parent = ND->getParent()) {
     if (!isa<NamespaceDecl>(Parent))
       break;
     ND = cast<NamespaceDecl>(Parent);
   }
 
   return ND->isStdNamespace();
 }
 
-std::string AnalysisDeclContext::getFunctionName(const Decl *D) {
+std::string AnalysisDeclContext::getFunctionOrDeclName(const Decl *D) {
   std::string Str;
   llvm::raw_string_ostream OS(Str);
   const ASTContext &Ctx = D->getASTContext();
 
   if (const FunctionDecl *FD = dyn_cast<FunctionDecl>(D)) {
     OS << FD->getQualifiedNameAsString();
 
     // In C++, there are overloads.
if (const auto *OID = dyn_cast<ObjCImplementationDecl>(DC)) {
       } else {
         OS << OC->getIdentifier()->getNameStart() << '('
            << OC->getIdentifier()->getNameStart() << ')';
       }
     } else if (const auto *OCD = dyn_cast<ObjCCategoryImplDecl>(DC)) {
       OS << OCD->getClassInterface()->getName() << '(' << OCD->getName() << ')';
     }
     OS << ' ' << OMD->getSelector().getAsString() << ']';
+  } else if (const auto *ND = dyn_cast<NamedDecl>(D)) {
+    OS << ND->getQualifiedNameAsString();
   }
 
   return OS.str();
 }
 
 LocationContextManager &AnalysisDeclContext::getLocationContextManager() {
   assert(
       ADCMgr &&
void LocationContext::dumpStack(raw_ostream &Out) const {
 
   unsigned Frame = 0;
   for (const LocationContext *LCtx = this; LCtx; LCtx = LCtx->getParent()) {
     switch (LCtx->getKind()) {
     case StackFrame:
       Out << "\t#" << Frame << ' ';
       ++Frame;
       if (const auto *D = dyn_cast<NamedDecl>(LCtx->getDecl()))
-        Out << "Calling " << AnalysisDeclContext::getFunctionName(D);
+        Out << "Calling " << AnalysisDeclContext::getFunctionOrDeclName(D);
       else
         Out << "Calling anonymous code";
       if (const Stmt *S = cast<StackFrameContext>(LCtx)->getCallSite()) {
         Out << " at line ";
         printLocation(Out, SM, S->getBeginLoc());
       }
       break;
     case Block:

clang/lib/StaticAnalyzer/Frontend/AnalysisConsumer.cpp

#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 DisplayDeclTime(const Decl *D, llvm::TimeRecord &Time) {
+    if (!Opts->AnalyzerDisplayProgress) {
+      return;
+    }
+    llvm::errs() << "Running checker callbacks on: "
+                 << AnalysisDeclContext::getFunctionOrDeclName(D);
+    DisplayTime(Time);
+  }
+
   void DisplayTime(llvm::TimeRecord &Time) {
     if (!Opts->AnalyzerDisplayProgress) {
       return;
     }
     llvm::errs() << " : " << llvm::format("%1.1f", Time.getWallTime() * 1000)
                  << " ms\n";
   }
 
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);
+                   << AnalysisDeclContext::getFunctionOrDeclName(D);
     }
   }
 
   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)
+      llvm::TimeRecord CheckerStartTime;
+      if (SyntaxCheckTimer) {
+        CheckerStartTime = SyntaxCheckTimer->getTotalTime();
         SyntaxCheckTimer->startTimer();
+      }
       checkerMgr->runCheckersOnASTDecl(D, *Mgr, *RecVisitorBR);
-      if (SyntaxCheckTimer)
+      if (SyntaxCheckTimer) {
         SyntaxCheckTimer->stopTimer();
+        llvm::TimeRecord CheckerEndTime = SyntaxCheckTimer->getTotalTime();
+        CheckerEndTime -= CheckerStartTime;
+        DisplayDeclTime(D, CheckerEndTime);
+      }
     }
     return true;
   }
 
   bool VisitVarDecl(VarDecl *VD) {
     if (!Opts->IsNaiveCTUEnabled)
       return true;
 
#include "clang/StaticAnalyzer/Core/Analyses.def"
   }
 
   void AddCheckerRegistrationFn(std::function<void(CheckerRegistry&)> Fn) override {
     CheckerRegistrationFns.push_back(std::move(Fn));
   }
 
 private:
   void storeTopLevelDecls(DeclGroupRef DG);
-  std::string getFunctionName(const Decl *D);
+  std::string getFunctionOrDeclName(const Decl *D);
 
   /// Check if we should skip (not analyze) the given function.
   AnalysisMode getModeForDecl(Decl *D, AnalysisMode Mode);
   void runAnalysisOnTranslationUnit(ASTContext &C);
 
   /// Print \p S to stderr if \c Opts->AnalyzerDisplayProgress is set.
   void reportAnalyzerProgress(StringRef S);
 }; // namespace
void AnalysisConsumer::HandleTranslationUnit(ASTContext &C) {
   // side-effects in PathDiagnosticConsumer's destructor. This is required when
   // used with option -disable-free.
   Mgr.reset();
 }
 
 AnalysisConsumer::AnalysisMode
 AnalysisConsumer::getModeForDecl(Decl *D, AnalysisMode Mode) {
   if (!Opts->AnalyzeSpecificFunction.empty() &&
-      AnalysisDeclContext::getFunctionName(D) != Opts->AnalyzeSpecificFunction)
+      AnalysisDeclContext::getFunctionOrDeclName(D) != Opts->AnalyzeSpecificFunction)
     return AM_None;
 
   // Unless -analyze-all is specified, treat decls differently depending on
   // where they came from:
   // - Main source file: run both path-sensitive and non-path-sensitive checks.
   // - Header files: run non-path-sensitive checks only.
   // - System headers: don't run any checks.
   SourceManager &SM = Ctx->getSourceManager();

clang/test/Analysis/inlining/analysis-order.c

 // RUN: %clang_analyze_cc1 -analyzer-checker=core.builtin.NoReturnFunctions -analyzer-display-progress %s 2>&1 | FileCheck %s
 
 // Do not analyze test1() again because it was inlined
 void test1();
 
 void test2() {
   test1();
 }
 
 void test1() {
 }
 
-// CHECK: analysis-order.c test2
+// CHECK: Running checker callbacks on: test1 : {{[0-9]+\.[0-9]+}} ms
+// CHECK-NEXT: Running checker callbacks on: test2 : {{[0-9]+\.[0-9]+}} ms
+// CHECK-NEXT: analysis-order.c test2
+// CHECK-NEXT: Running checker callbacks on: test1 : {{[0-9]+\.[0-9]+}} ms
 // CHECK-NEXT: analysis-order.c test1
 // CHECK-NEXT: analysis-order.c test2