[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

190

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

195

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

198

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

tools/opt/NewPMDriver.cpp

18

Unrelated change.

262

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

190

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

195

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.

198

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!

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;
 
-  bool Enabled;
+  /// Custom output stream to print timing information into.
+  /// By default we emit it into the stream controlled by -info-output-file.
+  raw_ostream *OutStream = nullptr;
+
+  bool Enabled = false;
 
 public:
-  TimePassesHandler(bool Enabled = TimePassesIsEnabled);
+  /// We construct this object in a disabled form.
+  /// To start the timing collection and reports explicit enable() call is
+  /// required.
+  TimePassesHandler();
 
   /// 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();
   }
 
   /// 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);
 
+  /// Enable timers collection and set the output stream for subsequent
+  /// reporting.
+  void enable(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.

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

lib/IR/PassTimingInfo.cpp

Timer &TimePassesHandler::getPassTimer(StringRef PassID) {
 
   PassInvocationID UID{PassID, Count};
   Timer *T = new Timer(PassID, FullDesc, TG);
   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) {}
+TimePassesHandler::TimePassesHandler()
+    : TG("pass", "... Pass execution timing report ...") {}
+
+void TimePassesHandler::enable(raw_ostream &Out) {
+  Enabled = true;
+  OutStream = &Out;
+}
 
-void TimePassesHandler::print() { TG.print(*CreateInfoOutputFile()); }
+void TimePassesHandler::print() {
+  if (!Enabled)
+    return;
+  assert(OutStream && "output stream can not be null");
+  TG.print(*OutStream);
+}
 
 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 << "("
              << I.first.second << ")\n";
   }
   dbgs() << "\tTriggered:\n";
   for (auto &I : TimingData) {

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

tools/opt/NewPMDriver.cpp

 /// This file is just a split of the code that logically belongs in opt.cpp but
 /// that includes the new pass manager headers.
 ///
 //===----------------------------------------------------------------------===//
 
 #include "NewPMDriver.h"
 #include "Debugify.h"
 #include "PassPrinters.h"
+#include "llvm/ADT/Statistic.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Analysis/AliasAnalysis.h"
 #include "llvm/Analysis/CGSCCPassManager.h"
 #include "llvm/Bitcode/BitcodeWriterPass.h"
 #include "llvm/Config/llvm-config.h"
 #include "llvm/IR/Dominators.h"
 #include "llvm/IR/IRPrintingPasses.h"
 #include "llvm/IR/LLVMContext.h"
if (CSPGOKindFlag != NoCSPGO) {
           P = PGOOptions("", CSProfileGenFile, ProfileRemappingFile,
                          PGOOptions::NoAction, PGOOptions::CSIRInstr);
       } else /* CSPGOKindFlag == CSInstrUse */ {
         if (!P)
           errs() << "CSInstrUse needs to be together with InstrUse";
         P->CSAction = PGOOptions::CSIRUse;
       }
     }
+
+  // Setting up standard instrumentations.
+  const bool StreamNeeded = TimePassesIsEnabled;
+  std::unique_ptr<raw_ostream> InfoStream = (StreamNeeded ? CreateInfoOutputFile() : nullptr);
   PassInstrumentationCallbacks PIC;
   StandardInstrumentations SI;
+  if (TimePassesIsEnabled)
+    SI.getTimePasses().enable(*InfoStream);
   SI.registerCallbacks(PIC);
 
   PassBuilder PB(TM, P, &PIC);
   registerEPCallbacks(PB, VerifyEachPass, DebugPM);
 
   // Load requested pass plugins and let them register pass builder callbacks
   for (auto &PluginFN : PassPlugins) {
     auto PassPlugin = PassPlugin::Load(PluginFN);