Add a new instrumentation for timing pass and analysis execution. This is made available in mlir-opt via the 'pass-timing' and 'pass-timing-display' flags. The 'pass-timing-display' flag toggles between the different available display modes for the timing results. The current display modes are 'list' and 'pipeline', with 'list' representing the default.

Below shows the output for an example mlir-opt command line.

mlir-opt foo.mlir -verify-each=false -cse -canonicalize -cse -cse -pass-timing

list view (-pass-timing-display=list):
* In this mode the results are displayed in a list sorted by total time; with each pass/analysis instance aggregated into one unique result. This mode is similar to the output of 'time-passes' in llvm-opt.

===-------------------------------------------------------------------------===
                      ... Pass execution timing report ...
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0097 seconds (0.0096 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.0051 ( 58.3%)   0.0001 ( 12.2%)   0.0052 ( 53.8%)   0.0052 ( 53.8%)  Canonicalizer
   0.0025 ( 29.1%)   0.0005 ( 58.2%)   0.0031 ( 31.9%)   0.0031 ( 32.0%)  CSE
   0.0011 ( 12.6%)   0.0003 ( 29.7%)   0.0014 ( 14.3%)   0.0014 ( 14.2%)  DominanceInfo
   0.0087 (100.0%)   0.0009 (100.0%)   0.0097 (100.0%)   0.0096 (100.0%)  Total

pipeline view (-pass-timing-display=pipeline):
* In this mode the results are displayed in a nested pipeline view that mirrors the internal pass pipeline that is being executed in the pass manager. This view is useful for understanding specifically which parts of the pipeline are taking the most time, and can also be used to identify when analyses are being invalidated and recomputed.

===-------------------------------------------------------------------------===
                      ... Pass execution timing report ...
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0082 seconds (0.0081 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.0042 (100.0%)   0.0039 (100.0%)   0.0082 (100.0%)   0.0081 (100.0%)  Function Pipeline
   0.0005 ( 11.6%)   0.0008 ( 21.1%)   0.0013 ( 16.1%)   0.0013 ( 16.2%)    CSE
   0.0002 (  5.0%)   0.0004 (  9.3%)   0.0006 (  7.0%)   0.0006 (  7.0%)      (A) DominanceInfo
   0.0026 ( 61.8%)   0.0018 ( 45.6%)   0.0044 ( 54.0%)   0.0044 ( 54.1%)    Canonicalizer
   0.0005 ( 11.7%)   0.0005 ( 13.0%)   0.0010 ( 12.3%)   0.0010 ( 12.4%)    CSE
   0.0003 (  6.1%)   0.0003 (  8.3%)   0.0006 (  7.2%)   0.0006 (  7.1%)      (A) DominanceInfo
   0.0002 (  3.8%)   0.0001 (  2.8%)   0.0003 (  3.3%)   0.0003 (  3.3%)    CSE
   0.0042 (100.0%)   0.0039 (100.0%)   0.0082 (100.0%)   0.0081 (100.0%)  Total

PiperOrigin-RevId: 237825367

mlir/include/mlir/Pass/Pass.h

@@ -181,6 +181,12 @@ namespace detail {
 /// pass execution and handles all of the necessary polymorphic API.
 template <typename IRUnitT, typename PassT, typename BasePassT>
 class PassModel : public BasePassT {
+public:
+  /// Support isa/dyn_cast functionality for the derived pass class.
+  static bool classof(const Pass *pass) {
+    return pass->getPassID() == PassID::getID<PassT>();
+  }
+
 protected:
   PassModel() : BasePassT(PassID::getID<PassT>()) {}
 

mlir/include/mlir/Pass/PassTiming.h

@@ -0,0 +1,109 @@
+//===- PassTiming.h ---------------------------------------------*- C++ -*-===//
+//
+// Copyright 2019 The MLIR Authors.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//   http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+// =============================================================================
+//
+// Pass and analysis execution timing instrumentation.
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef MLIR_PASS_PASSTIMING_H_
+#define MLIR_PASS_PASSTIMING_H_
+
+#include "mlir/Pass/PassInstrumentation.h"
+#include "llvm/ADT/MapVector.h"
+
+namespace llvm {
+class Timer;
+} // end namespace llvm
+
+namespace mlir {
+class Module;
+class Pass;
+
+class PassTiming : public PassInstrumentation {
+public:
+  enum DisplayMode {
+    // In this mode the results are displayed in a list sorted by total time,
+    // with each pass/analysis instance aggregated into one unique result.
+    List,
+
+    // In this mode the results are displayed in a nested pipeline view that
+    // mirrors the internal pass pipeline that is being executed in the pass
+    // manager.
+    Pipeline,
+  };
+
+  PassTiming(DisplayMode displayMode);
+  ~PassTiming();
+
+  /// Print and clear the timing results.
+  void print();
+
+private:
+  /// Setup the instrumentation hooks.
+  void runBeforePass(Pass *pass, const llvm::Any &) override {
+    startPassTimer(pass);
+  }
+  void runAfterPass(Pass *pass, const llvm::Any &) override {
+    stopPassTimer(pass);
+  }
+  void runAfterPassFailed(Pass *pass, const llvm::Any &) override {
+    stopPassTimer(pass);
+  }
+  void runBeforeAnalysis(llvm::StringRef name, AnalysisID *id,
+                         const llvm::Any &) override {
+    startAnalysisTimer(name, id);
+  }
+  void runAfterAnalysis(llvm::StringRef name, AnalysisID *id,
+                        const llvm::Any &) override {
+    stopAnalysisTimer(name, id);
+  }
+
+  /// Start a new timer for the given pass.
+  void startPassTimer(Pass *pass);
+
+  /// Stop a timer for the given pass.
+  void stopPassTimer(Pass *pass);
+
+  /// Start a new timer for the given analysis.
+  void startAnalysisTimer(llvm::StringRef name, AnalysisID *id);
+
+  /// Stop a timer for the given analysis.
+  void stopAnalysisTimer(llvm::StringRef name, AnalysisID *id);
+
+  /// Print the timing result in list mode.
+  void printResultsAsList(llvm::raw_ostream &os);
+
+  /// Print the timing result in pipeline mode.
+  void printResultsAsPipeline(llvm::raw_ostream &os);
+
+  /// Mapping between pass and a respective timer.
+  llvm::MapVector<Pass *, std::unique_ptr<llvm::Timer>> passTimers;
+
+  /// Mapping between [analysis id, pass] and a respective timer.
+  llvm::DenseMap<std::pair<AnalysisID *, Pass *>, std::unique_ptr<llvm::Timer>>
+      analysisTimers;
+
+  /// A pointer to the currently active pass, or null.
+  Pass *activePass = nullptr;
+
+  /// The display mode to use when printing the timing results.
+  DisplayMode displayMode;
+};
+
+} // end namespace mlir
+
+#endif // MLIR_PASS_PASSTIMING_H_

mlir/lib/Pass/PassTiming.cpp

@@ -0,0 +1,234 @@
+//===- PassTiming.cpp -----------------------------------------------------===//
+//
+// Copyright 2019 The MLIR Authors.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//   http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+// =============================================================================
+
+#include "mlir/Pass/PassTiming.h"
+#include "PassDetail.h"
+#include "llvm/ADT/SmallVector.h"
+#include "llvm/ADT/Statistic.h"
+#include "llvm/Support/Format.h"
+#include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/Timer.h"
+
+using namespace mlir;
+using namespace mlir::detail;
+
+constexpr llvm::StringLiteral kPassTimingDescription =
+    "... Pass execution timing report ...";
+
+/// Utility function to return if a pass refers to an adaptor pass. Adaptor
+/// passes are those that internally execute a pipeline, such as the
+/// ModuleToFunctionPassAdaptor.
+static bool isAdaptorPass(Pass *pass) {
+  return isa<ModuleToFunctionPassAdaptor>(pass);
+}
+
+PassTiming::PassTiming(DisplayMode displayMode) : displayMode(displayMode) {}
+
+PassTiming::~PassTiming() { print(); }
+
+/// Print out the current timing information.
+void PassTiming::print() {
+  // Don't print anything if there is no timing data.
+  if (passTimers.empty() && analysisTimers.empty())
+    return;
+
+  switch (displayMode) {
+  case DisplayMode::List:
+    printResultsAsList(*llvm::CreateInfoOutputFile());
+    break;
+  case DisplayMode::Pipeline:
+    printResultsAsPipeline(*llvm::CreateInfoOutputFile());
+    break;
+  }
+
+  // Reset and clear the timers.
+  for (auto &timerPair : passTimers)
+    timerPair.second->clear();
+  for (auto &timerPair : analysisTimers)
+    timerPair.second->clear();
+  passTimers.clear();
+  analysisTimers.clear();
+}
+
+/// Start a new timer for the given pass.
+void PassTiming::startPassTimer(Pass *pass) {
+  std::unique_ptr<llvm::Timer> &timer = passTimers[pass];
+
+  /// If the timer doesn't exist then create a new one.
+  if (!timer) {
+    auto passName = pass->getName();
+    timer.reset(new llvm::Timer(passName, passName));
+  }
+
+  activePass = pass;
+  timer->startTimer();
+}
+
+/// Stop a timer for the given pass.
+void PassTiming::stopPassTimer(Pass *pass) {
+  std::unique_ptr<llvm::Timer> &timer = passTimers[pass];
+  assert(timer && "expected valid timer to stop");
+  timer->stopTimer();
+  activePass = nullptr;
+}
+
+/// Start a new timer for the given analysis.
+void PassTiming::startAnalysisTimer(llvm::StringRef name, AnalysisID *id) {
+  auto &timer = analysisTimers[std::make_pair(id, activePass)];
+
+  /// If the timer doesn't exist then create a new one.
+  if (!timer)
+    timer.reset(new llvm::Timer(name, Twine("(A) " + name).str()));
+  timer->startTimer();
+}
+
+/// Stop a timer for the given analysis.
+void PassTiming::stopAnalysisTimer(llvm::StringRef name, AnalysisID *id) {
+  auto &timer = analysisTimers[std::make_pair(id, activePass)];
+  assert(timer && "expected a valid timer to stop");
+  timer->stopTimer();
+}
+
+/// Print the timing result in list mode.
+void PassTiming::printResultsAsList(llvm::raw_ostream &os) {
+  // Build a map of timer records uniqued by the timer name.
+  llvm::StringMap<llvm::TimeRecord> records;
+  auto addTimer = [&](llvm::Timer *timer) {
+    auto it = records.try_emplace(timer->getName(), timer->getTotalTime());
+    if (!it.second)
+      it.first->second += timer->getTotalTime();
+  };
+
+  // Add all non-adaptor classes to the time records.
+  for (auto &timerPair : passTimers)
+    if (!isAdaptorPass(timerPair.first))
+      addTimer(timerPair.second.get());
+
+  // Add the analysis timers.
+  for (auto &timerPair : analysisTimers)
+    addTimer(timerPair.second.get());
+
+  // Create a timer group for the records and print it out.
+  llvm::TimerGroup timerGroup("pass", kPassTimingDescription, records);
+  timerGroup.print(os);
+}
+
+/// Utility to print the heading information for the pipeline timer.
+/// Note: This is a replication of the header generated by llvm::TimerGroup.
+static void printPipelineTimerHeader(llvm::raw_ostream &os,
+                                     llvm::TimeRecord &pipelineTotal) {
+  os << "===" << std::string(73, '-') << "===\n";
+  // Figure out how many spaces to description name.
+  unsigned Padding = (80 - kPassTimingDescription.size()) / 2;
+  os.indent(Padding) << kPassTimingDescription << '\n';
+  os << "===" << std::string(73, '-') << "===\n";
+
+  // Print the total time.
+  os << llvm::format(
+      "  Total Execution Time: %5.4f seconds (%5.4f wall clock)\n\n",
+      pipelineTotal.getProcessTime(), pipelineTotal.getWallTime());
+
+  // Add the headers for each time section.
+  if (pipelineTotal.getUserTime())
+    os << "   ---User Time---";
+  if (pipelineTotal.getSystemTime())
+    os << "   --System Time--";
+  if (pipelineTotal.getProcessTime())
+    os << "   --User+System--";
+  os << "   ---Wall Time---";
+  if (pipelineTotal.getMemUsed())
+    os << "  ---Mem---";
+  os << "  --- Name ---\n";
+}
+
+/// Print the timing result in pipeline mode.
+void PassTiming::printResultsAsPipeline(llvm::raw_ostream &os) {
+  // Collect the total time information for each of the non-adaptor passes.
+  llvm::TimeRecord pipelineTotal;
+  for (auto &timerPair : passTimers)
+    if (!isAdaptorPass(timerPair.first))
+      pipelineTotal += timerPair.second->getTotalTime();
+
+  // Collect the analysis time records for each pass.
+  llvm::DenseMap<Pass *, std::vector<llvm::Timer *>> passAnalyses;
+  for (auto &timerPair : analysisTimers) {
+    passAnalyses[timerPair.first.second].push_back(timerPair.second.get());
+    pipelineTotal += timerPair.second->getTotalTime();
+  }
+  // Sort each of the analysis timers.
+  for (auto &analysisPair : passAnalyses) {
+    llvm::array_pod_sort(
+        analysisPair.second.begin(), analysisPair.second.end(),
+        [](llvm::Timer *const *lhsTimer, llvm::Timer *const *rhsTimer) -> int {
+          return (*lhsTimer)->getDescription().compare(
+              (*rhsTimer)->getDescription());
+        });
+  }
+
+  // Print out timing header.
+  printPipelineTimerHeader(os, pipelineTotal);
+
+  // Print the formatted timing record.
+  unsigned currentIndent = 0;
+  auto printTimer = [&](llvm::StringRef name, llvm::TimeRecord timeRecord) {
+    timeRecord.print(pipelineTotal, os);
+    os.indent(currentIndent) << name;
+    os << "\n";
+  };
+
+  // Utility to print the timing information for a pass and its analyses.
+  auto printPassTimer = [&](Pass *pass, llvm::Timer *passTimer) {
+    printTimer(passTimer->getDescription(), passTimer->getTotalTime());
+
+    // Print the computed analyses for this pass.
+    currentIndent += 2;
+    for (llvm::Timer *timer : passAnalyses[pass])
+      printTimer(timer->getDescription(), timer->getTotalTime());
+    currentIndent -= 2;
+  };
+
+  // Print the total execution time.
+  for (auto it = passTimers.begin(), e = passTimers.end(); it != e;) {
+    // Handle a ModuleToFunctionAdaptor pass.
+    if (isa<ModuleToFunctionPassAdaptor>(it->first)) {
+      // Print the time for this adaptor as the accumulation of each of the
+      // nested function passes.
+      llvm::TimeRecord total;
+      for (auto fpIt = ++it; fpIt != e && isa<FunctionPassBase>(fpIt->first);) {
+        total += fpIt->second->getTotalTime();
+        for (llvm::Timer *timer : passAnalyses[(fpIt++)->first])
+          total += timer->getTotalTime();
+      }
+      printTimer("Function Pipeline", total);
+
+      // Update the indent and print the time for each of the function passes
+      // within the pipeline.
+      currentIndent += 2;
+      for (; it != e && isa<FunctionPassBase>(it->first); ++it)
+        printPassTimer(it->first, it->second.get());
+      currentIndent -= 2;
+      continue;
+    }
+
+    // Otherwise, we print the pass timer directly.
+    printPassTimer(it->first, it->second.get());
+    ++it;
+  }
+
+  printTimer("Total\n", pipelineTotal);
+  os.flush();
+}

mlir/test/Pass/pass-timing.mlir

@@ -0,0 +1,31 @@
+// RUN: mlir-opt %s -verify-each=true -cse -canonicalize -cse -pass-timing -pass-timing-display=list 2>&1 | FileCheck -check-prefix=LIST %s
+// RUN: mlir-opt %s -verify-each=true -cse -canonicalize -cse -pass-timing -pass-timing-display=pipeline 2>&1 | FileCheck -check-prefix=PIPELINE %s
+
+func @foo() {
+  return
+}
+
+// LIST: Pass execution timing report
+// LIST: Total Execution Time:
+// LIST: Name
+// LIST-DAG: Canonicalizer
+// LIST-DAG: FunctionVerifier
+// LIST-DAG: CSE
+// LIST-DAG: ModuleVerifier
+// LIST-DAG: DominanceInfo
+// LIST: {{.*}} Total
+
+// PIPELINE: Pass execution timing report
+// PIPELINE: Total Execution Time:
+// PIPELINE: Name
+// PIPELINE-NEXT: Function Pipeline
+// PIPELINE-NEXT:   CSE
+// PIPELINE-NEXT:     (A) DominanceInfo
+// PIPELINE-NEXT:   FunctionVerifier
+// PIPELINE-NEXT:   Canonicalizer
+// PIPELINE-NEXT:   FunctionVerifier
+// PIPELINE-NEXT:   CSE
+// PIPELINE-NEXT:     (A) DominanceInfo
+// PIPELINE-NEXT:   FunctionVerifier
+// PIPELINE-NEXT: ModuleVerifier
+// PIPELINE-NEXT: Total

mlir/tools/mlir-opt/mlir-opt.cpp

@@ -30,6 +30,7 @@
 #include "mlir/Parser.h"
 #include "mlir/Pass/Pass.h"
 #include "mlir/Pass/PassManager.h"
+#include "mlir/Pass/PassTiming.h"
 #include "mlir/Support/FileUtilities.h"
 #include "mlir/TensorFlow/ControlFlowOps.h"
 #include "mlir/TensorFlow/Passes.h"
@@ -73,6 +74,18 @@ static cl::opt<bool>
                  cl::desc("Run the verifier after each transformation pass"),
                  cl::init(true));
 
+static cl::opt<bool>
+    passTiming("pass-timing",
+               cl::desc("Display the execution times of each pass"));
+
+static cl::opt<PassTiming::DisplayMode> passTimingDisplayMode(
+    "pass-timing-display", cl::desc("Display method for pass timing data"),
+    cl::init(PassTiming::DisplayMode::List),
+    cl::values(clEnumValN(PassTiming::DisplayMode::List, "list",
+                          "display the results in a list sorted by total time"),
+               clEnumValN(PassTiming::DisplayMode::Pipeline, "pipeline",
+                          "display the results with a nested pipeline view")));
+
 static std::vector<const mlir::PassRegistryEntry *> *passList;
 
 enum OptResult { OptSuccess, OptFailure };
@@ -134,6 +147,14 @@ static OptResult performActions(SourceMgr &sourceMgr, MLIRContext *context) {
   PassManager pm(verifyPasses);
   for (const auto *passEntry : *passList)
     passEntry->addToPipeline(pm);
+
+  // Add any necessary instrumentations.
+  // Note: The pass timing instrumentation should be added first to avoid any
+  // potential "ghost" timing from other instrumentations being unintentionally
+  // included in the timing results.
+  if (passTiming)
+    pm.addInstrumentation(new PassTiming(passTimingDisplayMode));
+
   if (failed(pm.run(module.get())))
     return OptFailure;