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

[fedor.sergeev]

Summary

As a followup to newpm -time-passes fix (D59366), now adding a similar
functionality to legacy time-passes.

Enhancing llvm::reportAndResetTimings to accept an optional stream
for reporting output. By default it still reports into info-output-file.

Also fixing to actually reset after printing as declared.

[philip.pfaffe]

Just two inline nits.

unittests/IR/TimePassesTest.cpp

174

You have a lot of namespace switches here. If you reorder slightly, that's unnecessary.

[fedor.sergeev]

moved legacy test code around to remove the need for additional namespace manipulations

[philip.pfaffe]

include/llvm/IR/PassTimingInfo.h

32

Sorry, this second nit got lost: Is it clear from context what info-output-file is? Otherwise reference CreateInfoOutputFile() instead.

unittests/IR/TimePassesTest.cpp

29

Is this one still necessary?

[fedor.sergeev]

include/llvm/IR/PassTimingInfo.h

32

Well, both of these would require a search through sources if you do not know what it is.
info-output-file is a command-line level control, CreateInfoOutputFile is an API control.
I really do not have any preferences here.

unittests/IR/TimePassesTest.cpp

29

well... as I see it is quite common through the unittests to use anonymous namespaces to hide test stuff
(I gather to avoid any clashes with LLVM interfaces).
Say, LegacyPassManagerTest does pretty much the same.
Its just that weird requirement of INITIALIZE_PASS for legacy passes to be inside namespace llvm that requires
extra namespace busywork.

I'm open for any suggestions here.

[fedor.sergeev]

include/llvm/IR/PassTimingInfo.h

32

Will it be more clear if I say "By default it uses file stream specified by -info-output-file" ?

[philip.pfaffe]

include/llvm/IR/PassTimingInfo.h

32

Technically that's not correct though, per default it uses CreateInfoOutputFile as far as the API is concerned. That that then reads the command line option is still one more hop.

unittests/IR/TimePassesTest.cpp

29

Sure, you're opening another anonymous namespace 30 lines down though.

[fedor.sergeev]

include/llvm/IR/PassTimingInfo.h

32

ok

unittests/IR/TimePassesTest.cpp

29

*that* is a completely different anonymous namespace, which is not nested into llvm.

this one:
namespace llvm {

namespace {
   ... passes here
}

}
is a namespace for Passes, which are required to be llvm::something, otherwise INITIALIZE_PASS does not seem to work.

and the next one:
namespace {

... tests here

}
is a namespace for tests, which can be whatever you want.
I can remove the latter and put everything (passes and tests) inside the former (nested inside llvm::) one.
I dont see it as a good solution, but I dont have strong feelings about that.

[fedor.sergeev]

comments updated

[philip.pfaffe]

On final language nit, otherwise LGTM!

include/llvm/IR/PassTimingInfo.h

68

Maybe 'into the stream created by CreateInfoOutputFile()'? Also in order to get the doxygen linking to kick in.

include/llvm/IR/PassTimingInfo.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();
+/// reset the timers to zero. By default it uses info-output-file stream.
+void reportAndResetTimings(raw_ostream *OutStream = nullptr);
 
 /// Request the timer for this legacy-pass-manager's pass instance.
 Timer *getPassTimer(Pass *);
 
 /// If the user specifies the -time-passes argument on an LLVM tool command line
 /// then the value of this boolean will be true, otherwise false.
 /// This is the storage for the -time-passes option.
 extern bool TimePassesIsEnabled;
class TimePassesHandler {
   /// 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.

include/llvm/Support/Timer.h

public:
 
   ~TimerGroup();
 
   void setName(StringRef NewName, StringRef NewDescription) {
     Name.assign(NewName.begin(), NewName.end());
     Description.assign(NewDescription.begin(), NewDescription.end());
   }
 
-  /// Print any started timers in this group.
-  void print(raw_ostream &OS);
+  /// Print any started timers in this group, optionally resetting timers after
+  /// printing them.
+  void print(raw_ostream &OS, bool ResetAfterPrint = false);
 
   /// Clear all timers in this group.
   void clear();
 
   /// This static method prints all timers.
   static void printAll(raw_ostream &OS);
 
   /// Clear out all timers. This is mostly used to disable automatic
public:
   /// used by the Statistic code to influence the construction and destruction
   /// order of the global timer lists.
   static void ConstructTimerLists();
 private:
   friend class Timer;
   friend void PrintStatisticsJSON(raw_ostream &OS);
   void addTimer(Timer &T);
   void removeTimer(Timer &T);
-  void prepareToPrintList();
+  void prepareToPrintList(bool reset_time = false);
   void PrintQueuedTimers(raw_ostream &OS);
   void printJSONValue(raw_ostream &OS, const PrintRecord &R,
                       const char *suffix, double Value);
 };
 
 } // end namespace llvm
 
 #endif

lib/IR/PassTimingInfo.cpp

public:
 
   /// Initializes the static \p TheTimeInfo member to a non-null value when
   /// -time-passes is enabled. Leaves it null otherwise.
   ///
   /// This method may be called multiple times.
   static void init();
 
   /// Prints out timing information and then resets the timers.
-  void print();
+  /// By default it uses info-output-file stream.
+  void print(raw_ostream *OutStream = nullptr);
 
   /// Returns the timer for the specified pass if it exists.
   Timer *getPassTimer(Pass *, PassInstanceID);
 
   static PassTimingInfo *TheTimeInfo;
 
 private:
   Timer *newPassTimer(StringRef PassID, StringRef PassDesc);
void PassTimingInfo::init() {
   // Constructed the first time this is called, iff -time-passes is enabled.
   // This guarantees that the object will be constructed after static globals,
   // thus it will be destroyed before them.
   static ManagedStatic<PassTimingInfo> TTI;
   TheTimeInfo = &*TTI;
 }
 
 /// Prints out timing information and then resets the timers.
-void PassTimingInfo::print() { TG.print(*CreateInfoOutputFile()); }
+void PassTimingInfo::print(raw_ostream *OutStream) {
+  TG.print(OutStream ? *OutStream : *CreateInfoOutputFile(), true);
+}
 
 Timer *PassTimingInfo::newPassTimer(StringRef PassID, StringRef PassDesc) {
   unsigned &num = PassIDCountMap[PassID];
   num++;
   // Appending description with a pass-instance number for all but the first one
   std::string PassDescNumbered =
       num <= 1 ? PassDesc.str() : formatv("{0} #{1}", PassDesc, num).str();
   return new Timer(PassID, PassDescNumbered, TG);
Timer *getPassTimer(Pass *P) {
   legacy::PassTimingInfo::init();
   if (legacy::PassTimingInfo::TheTimeInfo)
     return legacy::PassTimingInfo::TheTimeInfo->getPassTimer(P, P);
   return nullptr;
 }
 
 /// If timing is enabled, report the times collected up to now and then reset
 /// them.
-void reportAndResetTimings() {
+void reportAndResetTimings(raw_ostream *OutStream) {
   if (legacy::PassTimingInfo::TheTimeInfo)
-    legacy::PassTimingInfo::TheTimeInfo->print();
+    legacy::PassTimingInfo::TheTimeInfo->print(OutStream);
 }
 
 //===----------------------------------------------------------------------===//
 // Pass timing handling for the New Pass Manager
 //===----------------------------------------------------------------------===//
 
 /// Returns the timer for the specified pass invocation of \p PassID.
 /// Each time it creates a new timer.

 
 void TimePassesHandler::setOutStream(raw_ostream &Out) {
   OutStream = &Out;
 }
 
 void TimePassesHandler::print() {
   if (!Enabled)
     return;
-  TG.print(OutStream ? *OutStream : *CreateInfoOutputFile());
-  TG.clear();
+  TG.print(OutStream ? *OutStream : *CreateInfoOutputFile(), true);
 }
 
 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())

lib/Support/Timer.cpp

void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
 
   Total.print(Total, OS);
   OS << "Total\n\n";
   OS.flush();
 
   TimersToPrint.clear();
 }
 
-void TimerGroup::prepareToPrintList() {
+void TimerGroup::prepareToPrintList(bool ResetTime) {
   // See if any of our timers were started, if so add them to TimersToPrint.
   for (Timer *T = FirstTimer; T; T = T->Next) {
     if (!T->hasTriggered()) continue;
     bool WasRunning = T->isRunning();
     if (WasRunning)
       T->stopTimer();
 
     TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
 
+    if (ResetTime)
+      T->clear();
+
     if (WasRunning)
       T->startTimer();
   }
 }
 
-void TimerGroup::print(raw_ostream &OS) {
+void TimerGroup::print(raw_ostream &OS, bool ResetAfterPrint) {
+  {
+    // After preparing the timers we can free the lock
     sys::SmartScopedLock<true> L(*TimerLock);
-
-  prepareToPrintList();
+    prepareToPrintList(ResetAfterPrint);
+  }
 
   // If any timers were started, print the group.
   if (!TimersToPrint.empty())
     PrintQueuedTimers(OS);
 }
 
 void TimerGroup::clear() {
   sys::SmartScopedLock<true> L(*TimerLock);
void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
   constexpr auto max_digits10 = std::numeric_limits<double>::max_digits10;
   OS << "\t\"time." << Name << '.' << R.Name << suffix
      << "\": " << format("%.*e", max_digits10 - 1, Value);
 }
 
 const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
   sys::SmartScopedLock<true> L(*TimerLock);
 
-  prepareToPrintList();
+  prepareToPrintList(false);
   for (const PrintRecord &R : TimersToPrint) {
     OS << delim;
     delim = ",\n";
 
     const TimeRecord &T = R.Time;
     printJSONValue(OS, R, ".wall", T.getWallTime());
     OS << delim;
     printJSONValue(OS, R, ".user", T.getUserTime());

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/LegacyPassManager.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;
 
+//===----------------------------------------------------------------------===//
+// Define dummy passes for legacy pass manager run.
+
+namespace llvm {
+
+void initializePass1Pass(PassRegistry &);
+void initializePass2Pass(PassRegistry &);
+
+namespace {
+struct Pass1 : public ModulePass {
+  static char ID;
+
+public:
+  Pass1() : ModulePass(ID) {}
+  bool runOnModule(Module &M) override { return false; }
+  void getAnalysisUsage(AnalysisUsage &AU) const override {
+    AU.setPreservesAll();
+  }
+  StringRef getPassName() const override { return "Pass1"; }
+};
+char Pass1::ID;
+
+struct Pass2 : public ModulePass {
+  static char ID;
+
+public:
+  Pass2() : ModulePass(ID) {}
+  bool runOnModule(Module &M) override { return false; }
+  void getAnalysisUsage(AnalysisUsage &AU) const override {
+    AU.setPreservesAll();
+  }
+  StringRef getPassName() const override { return "Pass2"; }
+};
+char Pass2::ID;
+} // namespace
+} // namespace llvm
+
+INITIALIZE_PASS(Pass1, "Pass1", "Pass1", false, false)
+INITIALIZE_PASS(Pass2, "Pass2", "Pass2", false, false)
+
 namespace {
 
+TEST(TimePassesTest, LegacyCustomOut) {
+  PassInstrumentationCallbacks PIC;
+  PassInstrumentation PI(&PIC);
+
+  LLVMContext Context;
+  Module M("TestModule", Context);
+
+  SmallString<0> TimePassesStr;
+  raw_svector_ostream ReportStream(TimePassesStr);
+
+  // Setup pass manager
+  legacy::PassManager PM1;
+  PM1.add(new llvm::Pass1());
+  PM1.add(new llvm::Pass2());
+
+  // Enable time-passes and run passes.
+  TimePassesIsEnabled = true;
+  PM1.run(M);
+
+  // Generating report.
+  reportAndResetTimings(&ReportStream);
+
+  // 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();
+  reportAndResetTimings(&ReportStream);
+
+  // 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.
+  legacy::PassManager PM2;
+  PM2.add(new llvm::Pass2());
+  PM2.run(M);
+
+  // Generate report again.
+  reportAndResetTimings(&ReportStream);
+
+  // 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"));
+}
+
 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.
+  // Pretending that passes are running 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.
+  // Now trigger 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