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

[fedor.sergeev]

Summary

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.

[fedor.sergeev]

As per discussion with @philip.pfaffe - owning output stream is rather strange for TimePasses object.
This ownership idea came from CreateInfoOutputFile design, as it returns new stream each time.

Now making OutStream being just a non-owning pointer and handling ownership ouside of TimePasses
(in NewPMDriver).

[fedor.sergeev]

outstream in TimePasses is set when enabling, so now it is not possible
to enable and have outstream == nullptr.

[philip.pfaffe]

Why not default to CreateInfoOutputFile inside of TimePassesHandler if OutputStream is unset? And then have a setStream(raw_ostream&) method to change it.

[fedor.sergeev]

In D59366#1429333, @philip.pfaffe wrote:

Why not default to CreateInfoOutputFile inside of TimePassesHandler if OutputStream is unset? And then have a setStream(raw_ostream&) method to change it.

That is purely a chicken/egg issue.
CreateInfoOutputFile creates a new stream and unless we retake the ownership it will be destroyed.

So there are two approaches to set it for TimePasses by default:

• own it in TimePassesHandler (my initial implementation)
• pass the non-owning pointer into the default constructor (requires passing it to StandardInstrumentation first, so not ideal either)

[philip.pfaffe]

CreateInfoOutputFile creates a new stream and unless we retake the ownership it will be destroyed.

True, but that's what it is doing right now. Do you see reason to change that?

[fedor.sergeev]

In D59366#1429383, @philip.pfaffe wrote:

CreateInfoOutputFile creates a new stream and unless we retake the ownership it will be destroyed.

True, but that's what it is doing right now. Do you see reason to change that?

Okey, let me enumerate all the possible solutions that I see:

1. own stream in TimePassesHandler (my initial implementation)
2. create TimePasses disabled/no-stream, enable from NewPMDriver (current state), own by NewPMDriver
3. pass the stream to StandardInstrumentation constructor, pass through into TimePassesHandler constructor, own by NewPMDriver
4. change behavior of CreateInfoOutputFile and make it handle the ownership itself

I cant do 4. because that will change -stats behavior as well as -time-passes behavior with old-pm.
We have already decided that 1. is no-go.
So we are left with either 2. or 3.

And 3. requires StandardInstrumentation to decide on how to pass this stream around.
What if PrintIR will be changed to take the stream as well? Should StandardInstrumentation decide to pass the same stream there?
If no then should we add one more stream parameter to StandardInstrumentation constructor?
It does not seem to scale that much....

[fedor.sergeev]

Okey, a proper solution here is to get back to not setting the stream by default and restort to old CreateInfoOutputFile-just-for-printing scheme.
This way we do not need to play with ownership of that info-output-file stream.

The only piece that needs work is unittesting for the new interface, since it will not be utilized in opt/NewPMDriver.

[fedor.sergeev]

handling default case the same way as it was before;
adding unit-test for non-default case

[philip.pfaffe]

Couple of nits inline, otherwise looks great!

lib/IR/PassTimingInfo.cpp

185 ↗

(On Diff #190724)

I think this shouldn't be an error. If someone changes the stream for a disabled timer, so what?

190 ↗

(On Diff #190724)

Calling this now flushes all timer data. Is that worth a comment?

193 ↗

(On Diff #190724)

Isn't that a use-after-free? Is the stream guaranteed to survive the call to operator*?

tools/opt/NewPMDriver.cpp

18 ↗

(On Diff #190724)

Unrelated change.

262 ↗

(On Diff #190724)

Unrelated change.

unittests/IR/TimePassesTest.cpp

18 ↗

(On Diff #190724)

Are the gmock and Error includes actually used?

31 ↗

(On Diff #190724)

Do you need any of these?

58 ↗

(On Diff #190724)

Maybe leave a comment why this is here.

[fedor.sergeev]

Thanks for review!

lib/IR/PassTimingInfo.cpp

185 ↗

(On Diff #190724)

There is no way to reenable the timer. So I thought setting the stream for disabled timer means some confusion.... I'm not sure about this

190 ↗

(On Diff #190724)

The comment is there in the header. It was a "declared" functionality both in legacy and new interfaces, but it actually was never implemented.
Catched this when writing the unit-test.
Btw, I'm adding a check for this into the unit-test, and also preparing a separate patch that adds this flushing for legacy.

193 ↗

(On Diff #190724)

Temporaries are cleaned up at the end of a full-expression, in this case - afteri a TG.print call.

unittests/IR/TimePassesTest.cpp

18 ↗

(On Diff #190724)

yeah, this was copied from some other test, will clean it out.

58 ↗

(On Diff #190724)

will add a bit more code here, with comments...

[fedor.sergeev]

test cleanup - removing unneeded stuff, adding a few more checks, adding comments

[fedor.sergeev]

removing unneeded assert

[philip.pfaffe]

Looks good!

[fedor.sergeev]

Thanks for yet another thorough review!

llvm/trunk/include/llvm/IR/PassTimingInfo.h

 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/Timer.h"
 #include "llvm/Support/TypeName.h"
 #include <memory>
 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.
 void reportAndResetTimings();
 
 /// Request the timer for this legacy-pass-manager's pass instance.
 Timer *getPassTimer(Pass *);
 
class TimePassesHandler {
   DenseMap<PassInvocationID, std::unique_ptr<Timer>> TimingData;
 
   /// Map that counts invocations of passes, for use in UniqPassID construction.
   StringMap<unsigned> PassIDCountMap;
 
   /// 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();
 
   // We intend this to be unique per-compilation, thus no copies.
   TimePassesHandler(const TimePassesHandler &) = delete;
   void operator=(const TimePassesHandler &) = delete;
 
   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;
 
   /// Returns the new timer for each new run of the pass.
   Timer &getPassTimer(StringRef PassID);
 
   /// Returns the incremented counter for the next invocation of \p PassID.

llvm/trunk/include/llvm/Passes/StandardInstrumentations.h

 class StandardInstrumentations {
   PrintIRInstrumentation PrintIR;
   TimePassesHandler TimePasses;
 
 public:
   StandardInstrumentations() = default;
 
   void registerCallbacks(PassInstrumentationCallbacks &PIC);
+
+  TimePassesHandler &getTimePasses() { return TimePasses; }
 };
 } // namespace llvm
 
 #endif

llvm/trunk/lib/IR/PassTimingInfo.cpp

Timer &TimePassesHandler::getPassTimer(StringRef PassID) {
   auto Pair = TimingData.try_emplace(UID, T);
   assert(Pair.second && "should always create a new timer");
   return *(Pair.first->second.get());
 }
 
 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>()
          << ":\n\tRunning:\n";
   for (auto &I : TimingData) {
     const Timer *MyTimer = I.second.get();
     if (!MyTimer || MyTimer->isRunning())
       dbgs() << "\tTimer " << MyTimer << " for pass " << I.first.first << "("

llvm/trunk/test/Other/time-passes.ll

 ; RUN: opt < %s -disable-output -instcombine -instcombine -licm -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-LEGACY
 ; RUN: opt < %s -disable-output -instcombine -instcombine -licm -licm -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-LEGACY --check-prefix=TIME-DOUBLE-LICM-LEGACY
 ; RUN: opt < %s -disable-output -passes='instcombine,instcombine,loop(licm)' -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-NEW
 ; 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
 ; TIME-LEGACY-DAG:   Combine redundant instructions{{$}}
 ; TIME-LEGACY-DAG:   Combine redundant instructions #2
 ; TIME-LEGACY-DAG:   Loop Invariant Code Motion{{$}}
 ; TIME-DOUBLE-LICM-LEGACY-DAG: Loop Invariant Code Motion #2
 ; TIME-LEGACY-DAG:   Scalar Evolution Analysis

llvm/trunk/unittests/IR/CMakeLists.txt

add_llvm_unittest(IRTests
   IntrinsicsTest.cpp
   LegacyPassManagerTest.cpp
   MDBuilderTest.cpp
   ManglerTest.cpp
   MetadataTest.cpp
   ModuleTest.cpp
   PassManagerTest.cpp
   PatternMatch.cpp
+  TimePassesTest.cpp
   TypesTest.cpp
   UseTest.cpp
   UserTest.cpp
   ValueHandleTest.cpp
   ValueMapTest.cpp
   ValueTest.cpp
   VerifierTest.cpp
   WaymarkTest.cpp
   )
 
 target_link_libraries(IRTests PRIVATE LLVMTestingSupport)

llvm/trunk/unittests/IR/TimePassesTest.cpp

+//===- 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