[TimePasses] allow -time-passes reporting into a custom stream

TimePassesHandler object (implementation of time-passes for new pass manager)
gains ability to report into a stream customizable per-instance (per pipeline).

Intended use is to specify separate time-passes output stream per each compilation,
setting up TimePasses member of StandardInstrumentation during PassBuilder setup.
That allows to get independent non-overlapping pass-times reports for parallel
independent compilations (in JIT-like setups).

By default it still puts timing reports into the info-output-file stream
(created by CreateInfoOutputFile every time report is requested).

Unit-test added for non-default case, and it also allowed to discover that print() does not work
as declared - it did not reset the timers, leading to yet another report being printed into the default stream.
Fixed print() to actually reset timers according to what was declared in print's comments before.

Reviewed By: philip.pfaffe
Differential Revision: https://reviews.llvm.org/D59366

llvm-svn: 356305

include/llvm/IR/PassTimingInfo.h

@@ -26,6 +26,7 @@ namespace llvm {
 
 class Pass;
 class PassInstrumentationCallbacks;
+class raw_ostream;
 
 /// If -time-passes has been specified, report the timings immediately and then
 /// reset the timers to zero.
@@ -62,18 +63,18 @@ class TimePassesHandler {
   /// Stack of currently active timers.
   SmallVector<Timer *, 8> TimerStack;
 
+  /// Custom output stream to print timing information into.
+  /// By default (== nullptr) we emit time report into the stream controlled by
+  /// -info-output-file.
+  raw_ostream *OutStream = nullptr;
+
   bool Enabled;
 
 public:
   TimePassesHandler(bool Enabled = TimePassesIsEnabled);
 
   /// Destructor handles the print action if it has not been handled before.
-  ~TimePassesHandler() {
-    // First destroying the timers from TimingData, which deploys all their
-    // collected data into the TG time group member, which later prints itself
-    // when being destroyed.
-    TimingData.clear();
-  }
+  ~TimePassesHandler() { print(); }
 
   /// Prints out timing information and then resets the timers.
   void print();
@@ -84,6 +85,9 @@ public:
 
   void registerCallbacks(PassInstrumentationCallbacks &PIC);
 
+  /// Set a custom output stream for subsequent reporting.
+  void setOutStream(raw_ostream &OutStream);
+
 private:
   /// Dumps information for running/triggered timers, useful for debugging
   LLVM_DUMP_METHOD void dump() const;

include/llvm/Passes/StandardInstrumentations.h

@@ -63,6 +63,8 @@ public:
   StandardInstrumentations() = default;
 
   void registerCallbacks(PassInstrumentationCallbacks &PIC);
+
+  TimePassesHandler &getTimePasses() { return TimePasses; }
 };
 } // namespace llvm
 

lib/IR/PassTimingInfo.cpp

@@ -181,7 +181,16 @@ Timer &TimePassesHandler::getPassTimer(StringRef PassID) {
 TimePassesHandler::TimePassesHandler(bool Enabled)
     : TG("pass", "... Pass execution timing report ..."), Enabled(Enabled) {}
 
-void TimePassesHandler::print() { TG.print(*CreateInfoOutputFile()); }
+void TimePassesHandler::setOutStream(raw_ostream &Out) {
+  OutStream = &Out;
+}
+
+void TimePassesHandler::print() {
+  if (!Enabled)
+    return;
+  TG.print(OutStream ? *OutStream : *CreateInfoOutputFile());
+  TG.clear();
+}
 
 LLVM_DUMP_METHOD void TimePassesHandler::dump() const {
   dbgs() << "Dumping timers for " << getTypeName<TimePassesHandler>()

test/Other/time-passes.ll

@@ -4,6 +4,16 @@
 ; RUN: opt < %s -disable-output -passes='instcombine,loop(licm),instcombine,loop(licm)' -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-NEW -check-prefix=TIME-DOUBLE-LICM-NEW
 ; RUN: opt < %s -disable-output -passes='default<O2>' -time-passes 2>&1 | FileCheck %s --check-prefix=TIME
 ;
+; The following 4 test runs verify -info-output-file interaction (default goes to stderr, '-' goes to stdout).
+; RUN: opt < %s -disable-output -O2 -time-passes -info-output-file='-' 2>/dev/null | FileCheck %s --check-prefix=TIME
+; RUN: opt < %s -disable-output -passes='default<O2>' -time-passes -info-output-file='-' 2>/dev/null | FileCheck %s --check-prefix=TIME
+;
+; RUN: rm -f %t; opt < %s -disable-output -O2 -time-passes -info-output-file=%t
+; RUN:   cat %t | FileCheck %s --check-prefix=TIME
+;
+; RUN: rm -f %t; opt < %s -disable-output -passes='default<O2>' -time-passes -info-output-file=%t
+; RUN:   cat %t | FileCheck %s --check-prefix=TIME
+;
 ; TIME: Pass execution timing report
 ; TIME: Total Execution Time:
 ; TIME: Name

unittests/IR/CMakeLists.txt

@@ -30,6 +30,7 @@ add_llvm_unittest(IRTests
   ModuleTest.cpp
   PassManagerTest.cpp
   PatternMatch.cpp
+  TimePassesTest.cpp
   TypesTest.cpp
   UseTest.cpp
   UserTest.cpp

unittests/IR/TimePassesTest.cpp

@@ -0,0 +1,78 @@
+//===- unittests/IR/TimePassesTest.cpp - TimePassesHandler tests ----------===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#include <gtest/gtest.h>
+#include <llvm/ADT/SmallString.h>
+#include <llvm/IR/LLVMContext.h>
+#include <llvm/IR/Module.h>
+#include <llvm/IR/PassInstrumentation.h>
+#include <llvm/IR/PassManager.h>
+#include <llvm/IR/PassTimingInfo.h>
+#include <llvm/Support/raw_ostream.h>
+
+using namespace llvm;
+
+namespace {
+
+class MyPass1 : public PassInfoMixin<MyPass1> {};
+class MyPass2 : public PassInfoMixin<MyPass2> {};
+
+TEST(TimePassesTest, CustomOut) {
+  PassInstrumentationCallbacks PIC;
+  PassInstrumentation PI(&PIC);
+
+  LLVMContext Context;
+  Module M("TestModule", Context);
+  MyPass1 Pass1;
+  MyPass2 Pass2;
+
+  SmallString<0> TimePassesStr;
+  raw_svector_ostream ReportStream(TimePassesStr);
+
+  // Setup time-passes handler and redirect output to the stream.
+  std::unique_ptr<TimePassesHandler> TimePasses =
+      llvm::make_unique<TimePassesHandler>(true);
+  TimePasses->setOutStream(ReportStream);
+  TimePasses->registerCallbacks(PIC);
+
+  // Running some passes to trigger the timers.
+  PI.runBeforePass(Pass1, M);
+  PI.runBeforePass(Pass2, M);
+  PI.runAfterPass(Pass2, M);
+  PI.runAfterPass(Pass1, M);
+
+  // Generating report.
+  TimePasses->print();
+
+  // There should be Pass1 and Pass2 in the report
+  EXPECT_FALSE(TimePassesStr.empty());
+  EXPECT_TRUE(TimePassesStr.str().contains("report"));
+  EXPECT_TRUE(TimePassesStr.str().contains("Pass1"));
+  EXPECT_TRUE(TimePassesStr.str().contains("Pass2"));
+
+  // Clear and generate report again.
+  TimePassesStr.clear();
+  TimePasses->print();
+  // Since we did not run any passes since last print, report should be empty.
+  EXPECT_TRUE(TimePassesStr.empty());
+
+  // Now run just a single pass to populate timers again.
+  PI.runBeforePass(Pass2, M);
+  PI.runAfterPass(Pass2, M);
+
+  // Generate report by deleting the handler.
+  TimePasses.reset();
+
+  // There should be Pass2 in this report and no Pass1.
+  EXPECT_FALSE(TimePassesStr.str().empty());
+  EXPECT_TRUE(TimePassesStr.str().contains("report"));
+  EXPECT_FALSE(TimePassesStr.str().contains("Pass1"));
+  EXPECT_TRUE(TimePassesStr.str().contains("Pass2"));
+}
+
+} // end anonymous namespace