[Support] allow -stats/-time-passes reporting into a custom stream

[fedor.sergeev]

Summary

Extending the notion of info-output-file by replacing it with
a generic getInfoOutputStream. By default it is still populated with
the file stream created from a managed-static LibSupportInfoOutputFilename.

New interface introduced:

llvm::setInfoOutputStreamProvider

which allows to specify a custom callback which provides an output stream
when needed.

Current intended use is to get "info" output into separate output streams per
each compilation, allowing to, say, get independent non-overlapping pass-times
reports for parallel independent compilations. It can be implemented by installing
a custom stream provider that manages thread-local copies of output streams.

That "thread-aware" provider is not supplied with this fix.

[fedor.sergeev]

clang-formatted.
still figuring out how to unit-test this thing.

[philip.pfaffe]

I don't think this is sufficient or goes into the right direction to support parallel info collection and output.

For the new PassManager, reporting per-thread timings is trivial already and requires no (additional) global state. You can just create a TimePassesHandler instance per thread or per pipeline.
For Statistics on the other hand the approach in this change is insufficient, because the statistics registry is already a singleton. In order to support parallel statistics collection, can we get rid of the Statistics singleton?

[fedor.sergeev]

In D58572#1408671, @philip.pfaffe wrote:

I don't think this is sufficient or goes into the right direction to support parallel info collection and output.

For the new PassManager, reporting per-thread timings is trivial already and requires no (additional) global state. You can just create a TimePassesHandler instance per thread or per pipeline.

A global state of the data being collected is indeed a problem, yet I'm not trying to address it here.

This change is focused purely on the stream that LLVM uses to report the data being collected.
No matter how many TimePassesHandlers you create (and yes, we do create TimePassesHandler one per thread-per-pipeline) they all emit into the same CreateInfoOutputFile() - either stderr or a single file.
I'm trying to solve a problem of a badly interleaved output, thats all.

For Statistics on the other hand the approach in this change is insufficient, because the statistics registry is already a singleton. In order to support parallel statistics collection, can we get rid of the Statistics singleton?

Yes, unfortunately for now the only case that will work for me is -time-passes with new pass manager (and that means - just opt, and not codegen :( ).
But that will be a separate fight (which I perhaps will dash into).

[philip.pfaffe]

This change is focused purely on the stream that LLVM uses to report the data being collected.
No matter how many TimePassesHandlers you create (and yes, we do create TimePassesHandler one per thread-per-pipeline) they all emit into the same CreateInfoOutputFile() - either stderr or a single file.
I'm trying to solve a problem of a badly interleaved output, thats all.

You could set the output directly on the handler.

[fedor.sergeev]

In D58572#1411712, @philip.pfaffe wrote:

This change is focused purely on the stream that LLVM uses to report the data being collected.
No matter how many TimePassesHandlers you create (and yes, we do create TimePassesHandler one per thread-per-pipeline) they all emit into the same CreateInfoOutputFile() - either stderr or a single file.
I'm trying to solve a problem of a badly interleaved output, thats all.

You could set the output directly on the handler.

Do you suggest to get rid of the current scheme where we have a single output file for all kinds of "info data"?
Say, now w/o these changes -info-output-file is controlling the output file for both -stats and -time-passes.
Do you think it was a wrong design and we need to introduce separate output controls for each of those features?

Perhaps you can expand a bit on what exactly in *this* change do you see as problematic?
Your previous comment was mostly about overall -stats/-time-passes design, which I consider to be somewhat orthogonal here.

[philip.pfaffe]

Do you suggest to get rid of the current scheme where we have a single output file for all kinds of "info data"?

No I don't, that should certainly be the default.

Perhaps you can expand a bit on what exactly in *this* change do you see as problematic?

This patch adds to global state and it solves having multiple output streams in a very convoluted way. Since there's only a single callback the callee has to figure out who the caller is to give them the right file. And that's not as simple as looking at the thread id or something like that. For Statistics, it makes no sense to output to different files, because the statistics are singleton.

Your previous comment was mostly about overall -stats/-time-passes design, which I consider to be somewhat orthogonal here.

My comment was about decentralizing the info output file setting. I'm thinking the current CreateInfoOutputFile should be the default for things printing out infos. But in those cases where we want multiple info output streams, the override should be controlled by the caller (in this particular instance, TimePassesHandler, e.g.).

[chandlerc]

I do generally feel like it would be a useful and generically good direction to support the timing system having a pre-bound output stream so that it completely avoids the flag-based info output stream we currently use. It moves everything into a proper API instead of a flags based system that seems inherently hostile to more advanced users.

It also seems good to separate this at the *pass manager* level with a specifically bound pass because it is timing passes.

Statistics are, IMO, a separate question. There, I would suggest that the correct way to have useful parallel access to statistics is to follow-through on a long-standing idea of making statistics be owned by the LLVMContext. But unsure how necessary this is... I thought our statistics were already atomic updated. So maybe it would be enough to just have a single stream for those?

[fedor.sergeev]

Abandoning this in favor of D59366.

include/llvm/ADT/Statistic.h

 //
 // NOTE: Statistics *must* be declared as global variables.
 //
 //===----------------------------------------------------------------------===//
 
 #ifndef LLVM_ADT_STATISTIC_H
 #define LLVM_ADT_STATISTIC_H
 
+#include "llvm/ADT/FunctionExtras.h"
 #include "llvm/Config/llvm-config.h"
 #include "llvm/Support/Compiler.h"
 #include <atomic>
 #include <memory>
 #include <vector>
 
 // Determine whether statistics should be enabled. We must do it here rather
 // than in CMake because multi-config generators cannot determine this at
#define STATISTIC(VARNAME, DESC)                                               \
   static llvm::Statistic VARNAME = {DEBUG_TYPE, #VARNAME, DESC, {0}, {false}}
 
 /// Enable the collection and printing of statistics.
 void EnableStatistics(bool PrintOnExit = true);
 
 /// Check if statistics are enabled.
 bool AreStatisticsEnabled();
 
-/// Return a file stream to print our output on.
-std::unique_ptr<raw_fd_ostream> CreateInfoOutputFile();
+/// Return a stream to print our output into.
+std::unique_ptr<raw_ostream> getInfoOutputStream();
 
-/// Print statistics to the file returned by CreateInfoOutputFile().
+/// Set a callback that provides a stream for info-output
+void setInfoOutputStreamProvider(
+    llvm::unique_function<std::unique_ptr<raw_ostream>()> OStreamProvider);
+
+/// Print statistics to the stream returned by getInfoOutputStream().
 void PrintStatistics();
 
 /// Print statistics to the given output stream.
 void PrintStatistics(raw_ostream &OS);
 
 /// Print statistics in JSON format. This does include all global timers (\see
 /// Timer, TimerGroup). Note that the timers are cleared after printing and will
 /// not be printed in human readable form or in a second call of

lib/IR/PassTimingInfo.cpp

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() { TG.print(*getInfoOutputStream()); }
 
 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 &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::print() { TG.print(*getInfoOutputStream()); }
 
 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 << "("

lib/Support/Statistic.cpp

 #include "llvm/Support/Mutex.h"
 #include "llvm/Support/Timer.h"
 #include "llvm/Support/YAMLTraits.h"
 #include "llvm/Support/raw_ostream.h"
 #include <algorithm>
 #include <cstring>
 using namespace llvm;
 
+// This ugly hack is brought to you courtesy of constructor/destructor ordering
+// being unspecified by C++.  Basically the problem is that a Statistic object
+// gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
+// (below), which calls this function.  LibSupportInfoOutputFilename used to be
+// a global variable, but sometimes it would get destroyed before the Statistic,
+// causing havoc to ensue.  We "fix" this by creating the string the first time
+// it is needed and never destroying it.
+static ManagedStatic<std::string> LibSupportInfoOutputFilename;
+
+static cl::opt<std::string, true>
+    InfoOutputFilename("info-output-file", cl::value_desc("filename"),
+                       cl::desc("File to append -stats and -timer output to"),
+                       cl::Hidden, cl::location(*LibSupportInfoOutputFilename));
+
 /// -stats - Command line option to cause transformations to emit stats about
 /// what they did.
 ///
 static cl::opt<bool> Stats(
     "stats",
     cl::desc("Enable statistics output from program (available with Asserts)"),
     cl::Hidden);
 

 #if LLVM_ENABLE_STATS
   sys::SmartScopedLock<true> Reader(*StatLock);
   StatisticInfo &Stats = *StatInfo;
 
   // Statistics not enabled?
   if (Stats.Stats.empty()) return;
 
   // Get the stream to write to.
-  std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
+  std::unique_ptr<raw_ostream> OutStream = getInfoOutputStream();
   if (StatsAsJSON)
     PrintStatisticsJSON(*OutStream);
   else
     PrintStatistics(*OutStream);
 
 #else
   // Check if the -stats option is set instead of checking
   // !Stats.Stats.empty().  In release builds, Statistics operators
   // do nothing, so stats are never Registered.
   if (Stats) {
     // Get the stream to write to.
-    std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
+    std::unique_ptr<raw_ostream> OutStream = getInfoOutputStream();
     (*OutStream) << "Statistics are disabled.  "
                  << "Build with asserts or with -DLLVM_ENABLE_STATS\n";
   }
 #endif
 }
 
 const std::vector<std::pair<StringRef, unsigned>> llvm::GetStatistics() {
   sys::SmartScopedLock<true> Reader(*StatLock);
   std::vector<std::pair<StringRef, unsigned>> ReturnStats;
 
   for (const auto &Stat : StatInfo->statistics())
     ReturnStats.emplace_back(Stat->getName(), Stat->getValue());
   return ReturnStats;
 }
 
 void llvm::ResetStatistics() {
   StatInfo->reset();
 }
+
+namespace {
+
+std::unique_ptr<raw_fd_ostream> createInfoOutputFile() {
+  std::string OutputFilename = *LibSupportInfoOutputFilename;
+  if (OutputFilename.empty())
+    return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
+  if (OutputFilename == "-")
+    return llvm::make_unique<raw_fd_ostream>(1, false); // stdout.
+
+  // Append mode is used because the info output file is opened and closed
+  // each time -stats or -time-passes wants to print output to it. To
+  // compensate for this, the test-suite Makefiles have code to delete the
+  // info output file before running commands which write to it.
+  std::error_code EC;
+  auto Result = llvm::make_unique<raw_fd_ostream>(
+      OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text);
+  if (!EC)
+    return Result;
+
+  errs() << "Error opening info-output-file '" << OutputFilename
+         << " for appending!\n";
+  return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
+}
+
+static llvm::unique_function<std::unique_ptr<llvm::raw_ostream>()>
+    InfoOStreamProvider;
+
+} // namespace
+
+void llvm::setInfoOutputStreamProvider(
+    llvm::unique_function<std::unique_ptr<llvm::raw_ostream>()>
+        OStreamProvider) {
+  static sys::SmartMutex<true> InfoOutputProviderMutex;
+  sys::SmartScopedLock<true> Lock(InfoOutputProviderMutex);
+  InfoOStreamProvider = std::move(OStreamProvider);
+}
+
+std::unique_ptr<raw_ostream> llvm::getInfoOutputStream() {
+  if (InfoOStreamProvider) {
+    std::unique_ptr<raw_ostream> CustomStream = InfoOStreamProvider();
+    if (CustomStream)
+      return std::move(CustomStream);
+  }
+  return std::unique_ptr<raw_ostream>{createInfoOutputFile()};
+}

lib/Support/Timer.cpp

 #include "llvm/Support/Process.h"
 #include "llvm/Support/Signposts.h"
 #include "llvm/Support/YAMLTraits.h"
 #include "llvm/Support/raw_ostream.h"
 #include <limits>
 
 using namespace llvm;
 
-// This ugly hack is brought to you courtesy of constructor/destructor ordering
-// being unspecified by C++.  Basically the problem is that a Statistic object
-// gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
-// (below), which calls this function.  LibSupportInfoOutputFilename used to be
-// a global variable, but sometimes it would get destroyed before the Statistic,
-// causing havoc to ensue.  We "fix" this by creating the string the first time
-// it is needed and never destroying it.
-static ManagedStatic<std::string> LibSupportInfoOutputFilename;
-static std::string &getLibSupportInfoOutputFilename() {
-  return *LibSupportInfoOutputFilename;
-}
-
 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
 
 /// Allows llvm::Timer to emit signposts when supported.
 static ManagedStatic<SignpostEmitter> Signposts;
 
 namespace {
   static cl::opt<bool>
   TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
                                       "tracking (this may be slow)"),
              cl::Hidden);
 
-  static cl::opt<std::string, true>
-  InfoOutputFilename("info-output-file", cl::value_desc("filename"),
-                     cl::desc("File to append -stats and -timer output to"),
-                   cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
-}
-
-std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
-  const std::string &OutputFilename = getLibSupportInfoOutputFilename();
-  if (OutputFilename.empty())
-    return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
-  if (OutputFilename == "-")
-    return llvm::make_unique<raw_fd_ostream>(1, false); // stdout.
-
-  // Append mode is used because the info output file is opened and closed
-  // each time -stats or -time-passes wants to print output to it. To
-  // compensate for this, the test-suite Makefiles have code to delete the
-  // info output file before running commands which write to it.
-  std::error_code EC;
-  auto Result = llvm::make_unique<raw_fd_ostream>(
-      OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text);
-  if (!EC)
-    return Result;
-
-  errs() << "Error opening info-output-file '"
-    << OutputFilename << " for appending!\n";
-  return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
 }
 
 namespace {
 struct CreateDefaultTimerGroup {
   static void *call() {
     return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
   }
 };
void TimerGroup::removeTimer(Timer &T) {
   if (T.Next)
     T.Next->Prev = T.Prev;
 
   // Print the report when all timers in this group are destroyed if some of
   // them were started.
   if (FirstTimer || TimersToPrint.empty())
     return;
 
-  std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
+  std::unique_ptr<raw_ostream> OutStream = getInfoOutputStream();
   PrintQueuedTimers(*OutStream);
 }
 
 void TimerGroup::addTimer(Timer &T) {
   sys::SmartScopedLock<true> L(*TimerLock);
 
   // Add the timer to our list.
   if (FirstTimer)