[ASTMatchers] Don't garble the profiling output when multiple TU's are processed

[lebedev.ri]

Summary

D5911 added support for profiling clang-tidy checks.

It works nice, the tabulated report generated by clang-tidy -enable-check-profile is readable.
Unfortunately, it gets complicated with more than just one source file.

You could run clang-tidy on each file, then parse the profiles,
combine (sum) based on the Name column, and re-display.
Given that the profiles are display friendly, this is messy. (or is there a tool i've missed?)

Or, you could run clang-tidy only once, on all the sources at at once.
This obviously does not scale well. But one would think at least
it would sidestep the problem of combining the separate reports.

One would think. No, it does not. The profiling info is displayed,
only once at the end of clang-tidy run, but the info is garbage.
It only contains some portion of the data. I suspect it only contains the last TU.

This is because MatchASTVisitor is kinda smart, it contains it's own local
llvm::StringMap<llvm::TimeRecord> TimeByBucket;, which is used,
and at the end, MatchASTVisitor::~MatchASTVisitor() "propagates"
the collected data to the specified profiling info storage.
But it overrides it, not appends/combines...

[lebedev.ri]

Ping?

[alexfh]

From a user's perspective I'd probably prefer a different behavior of checks profiling with multiple translation units: per-file table after each file and an aggregate table at the end. An independent improvement could be to support TSV/CSV output and/or dumping to a file to spare the user from parsing the tables out of the stdout/stderr.

[lebedev.ri]

Thank you for looking at this.

In D45931#1083184, @alexfh wrote:

From a user's perspective I'd probably prefer a different behavior of checks profiling with multiple translation units: per-file table after each file and an aggregate table at the end.

Is this a review note, or a general observation?

I'm sure it could be done, i'm just not too sure how useful it would be, since it seems no one before now even noticed that timing with multiple TU's was 'broken'.

An independent improvement could be to support TSV/CSV output and/or dumping to a file to spare the user from parsing the tables out of the stdout/stderr.

Yes, and a script to merge those CSV's, would be nice.

[lebedev.ri]

In D45931#1083192, @lebedev.ri wrote:

Thank you for looking at this.

In D45931#1083184, @alexfh wrote:

From a user's perspective I'd probably prefer a different behavior of checks profiling with multiple translation units: per-file table after each file and an aggregate table at the end.

Is this a review note, or a general observation?

I'm sure it could be done, i'm just not too sure how useful it would be, since it seems no one before now even noticed that timing with multiple TU's was 'broken'.

Hi @alexfh. Do i need to make those changes or not?
I'd really prefer to have such kind of high-level feedback the sooner the better, to avoid wasting everyone's time.

An independent improvement could be to support TSV/CSV output and/or dumping to a file to spare the user from parsing the tables out of the stdout/stderr.

Yes, and a script to merge those CSV's, would be nice.

[alexfh]

In D45931#1084503, @lebedev.ri wrote:

In D45931#1083192, @lebedev.ri wrote:

Thank you for looking at this.

In D45931#1083184, @alexfh wrote:

From a user's perspective I'd probably prefer a different behavior of checks profiling with multiple translation units: per-file table after each file and an aggregate table at the end.

Is this a review note, or a general observation?

Why not both? ;)

An independent improvement could be to support TSV/CSV output and/or dumping to a file to spare the user from parsing the tables out of the stdout/stderr.

Yes, and a script to merge those CSV's, would be nice.

I'd probably go with a set of features enough for various use cases:
0. don't add any profile merging logic to clang-tidy

1. dump profile after each TU to the screen in the current tabulated format
2. add a flag to specify a file name prefix to dump profile output for each file as CSV
3. (optional) add a script to merge profiles from CSV files and dump as CSV or tabulated (without a script this could be done in a spreadsheet)

WDYT?

[lebedev.ri]

In D45931#1086665, @alexfh wrote:

In D45931#1084503, @lebedev.ri wrote:

In D45931#1083192, @lebedev.ri wrote:

Thank you for looking at this.

In D45931#1083184, @alexfh wrote:

From a user's perspective I'd probably prefer a different behavior of checks profiling with multiple translation units: per-file table after each file and an aggregate table at the end.

Is this a review note, or a general observation?

Why not both? ;)

Review latency, finite time amount, you name it :)

An independent improvement could be to support TSV/CSV output and/or dumping to a file to spare the user from parsing the tables out of the stdout/stderr.

Yes, and a script to merge those CSV's, would be nice.

I'd probably go with a set of features enough for various use cases:
0. don't add any profile merging logic to clang-tidy

1. dump profile after each TU to the screen in the current tabulated format
2. add a flag to specify a file name prefix to dump profile output for each file as CSV
3. (optional) add a script to merge profiles from CSV files and dump as CSV or tabulated (without a script this could be done in a spreadsheet)

WDYT?

[lebedev.ri]

In D45931#1086665, @alexfh wrote:

In D45931#1084503, @lebedev.ri wrote:

In D45931#1083192, @lebedev.ri wrote:

Thank you for looking at this.

In D45931#1083184, @alexfh wrote:

From a user's perspective I'd probably prefer a different behavior of checks profiling with multiple translation units: per-file table after each file and an aggregate table at the end.

Is this a review note, or a general observation?

Why not both? ;)

BTW, that did not answer the question:

In D45931#1084503, @lebedev.ri wrote:

In D45931#1083192, @lebedev.ri wrote:

Thank you for looking at this.

In D45931#1083184, @alexfh wrote:

From a user's perspective I'd probably prefer a different behavior of checks profiling with multiple translation units: per-file table after each file and an aggregate table at the end.

Is this a review note, or a general observation?

I'm sure it could be done, i'm just not too sure how useful it would be, since it seems no one before now even noticed that timing with multiple TU's was 'broken'.

Hi @alexfh. Do i need to make those changes or not?
I'd really prefer to have such kind of high-level feedback the sooner the better, to avoid wasting everyone's time.

[alexfh]

In D45931#1087007, @lebedev.ri wrote:

In D45931#1086665, @alexfh wrote:

In D45931#1084503, @lebedev.ri wrote:

In D45931#1083192, @lebedev.ri wrote:

Thank you for looking at this.

In D45931#1083184, @alexfh wrote:

From a user's perspective I'd probably prefer a different behavior of checks profiling with multiple translation units: per-file table after each file and an aggregate table at the end.

Is this a review note, or a general observation?

Why not both? ;)

BTW, that did not answer the question:

I'm sure it could be done, i'm just not too sure how useful it would be, since it seems no one before now even noticed that timing with multiple TU's was 'broken'.

I think, I noticed incorrect handling of profiling with multiple TUs at some point and switched to running clang-tidy multiple times. The solution I proposed (most importantly, point 1) would be the most convenient one for me at that time:

I'd probably go with a set of features enough for various use cases:

0. don't add any profile merging logic to clang-tidy

1. dump profile after each TU to the screen in the current tabulated format
2. add a flag to specify a file name prefix to dump profile output for each file as CSV
3. (optional) add a script to merge profiles from CSV files and dump as CSV or tabulated (without a script this could be done in a spreadsheet)

Are any other questions still open?

lib/ASTMatchers/ASTMatchFinder.cpp

 };
 
 // Controls the outermost traversal of the AST and allows to match multiple
 // matchers.
 class MatchASTVisitor : public RecursiveASTVisitor<MatchASTVisitor>,
                         public ASTMatchFinder {
 public:
   MatchASTVisitor(const MatchFinder::MatchersByType *Matchers,
-                  const MatchFinder::MatchFinderOptions &Options)
-      : Matchers(Matchers), Options(Options), ActiveASTContext(nullptr) {}
-
-  ~MatchASTVisitor() override {
-    if (Options.CheckProfiling) {
-      Options.CheckProfiling->Records = std::move(TimeByBucket);
-    }
+                  MatchFinder::MatchFinderOptions &Options)
+      : Matchers(Matchers), ActiveASTContext(nullptr) {
+    if (Options.CheckProfiling.hasValue())
+      TimeByBucket = &(Options.CheckProfiling->Records);
   }
 
   void onStartOfTranslationUnit() {
-    const bool EnableCheckProfiling = Options.CheckProfiling.hasValue();
     TimeBucketRegion Timer;
     for (MatchCallback *MC : Matchers->AllCallbacks) {
-      if (EnableCheckProfiling)
-        Timer.setBucket(&TimeByBucket[MC->getID()]);
+      if (TimeByBucket)
+        Timer.setBucket(&(*TimeByBucket)[MC->getID()]);
       MC->onStartOfTranslationUnit();
     }
   }
 
   void onEndOfTranslationUnit() {
-    const bool EnableCheckProfiling = Options.CheckProfiling.hasValue();
     TimeBucketRegion Timer;
     for (MatchCallback *MC : Matchers->AllCallbacks) {
-      if (EnableCheckProfiling)
-        Timer.setBucket(&TimeByBucket[MC->getID()]);
+      if (TimeByBucket)
+        Timer.setBucket(&(*TimeByBucket)[MC->getID()]);
       MC->onEndOfTranslationUnit();
     }
   }
 
   void set_active_ast_context(ASTContext *NewActiveASTContext) {
     ActiveASTContext = NewActiveASTContext;
   }
 
private:
     llvm::TimeRecord *Bucket;
   };
 
   /// \brief Runs all the \p Matchers on \p Node.
   ///
   /// Used by \c matchDispatch() below.
   template <typename T, typename MC>
   void matchWithoutFilter(const T &Node, const MC &Matchers) {
-    const bool EnableCheckProfiling = Options.CheckProfiling.hasValue();
     TimeBucketRegion Timer;
     for (const auto &MP : Matchers) {
-      if (EnableCheckProfiling)
-        Timer.setBucket(&TimeByBucket[MP.second->getID()]);
+      if (TimeByBucket)
+        Timer.setBucket(&(*TimeByBucket)[MP.second->getID()]);
       BoundNodesTreeBuilder Builder;
       if (MP.first.matches(Node, this, &Builder)) {
         MatchVisitor Visitor(ActiveASTContext, MP.second);
         Builder.visitMatches(&Visitor);
       }
     }
   }
 
   void matchWithFilter(const ast_type_traits::DynTypedNode &DynNode) {
     auto Kind = DynNode.getNodeKind();
     auto it = MatcherFiltersMap.find(Kind);
     const auto &Filter =
         it != MatcherFiltersMap.end() ? it->second : getFilterForKind(Kind);
 
     if (Filter.empty())
       return;
 
-    const bool EnableCheckProfiling = Options.CheckProfiling.hasValue();
     TimeBucketRegion Timer;
     auto &Matchers = this->Matchers->DeclOrStmt;
     for (unsigned short I : Filter) {
       auto &MP = Matchers[I];
-      if (EnableCheckProfiling)
-        Timer.setBucket(&TimeByBucket[MP.second->getID()]);
+      if (TimeByBucket)
+        Timer.setBucket(&(*TimeByBucket)[MP.second->getID()]);
       BoundNodesTreeBuilder Builder;
       if (MP.first.matchesNoKindCheck(DynNode, this, &Builder)) {
         MatchVisitor Visitor(ActiveASTContext, MP.second);
         Builder.visitMatches(&Visitor);
       }
     }
   }
 
for (const TypedefNameDecl *Alias : Aliases->second) {
       }
     }
     return false;
   }
 
   /// \brief Bucket to record map.
   ///
   /// Used to get the appropriate bucket for each matcher.
-  llvm::StringMap<llvm::TimeRecord> TimeByBucket;
+  llvm::StringMap<llvm::TimeRecord> *TimeByBucket = nullptr;
 
   const MatchFinder::MatchersByType *Matchers;
 
   /// \brief Filtered list of matcher indices for each matcher kind.
   ///
   /// \c Decl and \c Stmt toplevel matchers usually apply to a specific node
   /// kind (and derived kinds) so it is a waste to try every matcher on every
   /// node.
   /// We precalculate a list of matchers that pass the toplevel restrict check.
   /// This also allows us to skip the restrict check at matching time. See
   /// use \c matchesNoKindCheck() above.
   llvm::DenseMap<ast_type_traits::ASTNodeKind, std::vector<unsigned short>>
       MatcherFiltersMap;
 
-  const MatchFinder::MatchFinderOptions &Options;
   ASTContext *ActiveASTContext;
 
   // Maps a canonical type to its TypedefDecls.
   llvm::DenseMap<const Type*, std::set<const TypedefNameDecl*> > TypeAliases;
 
   // Maps (matcher, node) -> the match result for memoization.
   typedef std::map<MatchKey, MemoizedMatchResult> MemoizationMap;
   MemoizationMap ResultCache;

unittests/ASTMatchers/ASTMatchersInternalTest.cpp

TEST(MatchFinder, CheckProfiling) {
   std::unique_ptr<FrontendActionFactory> Factory(
       newFrontendActionFactory(&Finder));
   ASSERT_TRUE(tooling::runToolOnCode(Factory->create(), "int x;"));
 
   EXPECT_EQ(1u, Records.size());
   EXPECT_EQ("MyID", Records.begin()->getKey());
 }
 
+TEST(MatchFinder, CheckProfilingTwoTU) {
+  llvm::StringMap<llvm::TimeRecord> Records;
+
+  MatchFinder::MatchFinderOptions Options0;
+  Options0.CheckProfiling.emplace(Records);
+  MatchFinder Finder0(std::move(Options0));
+
+  struct NamedCallback0 : public MatchFinder::MatchCallback {
+    void run(const MatchFinder::MatchResult &Result) override {}
+    StringRef getID() const override { return "MyID0"; }
+  } Callback0;
+  Finder0.addMatcher(decl(), &Callback0);
+  std::unique_ptr<FrontendActionFactory> Factory0(
+      newFrontendActionFactory(&Finder0));
+
+  MatchFinder::MatchFinderOptions Options1;
+  Options1.CheckProfiling.emplace(Records); // **before** using the first one.
+  MatchFinder Finder1(std::move(Options1));
+
+  struct NamedCallback1 : public MatchFinder::MatchCallback {
+    void run(const MatchFinder::MatchResult &Result) override {}
+    StringRef getID() const override { return "MyID1"; }
+  } Callback1;
+  Finder1.addMatcher(decl(), &Callback1);
+  std::unique_ptr<FrontendActionFactory> Factory1(
+      newFrontendActionFactory(&Finder1));
+
+  ASSERT_TRUE(tooling::runToolOnCode(Factory0->create(), "int x;"));
+
+  EXPECT_EQ(1u, Records.size());
+  EXPECT_EQ("MyID0", Records.begin()->getKey());
+  EXPECT_NE(Records.find("MyID0"), Records.end());
+
+  ASSERT_TRUE(tooling::runToolOnCode(Factory1->create(), "int x;"));
+
+  EXPECT_EQ(2u, Records.size());
+  EXPECT_NE(Records.find("MyID0"), Records.end());
+  EXPECT_NE(Records.find("MyID1"), Records.end());
+}
+
 class VerifyStartOfTranslationUnit : public MatchFinder::MatchCallback {
 public:
   VerifyStartOfTranslationUnit() : Called(false) {}
   void run(const MatchFinder::MatchResult &Result) override {
     EXPECT_TRUE(Called);
   }
   void onStartOfTranslationUnit() override { Called = true; }
   bool Called;