[TableGen] Add frontend/backend phase timing capability.

Describe in the BackEnd Developer's Guide. Instrument a few backends.

Remove an old unused timing facility. Add a null backend for timing
the parser.

Differential Revision: https://reviews.llvm.org/D91388

docs/CommandGuide/tblgen.rst

@@ -43,7 +43,7 @@ General Options
 
   Specify the name of the dependency filename.
 
-.. option:: --debug
+.. option:: -debug
 
   Enable debug output.
 
@@ -58,6 +58,11 @@ General Options
  ``directory`` value should be a full or partial path to a directory that
  contains target description files.
 
+.. option:: -null-backend
+
+  Parse the source files and build the records, but do not run any
+  backend. This is useful for timing the frontend.
+
 .. option:: -o filename
 
  Specify the output file name.  If ``filename`` is ``-``, then
@@ -65,21 +70,24 @@ General Options
 
 .. option:: -print-records
 
- Print all classes and records to standard output (default option).
+ Print all classes and records to standard output (default backend option).
 
 .. option:: -print-detailed-records
 
   Print a detailed report of all global variables, classes, and records
   to standard output.
 
-.. option:: --stats
+.. option:: -stats
 
   Enable statistics output.
 
+.. option:: -time-phases
+
+  Time the parser and backend phases and print a report.
+
 .. option:: -write-if-changed
 
-  Write the output file only if it is new or has changed. The default
+  Write the output file only if it is new or has changed.
-  is true.
 
 llvm-tblgen Options
 ~~~~~~~~~~~~~~~~~~~

docs/TableGen/BackGuide.rst

@@ -824,3 +824,55 @@ parentheses. Each field is shown with its value and the source location at
 which it was set.
 The ``defm`` sequence gives the locations of the ``defm`` statements that
 were involved in generating the record, in the order they were invoked.
+
+Timing TableGen Phases
+----------------------
+
+TableGen provides a phase timing feature that produces a report of the time
+used by the various phases of parsing the source files and running the
+selected backend. This feature is enabled with the ``--time-phases`` option
+of the TableGen command.
+
+If the backend is *not* instrumented for timing, then a report such as the
+following is produced. This is the timing for the
+``--print-detailed-records`` backend run on the AMDGPU target.
+
+.. code-block:: text
+
+  ===-------------------------------------------------------------------------===
+                               TableGen Phase Timing
+  ===-------------------------------------------------------------------------===
+    Total Execution Time: 101.0106 seconds (102.4819 wall clock)
+  
+     ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
+    85.5197 ( 84.9%)   0.1560 ( 50.0%)  85.6757 ( 84.8%)  85.7009 ( 83.6%)  Backend overall
+    15.1789 ( 15.1%)   0.0000 (  0.0%)  15.1789 ( 15.0%)  15.1829 ( 14.8%)  Parse, build records
+     0.0000 (  0.0%)   0.1560 ( 50.0%)   0.1560 (  0.2%)   1.5981 (  1.6%)  Write output
+    100.6986 (100.0%)   0.3120 (100.0%)  101.0106 (100.0%)  102.4819 (100.0%)  Total
+
+Note that all the time for the backend is lumped under "Backend overall".
+
+If the backend is instrumented for timing, then its processing is
+divided into phases and each one timed separately. This is the timing for
+the ``--emit-dag-isel`` backend run on the AMDGPU target.
+
+.. code-block:: text
+
+  ===-------------------------------------------------------------------------===
+                               TableGen Phase Timing
+  ===-------------------------------------------------------------------------===
+    Total Execution Time: 746.3868 seconds (747.1447 wall clock)
+  
+     ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
+    657.7938 ( 88.1%)   0.1404 ( 90.0%)  657.9342 ( 88.1%)  658.6497 ( 88.2%)  Emit matcher table
+    70.2317 (  9.4%)   0.0000 (  0.0%)  70.2317 (  9.4%)  70.2700 (  9.4%)  Convert to matchers
+    14.8825 (  2.0%)   0.0156 ( 10.0%)  14.8981 (  2.0%)  14.9009 (  2.0%)  Parse, build records
+     2.1840 (  0.3%)   0.0000 (  0.0%)   2.1840 (  0.3%)   2.1791 (  0.3%)  Sort patterns
+     1.1388 (  0.2%)   0.0000 (  0.0%)   1.1388 (  0.2%)   1.1401 (  0.2%)  Optimize matchers
+     0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0050 (  0.0%)  Write output
+    746.2308 (100.0%)   0.1560 (100.0%)  746.3868 (100.0%)  747.1447 (100.0%)  Total
+
+The backend has been divided into four phases and timed separately.
+
+If you want to instrument a backend, refer to the backend ``DAGISelEmitter.cpp``
+and search for ``Records.startTimer``.

include/llvm/TableGen/Record.h

@@ -26,6 +26,7 @@
 #include "llvm/Support/SMLoc.h"
 #include "llvm/Support/TrailingObjects.h"
 #include "llvm/Support/raw_ostream.h"
+#include "llvm/Support/timer.h"
 #include <algorithm>
 #include <cassert>
 #include <cstddef>
@@ -1743,6 +1744,13 @@ class RecordKeeper {
   std::map<std::string, Init *, std::less<>> ExtraGlobals;
   unsigned AnonCounter = 0;
 
+  // These members are for the phase timing feature. We need a timer group,
+  // the last timer started, and a flag to say whether the last timer
+  // is the special "backend overall timer."
+  TimerGroup *TimingGroup = nullptr;
+  Timer *LastTimer = nullptr;
+  bool BackendTimer = false;
+
 public:
   /// Get the main TableGen input file's name.
   const std::string getInputFilename() const { return InputFilename; }
@@ -1803,6 +1811,30 @@ public:
 
   Init *getNewAnonymousName();
 
+  /// Start phase timing; called if the --time-phases option is specified.
+  void startPhaseTiming() {
+    TimingGroup = new TimerGroup("TableGen", "TableGen Phase Timing");
+  }
+
+  /// Start timing a phase. Automatically stops any previous phase timer.
+  void startTimer(StringRef Name);
+
+  /// Stop timing a phase.
+  void stopTimer();
+
+  /// Start timing the overall backend. If the backend starts a timer,
+  /// then this timer is cleared.
+  void startBackendTimer(StringRef Name);
+
+  /// Stop timing the overall backend.
+  void stopBackendTimer();
+
+  /// Stop phase timing and print the report.
+  void stopPhaseTiming() {
+    if (TimingGroup)
+      delete TimingGroup;
+  }
+
   //===--------------------------------------------------------------------===//
   // High-level helper methods, useful for tablegen backends.
 

lib/TableGen/Main.cpp

@@ -52,6 +52,9 @@ MacroNames("D", cl::desc("Name of the macro to be defined"),
 static cl::opt<bool>
 WriteIfChanged("write-if-changed", cl::desc("Only write output if it changed"));
 
+static cl::opt<bool>
+TimePhases("time-phases", cl::desc("Time phases of parser and backend"));
+
 static int reportError(const char *ProgName, Twine Msg) {
   errs() << ProgName << ": " << Msg;
   errs().flush();
@@ -83,7 +86,12 @@ static int createDependencyFile(const TGParser &Parser, const char *argv0) {
 int llvm::TableGenMain(const char *argv0, TableGenMainFn *MainFn) {
   RecordKeeper Records;
 
+  if (TimePhases)
+    Records.startPhaseTiming();
+
   // Parse the input file.
+
+  Records.startTimer("Parse, build records");
   ErrorOr<std::unique_ptr<MemoryBuffer>> FileOrErr =
       MemoryBuffer::getFileOrSTDIN(InputFilename);
   if (std::error_code EC = FileOrErr.getError())
@@ -103,11 +111,15 @@ int llvm::TableGenMain(const char *argv0, TableGenMainFn *MainFn) {
 
   if (Parser.ParseFile())
     return 1;
+  Records.stopTimer();
 
   // Write output to memory.
+  Records.startBackendTimer("Backend overall");
   std::string OutString;
   raw_string_ostream Out(OutString);
-  if (MainFn(Out, Records))
+  unsigned status = MainFn(Out, Records);
+  Records.stopBackendTimer();
+  if (status)
     return 1;
 
   // Always write the depfile, even if the main output hasn't changed.
@@ -119,26 +131,31 @@ int llvm::TableGenMain(const char *argv0, TableGenMainFn *MainFn) {
       return Ret;
   }
 
+  Records.startTimer("Write output");
+  bool WriteFile = true;
   if (WriteIfChanged) {
     // Only updates the real output file if there are any differences.
     // This prevents recompilation of all the files depending on it if there
     // aren't any.
     if (auto ExistingOrErr = MemoryBuffer::getFile(OutputFilename))
       if (std::move(ExistingOrErr.get())->getBuffer() == Out.str())
-        return 0;
+        WriteFile = false;
+  }
+  if (WriteFile) {
+    std::error_code EC;
+    ToolOutputFile OutFile(OutputFilename, EC, sys::fs::OF_None);
+    if (EC)
+      return reportError(argv0, "error opening " + OutputFilename + ": " +
+                                    EC.message() + "\n");
+    OutFile.os() << Out.str();
+    if (ErrorsPrinted == 0)
+      OutFile.keep();
   }
   
-  std::error_code EC;
+  Records.stopTimer();
-  ToolOutputFile OutFile(OutputFilename, EC, sys::fs::OF_None);
+  Records.stopPhaseTiming();
-  if (EC)
-    return reportError(argv0, "error opening " + OutputFilename + ":" +
-                                  EC.message() + "\n");
-  OutFile.os() << Out.str();
 
   if (ErrorsPrinted > 0)
     return reportError(argv0, Twine(ErrorsPrinted) + " errors.\n");
-
-  // Declare success.
-  OutFile.keep();
   return 0;
 }

lib/TableGen/Record.cpp

@@ -27,6 +27,7 @@
 #include "llvm/Support/ErrorHandling.h"
 #include "llvm/Support/SMLoc.h"
 #include "llvm/Support/raw_ostream.h"
+#include "llvm/Support/timer.h"
 #include "llvm/TableGen/Error.h"
 #include "llvm/TableGen/Record.h"
 #include <cassert>
@@ -2574,6 +2575,46 @@ Init *RecordKeeper::getNewAnonymousName() {
   return StringInit::get("anonymous_" + utostr(AnonCounter++));
 }
 
+// These functions implement the phase timing facility. Starting a timer
+// when one is already running stops the running one.
+
+void RecordKeeper::startTimer(StringRef Name) {
+  if (TimingGroup) {
+    if (LastTimer && LastTimer->isRunning()) {
+      LastTimer->stopTimer();
+      if (BackendTimer) {
+        LastTimer->clear();
+        BackendTimer = false;
+      }
+    }
+
+    LastTimer = new Timer("", Name, *TimingGroup);
+    LastTimer->startTimer();
+  }
+}
+
+void RecordKeeper::stopTimer() {
+  if (TimingGroup) {
+    assert(LastTimer && "No phase timer was started");
+    LastTimer->stopTimer();
+  }
+}
+
+void RecordKeeper::startBackendTimer(StringRef Name) {
+  if (TimingGroup) {
+    startTimer(Name);
+    BackendTimer = true;
+  }
+}
+
+void RecordKeeper::stopBackendTimer() {
+  if (TimingGroup) {
+    if (BackendTimer)
+      stopTimer();
+      BackendTimer = false;
+  }
+}
+
 std::vector<Record *> RecordKeeper::getAllDerivedDefinitions(
     const ArrayRef<StringRef> ClassNames) const {
   SmallVector<Record *, 2> ClassRecs;

utils/TableGen/CallingConvEmitter.cpp

@@ -38,6 +38,7 @@ void CallingConvEmitter::run(raw_ostream &O) {
 
   // Emit prototypes for all of the non-custom CC's so that they can forward ref
   // each other.
+  Records.startTimer("Emit prototypes");
   for (Record *CC : CCs) {
     if (!CC->getValueAsBit("Custom")) {
       unsigned Pad = CC->getName().size();
@@ -56,6 +57,7 @@ void CallingConvEmitter::run(raw_ostream &O) {
   }
 
   // Emit each non-custom calling convention description in full.
+  Records.startTimer("Emit full descriptions");
   for (Record *CC : CCs) {
     if (!CC->getValueAsBit("Custom"))
       EmitCallingConv(CC, O);

utils/TableGen/CodeGenTarget.cpp

@@ -433,8 +433,6 @@ CodeGenSchedModels &CodeGenTarget::getSchedModels() const {
 }
 
 void CodeGenTarget::ReadInstructions() const {
-  NamedRegionTimer T("Read Instructions", "Time spent reading instructions",
-                     "CodeGenTarget", "CodeGenTarget", TimeRegions);
   std::vector<Record*> Insts = Records.getAllDerivedDefinitions("Instruction");
   if (Insts.size() <= 2)
     PrintFatalError("No 'Instruction' subclasses defined!");

utils/TableGen/DAGISelEmitter.cpp

@@ -23,9 +23,10 @@ namespace {
 /// DAGISelEmitter - The top-level class which coordinates construction
 /// and emission of the instruction selector.
 class DAGISelEmitter {
+  RecordKeeper &Records; // Just so we can get at the timing functions.
   CodeGenDAGPatterns CGP;
 public:
-  explicit DAGISelEmitter(RecordKeeper &R) : CGP(R) {}
+  explicit DAGISelEmitter(RecordKeeper &R) : Records(R), CGP(R) {}
   void run(raw_ostream &OS);
 };
 } // End anonymous namespace
@@ -150,6 +151,7 @@ void DAGISelEmitter::run(raw_ostream &OS) {
              });
 
   // Add all the patterns to a temporary list so we can sort them.
+  Records.startTimer("Sort patterns");
   std::vector<const PatternToMatch*> Patterns;
   for (CodeGenDAGPatterns::ptm_iterator I = CGP.ptm_begin(), E = CGP.ptm_end();
        I != E; ++I)
@@ -160,8 +162,8 @@ void DAGISelEmitter::run(raw_ostream &OS) {
   std::stable_sort(Patterns.begin(), Patterns.end(),
                    PatternSortingPredicate(CGP));
 
-
   // Convert each variant of each pattern into a Matcher.
+  Records.startTimer("Convert to matchers");
   std::vector<Matcher*> PatternMatchers;
   for (unsigned i = 0, e = Patterns.size(); i != e; ++i) {
     for (unsigned Variant = 0; ; ++Variant) {
@@ -175,8 +177,12 @@ void DAGISelEmitter::run(raw_ostream &OS) {
   std::unique_ptr<Matcher> TheMatcher =
     std::make_unique<ScopeMatcher>(PatternMatchers);
 
+  Records.startTimer("Optimize matchers");
   OptimizeMatcher(TheMatcher, CGP);
+
   //Matcher->dump();
+
+  Records.startTimer("Emit matcher table");
   EmitMatcherTable(TheMatcher.get(), CGP, OS);
 }
 

utils/TableGen/GICombinerEmitter.cpp

@@ -346,8 +346,6 @@ void CombineRule::declareMatchData(StringRef PatternSymbol, StringRef Type,
 }
 
 bool CombineRule::parseDefs() {
-  NamedRegionTimer T("parseDefs", "Time spent parsing the defs", "Rule Parsing",
-                     "Time spent on rule parsing", TimeRegions);
   DagInit *Defs = TheDef.getValueAsDag("Defs");
 
   if (Defs->getOperatorAsDef(TheDef.getLoc())->getName() != "defs") {
@@ -488,8 +486,6 @@ bool CombineRule::parseWipMatchOpcodeMatcher(const CodeGenTarget &Target,
   return false;
 }
 bool CombineRule::parseMatcher(const CodeGenTarget &Target) {
-  NamedRegionTimer T("parseMatcher", "Time spent parsing the matcher",
-                     "Rule Parsing", "Time spent on rule parsing", TimeRegions);
   StringMap<std::vector<VarInfo>> NamedEdgeDefs;
   StringMap<std::vector<VarInfo>> NamedEdgeUses;
   DagInit *Matchers = TheDef.getValueAsDag("Match");
@@ -593,6 +589,7 @@ bool CombineRule::parseMatcher(const CodeGenTarget &Target) {
 }
 
 class GICombinerEmitter {
+  RecordKeeper &Records;
   StringRef Name;
   const CodeGenTarget &Target;
   Record *Combiner;
@@ -626,7 +623,7 @@ public:
 GICombinerEmitter::GICombinerEmitter(RecordKeeper &RK,
                                      const CodeGenTarget &Target,
                                      StringRef Name, Record *Combiner)
-    : Name(Name), Target(Target), Combiner(Combiner) {}
+    : Records(RK), Name(Name), Target(Target), Combiner(Combiner) {}
 
 void GICombinerEmitter::emitNameMatcher(raw_ostream &OS) const {
   std::vector<std::pair<std::string, std::string>> Cases;
@@ -850,6 +847,7 @@ static void emitAdditionalHelperMethodArguments(raw_ostream &OS,
 }
 
 void GICombinerEmitter::run(raw_ostream &OS) {
+  Records.startTimer("Gather rules");
   gatherRules(Rules, Combiner->getValueAsListOfDefs("Rules"));
   if (StopAfterParse) {
     MatchDagCtx.print(errs());
@@ -861,11 +859,8 @@ void GICombinerEmitter::run(raw_ostream &OS) {
     PrintFatalError(Combiner->getLoc(), "Failed to parse one or more rules");
   LLVM_DEBUG(dbgs() << "Optimizing tree for " << Rules.size() << " rules\n");
   std::unique_ptr<GIMatchTree> Tree;
+  Records.startTimer("Optimize combiner");
   {
-    NamedRegionTimer T("Optimize", "Time spent optimizing the combiner",
-                       "Code Generation", "Time spent generating code",
-                       TimeRegions);
-
     GIMatchTreeBuilder TreeBuilder(0);
     for (const auto &Rule : Rules) {
       bool HadARoot = false;
@@ -887,9 +882,7 @@ void GICombinerEmitter::run(raw_ostream &OS) {
     return;
   }
 
-  NamedRegionTimer T("Emit", "Time spent emitting the combiner",
+  Records.startTimer("Emit combiner");
-                     "Code Generation", "Time spent generating code",
-                     TimeRegions);
   OS << "#ifdef " << Name.upper() << "_GENCOMBINERHELPER_DEPS\n"
      << "#include \"llvm/ADT/SparseBitVector.h\"\n"
      << "namespace llvm {\n"

utils/TableGen/PseudoLoweringEmitter.cpp

@@ -298,11 +298,13 @@ void PseudoLoweringEmitter::run(raw_ostream &o) {
       Records.getAllDerivedDefinitions(makeArrayRef(Classes));
 
   // Process the pseudo expansion definitions, validating them as we do so.
+  Records.startTimer("Process definitions");
   for (unsigned i = 0, e = Insts.size(); i != e; ++i)
     evaluateExpansion(Insts[i]);
 
   // Generate expansion code to lower the pseudo to an MCInst of the real
   // instruction.
+  Records.startTimer("Emit expansion code");
   emitLoweringEmitter(o);
 }
 

utils/TableGen/RegisterBankEmitter.cpp

@@ -282,6 +282,7 @@ void RegisterBankEmitter::run(raw_ostream &OS) {
   StringRef TargetName = Target.getName();
   const CodeGenRegBank &RegisterClassHierarchy = Target.getRegBank();
 
+  Records.startTimer("Analyze records");
   std::vector<RegisterBank> Banks;
   for (const auto &V : Records.getAllDerivedDefinitions("RegisterBank")) {
     SmallPtrSet<const CodeGenRegisterClass *, 8> VisitedRCs;
@@ -303,6 +304,7 @@ void RegisterBankEmitter::run(raw_ostream &OS) {
   }
 
   // Warn about ambiguous MIR caused by register bank/class name clashes.
+  Records.startTimer("Warn ambiguous");
   for (const auto &Class : RegisterClassHierarchy.getRegClasses()) {
     for (const auto &Bank : Banks) {
       if (Bank.getName().lower() == StringRef(Class.getName()).lower()) {
@@ -315,6 +317,7 @@ void RegisterBankEmitter::run(raw_ostream &OS) {
     }
   }
 
+  Records.startTimer("Emit output");
   emitSourceFileHeader("Register Bank Source Fragments", OS);
   OS << "#ifdef GET_REGBANK_DECLARATIONS\n"
      << "#undef GET_REGBANK_DECLARATIONS\n";

utils/TableGen/RegisterInfoEmitter.cpp

@@ -1616,9 +1616,16 @@ RegisterInfoEmitter::runTargetDesc(raw_ostream &OS, CodeGenTarget &Target,
 
 void RegisterInfoEmitter::run(raw_ostream &OS) {
   CodeGenRegBank &RegBank = Target.getRegBank();
+  Records.startTimer("Print enums");
   runEnums(OS, Target, RegBank);
+
+  Records.startTimer("Print MC registers");
   runMCDesc(OS, Target, RegBank);
+
+  Records.startTimer("Print header fragment");
   runTargetHeader(OS, Target, RegBank);
+
+  Records.startTimer("Print target registers");
   runTargetDesc(OS, Target, RegBank);
 
   if (RegisterInfoDebug)

utils/TableGen/TableGen.cpp

@@ -22,6 +22,7 @@ using namespace llvm;
 enum ActionType {
   PrintRecords,
   PrintDetailedRecords,
+  NullBackend,
   DumpJSON,
   GenEmitter,
   GenRegisterInfo,
@@ -59,9 +60,6 @@ enum ActionType {
 };
 
 namespace llvm {
-/// Storage for TimeRegionsOpt as a global so that backends aren't required to
-/// include CommandLine.h
-bool TimeRegions = false;
 cl::opt<bool> EmitLongStrLiterals(
     "long-string-literals",
     cl::desc("when emitting large string tables, prefer string literals over "
@@ -78,6 +76,8 @@ cl::opt<ActionType> Action(
                    "Print all records to stdout (default)"),
         clEnumValN(PrintDetailedRecords, "print-detailed-records",
                    "Print full details of all records to stdout"),
+        clEnumValN(NullBackend, "null-backend",
+                   "Do nothing after parsing (useful for timing)"),
         clEnumValN(DumpJSON, "dump-json",
                    "Dump all records as machine-readable JSON"),
         clEnumValN(GenEmitter, "gen-emitter", "Generate machine code emitter"),
@@ -145,19 +145,16 @@ cl::opt<std::string> Class("class", cl::desc("Print Enum list for this class"),
                            cl::value_desc("class name"),
                            cl::cat(PrintEnumsCat));
 
-cl::opt<bool, true>
-    TimeRegionsOpt("time-regions",
-                   cl::desc("Time regions of tablegens execution"),
-                   cl::location(TimeRegions));
-
 bool LLVMTableGenMain(raw_ostream &OS, RecordKeeper &Records) {
   switch (Action) {
   case PrintRecords:
-    OS << Records;           // No argument, dump all contents
+    OS << Records;              // No argument, dump all contents
     break;
   case PrintDetailedRecords:
     EmitDetailedRecords(Records, OS);
     break;
+  case NullBackend:             // No backend at all.
+    break;
   case DumpJSON:
     EmitJSON(Records, OS);
     break;