Statistic/Timer: Include timers in PrintStatisticsJSON().

[hfinkel]

Why are we using JSON for this? Should we use YAML for consistency with other things we serialize to text?

[MatzeB]

In D25588#569932, @hfinkel wrote:

Why are we using JSON for this? Should we use YAML for consistency with other things we serialize to text?

Technically YAML is a superset of JSON so this is YAML. Though admittedly I just looked that up, this really was a "I don't care" decision, my first version used in http://reviews.llvm.org/D20995 used CSV but the reviewers rather liked JSON.

Maybe I can sneak the escape function into one of our yaml headers then. Though I probably don't want to use all the IO machinery in YAMLTraits.h just to output some key/value pairs...

[MatzeB]

Use yaml::needsQuotes() instead of adding a new JSONEscape() function/JSON.h header.

[bruno]

This is very nice. A couple of questions/comments:

• Looks like if you pass -stats -stats-json -time-passes then all timers and statistics are printed together, what happens if you just pass -stats-json -time-passes, would that only output the timers in json format? Also, when printed together, are they part of the same "group"? it's not clear from the tests how the output layout works.
• Do you plan to somehow track different runs of the same pass? Right now that could be inferred by looking into the output order, but it would be nice (not necessarily in this patch) to easily access that information; I remember it to be really useful when comparing compile time between two different compilers, I could then notice when one compiler run the same pass more times than the other and it would also help identify when specific runs were slower due to the influence of other opts.

[MatzeB]

In D25588#571012, @bruno wrote:

This is very nice. A couple of questions/comments:

• Looks like if you pass -stats -stats-json -time-passes then all timers and statistics are printed together, what happens if you just pass -stats-json -time-passes, would that only output the timers in json format? Also, when printed together, are they part of the same "group"? it's not clear from the tests how the output layout works.

The way this currently works is that the statistics printing code grabs the timers when printing (as a side effect this clears the timers so they won't get printed again by the timer printing code). This means that with "-stats-json -time-passes" without "-stats" you will get no stats printed and the timers will end up being printed in the traditional format. I don't think we need such a mode either as I expect the data to be processed by scripts which could just as well do the filtering afterwards.

The current output format is simply a list of key/values. However I introduced some hierarchy in the key names, so you will see key names like "mem2reg.NumSingleStore", "time.regalloc.seed.user" or "time.pass.Scalar Evolution Analysis.wall" so you can filter somewhat by prefixes/suffixes of the keys.

• Do you plan to somehow track different runs of the same pass? Right now that could be inferred by looking into the output order, but it would be nice (not necessarily in this patch) to easily access that information; I remember it to be really useful when comparing compile time between two different compilers, I could then notice when one compiler run the same pass more times than the other and it would also help identify when specific runs were slower due to the influence of other opts.

This patch does not change the way timers are run, so all timers with the same name and therefore all runs of a pass with the same name are merged together. It would indeed be nice to introduce a model here where rather dump some form statistic events rather than the summed stats; But that is a more fundamental change that needs to be done in a different commit. I'd be happy to help discuss, design and review if someone wants to attack this.

[MatzeB]

ping

[MatzeB]

ping2

[bruno]

Thanks for the detailed explanations Matthias. LGTM

include/llvm/ADT/Statistic.h

 std::unique_ptr<raw_fd_ostream> CreateInfoOutputFile();
 
 /// \brief Print statistics to the file returned by CreateInfoOutputFile().
 void PrintStatistics();
 
 /// \brief Print statistics to the given output stream.
 void PrintStatistics(raw_ostream &OS);
 
-/// Print statistics in JSON format.
+/// 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
+/// PrintStatisticsJSON().
 void PrintStatisticsJSON(raw_ostream &OS);
 
 } // end namespace llvm
 
 #endif // LLVM_ADT_STATISTIC_H

include/llvm/Support/Timer.h

explicit NamedRegionTimer(StringRef Name, StringRef Description,
                             StringRef GroupDescription, bool Enabled = true);
 };
 
 /// The TimerGroup class is used to group together related timers into a single
 /// report that is printed when the TimerGroup is destroyed.  It is illegal to
 /// destroy a TimerGroup object before all of the Timers in it are gone.  A
 /// TimerGroup can be specified for a newly created timer in its constructor.
 class TimerGroup {
+  struct PrintRecord {
+    TimeRecord Time;
+    std::string Name;
+    std::string Description;
+
+    PrintRecord(const PrintRecord &Other) = default;
+    PrintRecord(const TimeRecord &Time, const std::string &Name,
+                const std::string &Description)
+      : Time(Time), Name(Name), Description(Description) {}
+
+    bool operator <(const PrintRecord &Other) const {
+      return Time < Other.Time;
+    }
+  };
   std::string Name;
   std::string Description;
   Timer *FirstTimer = nullptr; ///< First timer in the group.
-  std::vector<std::pair<TimeRecord, std::string>> TimersToPrint;
+  std::vector<PrintRecord> TimersToPrint;
 
   TimerGroup **Prev; ///< Pointer to Next field of previous timergroup in list.
   TimerGroup *Next;  ///< Pointer to next timergroup in list.
   TimerGroup(const TimerGroup &TG) = delete;
   void operator=(const TimerGroup &TG) = delete;
 
 public:
   explicit TimerGroup(StringRef Name, StringRef Description);
   ~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 and zero them.
   void print(raw_ostream &OS);
 
   /// This static method prints all timers and clears them all out.
   static void printAll(raw_ostream &OS);
 
+  /// Ensure global timer group lists are initialized. This function is mostly
+  /// 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 PrintQueuedTimers(raw_ostream &OS);
+  void printJSONValue(raw_ostream &OS, const PrintRecord &R,
+                      const char *suffix, double Value);
+  const char *printJSONValues(raw_ostream &OS, const char *delim);
+  static const char *printAllJSONValues(raw_ostream &OS, const char *delim);
 };
 
 } // end namespace llvm
 
 #endif

lib/Support/Statistic.cpp

 #include "llvm/ADT/Statistic.h"
 #include "llvm/ADT/StringExtras.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/Compiler.h"
 #include "llvm/Support/Debug.h"
 #include "llvm/Support/Format.h"
 #include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/Mutex.h"
+#include "llvm/Support/Timer.h"
 #include "llvm/Support/raw_ostream.h"
+#include "llvm/Support/YAMLTraits.h"
 #include <algorithm>
 #include <cstring>
 using namespace llvm;
 
 /// -stats - Command line option to cause transformations to emit stats about
 /// what they did.
 ///
 static cl::opt<bool> Stats("stats",
class StatisticInfo {
   std::vector<const Statistic*> Stats;
   friend void llvm::PrintStatistics();
   friend void llvm::PrintStatistics(raw_ostream &OS);
   friend void llvm::PrintStatisticsJSON(raw_ostream &OS);
 
   /// Sort statistics by debugtype,name,description.
   void sort();
 public:
+  StatisticInfo();
   ~StatisticInfo();
 
   void addStatistic(const Statistic *S) {
     Stats.push_back(S);
   }
 };
 }
 
if (!Initialized) {
     sys::MemoryFence();
     // Remember we have been registered.
     TsanIgnoreWritesBegin();
     Initialized = true;
     TsanIgnoreWritesEnd();
   }
 }
 
+StatisticInfo::StatisticInfo() {
+  // Ensure timergroup lists are created first so they are destructed after us.
+  TimerGroup::ConstructTimerLists();
+}
+
 // Print information when destroyed, iff command line option is specified.
 StatisticInfo::~StatisticInfo() {
   if (::Stats || PrintOnExit)
     llvm::PrintStatistics();
 }
 
 void llvm::EnableStatistics(bool PrintOnExit) {
   Enabled = true;
OS << format("%*u %-*s - %s\n",
                  MaxValLen, Stats.Stats[i]->getValue(),
                  MaxDebugTypeLen, Stats.Stats[i]->getDebugType(),
                  Stats.Stats[i]->getDesc());
 
   OS << '\n';  // Flush the output stream.
   OS.flush();
 }
 
-static void write_json_string_escaped(raw_ostream &OS, const char *string) {
-  // Out current usage should not need any escaping. Keep it simple and just
-  // check that the input is pure ASCII without special characers.
-#ifndef NDEBUG
-  for (const unsigned char *c = (const unsigned char*)string; *c != '\0'; ++c) {
-    assert(*c != '\\' && *c != '\"' && *c >= 0x20 && *c < 0x80);
-  }
-#endif
-  OS << string;
-}
-
 void llvm::PrintStatisticsJSON(raw_ostream &OS) {
   StatisticInfo &Stats = *StatInfo;
 
   Stats.sort();
 
   // Print all of the statistics.
   OS << "{\n";
   const char *delim = "";
   for (const Statistic *Stat : Stats.Stats) {
     OS << delim;
-    OS << "\t\"";
-    write_json_string_escaped(OS, Stat->getDebugType());
-    OS << '.';
-    write_json_string_escaped(OS, Stat->getName());
-    OS << "\": " << Stat->getValue();
+    assert(!yaml::needsQuotes(Stat->getDebugType()) &&
+           "Statistic group/type name is simple.");
+    assert(!yaml::needsQuotes(Stat->getName()) && "Statistic name is simple");
+    OS << "\t\"" << Stat->getDebugType() << '.' << Stat->getName() << "\": "
+       << Stat->getValue();
     delim = ",\n";
   }
+  // Print timers.
+  TimerGroup::printAllJSONValues(OS, delim);
+
   OS << "\n}\n";
   OS.flush();
 }
 
 void llvm::PrintStatistics() {
 #if !defined(NDEBUG) || defined(LLVM_ENABLE_STATS)
   StatisticInfo &Stats = *StatInfo;
 

lib/Support/Timer.cpp

 #include "llvm/ADT/StringMap.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/Format.h"
 #include "llvm/Support/ManagedStatic.h"
 #include "llvm/Support/Mutex.h"
 #include "llvm/Support/Process.h"
 #include "llvm/Support/raw_ostream.h"
+#include "llvm/Support/YAMLTraits.h"
 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

 }
 
 
 void TimerGroup::removeTimer(Timer &T) {
   sys::SmartScopedLock<true> L(*TimerLock);
 
   // If the timer was started, move its data to TimersToPrint.
   if (T.hasTriggered())
-    TimersToPrint.emplace_back(T.Time, T.Description);
+    TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
 
   T.TG = nullptr;
 
   // Unlink the timer from our list.
   *T.Prev = T.Next;
   if (T.Next)
     T.Next->Prev = T.Prev;
 
void TimerGroup::addTimer(Timer &T) {
   FirstTimer = &T;
 }
 
 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
   // Sort the timers in descending order by amount of time taken.
   std::sort(TimersToPrint.begin(), TimersToPrint.end());
 
   TimeRecord Total;
-  for (auto &RecordNamePair : TimersToPrint)
-    Total += RecordNamePair.first;
+  for (const PrintRecord &Record : TimersToPrint)
+    Total += Record.Time;
 
   // Print out timing header.
   OS << "===" << std::string(73, '-') << "===\n";
   // Figure out how many spaces to indent TimerGroup name.
   unsigned Padding = (80-Description.length())/2;
   if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
   OS.indent(Padding) << Description << '\n';
   OS << "===" << std::string(73, '-') << "===\n";
void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
   if (Total.getProcessTime())
     OS << "   --User+System--";
   OS << "   ---Wall Time---";
   if (Total.getMemUsed())
     OS << "  ---Mem---";
   OS << "  --- Name ---\n";
 
   // Loop through all of the timing data, printing it out.
-  for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) {
-    const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1];
-    Entry.first.print(Total, OS);
-    OS << Entry.second << '\n';
+  for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(),
+                                              TimersToPrint.rend())) {
+    Record.Time.print(Total, OS);
+    OS << Record.Description << '\n';
   }
 
   Total.print(Total, OS);
   OS << "Total\n\n";
   OS.flush();
 
   TimersToPrint.clear();
 }
 
-void TimerGroup::print(raw_ostream &OS) {
-  sys::SmartScopedLock<true> L(*TimerLock);
-
+void TimerGroup::prepareToPrintList() {
   // See if any of our timers were started, if so add them to TimersToPrint and
   // reset them.
   for (Timer *T = FirstTimer; T; T = T->Next) {
     if (!T->hasTriggered()) continue;
-    TimersToPrint.emplace_back(T->Time, T->Description);
+    TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
 
     // Clear out the time.
     T->clear();
   }
+}
+
+void TimerGroup::print(raw_ostream &OS) {
+  sys::SmartScopedLock<true> L(*TimerLock);
+
+  prepareToPrintList();
 
   // If any timers were started, print the group.
   if (!TimersToPrint.empty())
     PrintQueuedTimers(OS);
 }
 
 void TimerGroup::printAll(raw_ostream &OS) {
   sys::SmartScopedLock<true> L(*TimerLock);
 
   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
     TG->print(OS);
 }
+
+void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
+                                const char *suffix, double Value) {
+  assert(!yaml::needsQuotes(Name) && "TimerGroup name needs no quotes");
+  assert(!yaml::needsQuotes(R.Name) && "Timer name needs no quotes");
+  OS << "\t\"time." << Name << '.' << R.Name << suffix << "\": " << Value;
+}
+
+const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
+  prepareToPrintList();
+  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());
+    OS << delim;
+    printJSONValue(OS, R, ".sys", T.getSystemTime());
+  }
+  TimersToPrint.clear();
+  return delim;
+}
+
+const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
+  sys::SmartScopedLock<true> L(*TimerLock);
+  for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
+    delim = TG->printJSONValues(OS, delim);
+  return delim;
+}
+
+void TimerGroup::ConstructTimerLists() {
+  (void)*NamedGroupedTimers;
+}

test/Other/statistic.ll

 ; RUN: opt < %s -o /dev/null -instsimplify -stats -stats-json 2>&1 | FileCheck %s --check-prefix=JSON
 ; RUN: opt < %s -o /dev/null -instsimplify -stats -stats-json -info-output-file %t && FileCheck %s < %t --check-prefix=JSON
+; RUN: opt < %s -o /dev/null -instsimplify -stats -stats-json -time-passes 2>&1 | FileCheck %s --check-prefixes=JSON,JSONTIME
+; RUN: opt < %s -o /dev/null -instsimplify -stats -stats-json -time-passes -info-output-file %t && FileCheck %s < %t --check-prefixes=JSON,JSONTIME
 ; RUN: opt < %s -o /dev/null -instsimplify -stats 2>&1 | FileCheck %s --check-prefix=DEFAULT
 ; RUN: opt < %s -o /dev/null -instsimplify -stats -info-output-file %t && FileCheck %s < %t --check-prefix=DEFAULT
 ; REQUIRES: asserts
 
 ; JSON: {
-; JSON:   "instsimplify.NumSimplified": 1
+; JSON-DAG:   "instsimplify.NumSimplified": 1
+; JSONTIME-DAG:   "time.pass.Remove redundant instructions.wall"
+; JSONTIME-DAG:   "time.pass.Remove redundant instructions.user"
+; JSONTIME-DAG:   "time.pass.Remove redundant instructions.sys"
 ; JSON: }
 
 ; DEFAULT: 1 instsimplify - Number of redundant instructions removed
 
 define i32 @foo() {
   %res = add i32 5, 4
   ret i32 %res
 }