[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

git-svn-id: https://llvm.org/svn/llvm-project/llvm/trunk@356305 91177308-0d34-0410-b5e6-96231b3b80d8

diff --git a/include/llvm/IR/PassTimingInfo.h b/include/llvm/IR/PassTimingInfo.h
index ddddbdfa3a30d025e85b3cf3fbd332344bc16d15..22a473e923bc1f75601e29432462992dbf0f8d87 100644 (file)
--- a/include/llvm/IR/PassTimingInfo.h
+++ b/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;

diff --git a/include/llvm/Passes/StandardInstrumentations.h b/include/llvm/Passes/StandardInstrumentations.h
index 56725436a7742041db0a136e89334fa0929a1a27..3d3002eecce98ccb48548bb7db9585df85c9a632 100644 (file)
--- a/include/llvm/Passes/StandardInstrumentations.h
+++ b/include/llvm/Passes/StandardInstrumentations.h
@@ -63,6 +63,8 @@ public:
   StandardInstrumentations() = default;
 
   void registerCallbacks(PassInstrumentationCallbacks &PIC);
+
+  TimePassesHandler &getTimePasses() { return TimePasses; }
 };
 } // namespace llvm
 

diff --git a/lib/IR/PassTimingInfo.cpp b/lib/IR/PassTimingInfo.cpp
index 57efdca423fc9ccf5c1f95d2f9c141341fe146be..dcbfff1a1618733e75ec67ecdfe8029496be40bd 100644 (file)
--- a/lib/IR/PassTimingInfo.cpp
+++ b/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>()

diff --git a/test/Other/time-passes.ll b/test/Other/time-passes.ll
index 066ff267c473a0ab020ce7e8e93b9dd6b8c35308..743b4ebc0d6d1a815c3df154b1061042a1307729 100644 (file)
--- a/test/Other/time-passes.ll
+++ b/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

diff --git a/unittests/IR/CMakeLists.txt b/unittests/IR/CMakeLists.txt
index c3cdf90c0ef0dde62750aa722986404410f49c6c..5b35dc726838eafc487a50b6fc15137592592d75 100644 (file)
--- a/unittests/IR/CMakeLists.txt
+++ b/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

diff --git a/unittests/IR/TimePassesTest.cpp b/unittests/IR/TimePassesTest.cpp
new file mode 100644 (file)
index 0000000..7014436
--- /dev/null
+++ b/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