SILOptimizer: add an option to profile and measure the runtime of optimization passes.

When enabling the option `-sil-opt-profile-repeat=<n>`, the optimizer runs passes n times and reports the total runtime at the end of the pass pipeline.
This is useful to profile a specific optimization pass with `sil-opt`.
For example, to profile the stack promotion pass:
```
  sil-opt -stack-promotion -sil-opt-profile-repeat=10000 -o /dev/null test.sil
```

Author: eeckstein

include/swift/SILOptimizer/PassManager/PassManager.h

@@ -20,6 +20,7 @@
 #include "llvm/ADT/DenseMap.h"
 #include "llvm/ADT/SmallVector.h"
 #include "llvm/Support/Casting.h"
+#include "llvm/Support/Chrono.h"
 #include "llvm/Support/ErrorHandling.h"
 #include <vector>
 
@@ -203,6 +204,8 @@ class SILPassManager {
   /// pass manager is destroyed.
   DeserializationNotificationHandler *deserializationNotificationHandler;
 
+  std::chrono::nanoseconds totalPassRuntime = std::chrono::nanoseconds(0);
+
   /// C'tor. It creates and registers all analysis passes, which are defined
   /// in Analysis.def. This is private as it should only be used by
   /// ExecuteSILPipelineRequest.

lib/SILOptimizer/PassManager/PassManager.cpp

@@ -37,7 +37,6 @@
 #include "llvm/Support/Debug.h"
 #include "llvm/Support/GraphWriter.h"
 #include "llvm/Support/ManagedStatic.h"
-#include "llvm/Support/Chrono.h"
 
 using namespace swift;
 
@@ -61,6 +60,10 @@ llvm::cl::opt<std::string> SILNumOptPassesToRun(
     "sil-opt-pass-count", llvm::cl::init(""),
     llvm::cl::desc("Stop optimizing after <N> passes or <N>.<M> passes/sub-passes"));
 
+llvm::cl::opt<unsigned> SILOptProfileRepeat(
+    "sil-opt-profile-repeat", llvm::cl::init(1),
+    llvm::cl::desc("repeat passes N times and report the run time"));
+
 llvm::cl::opt<std::string> SILBreakOnFun(
     "sil-break-on-function", llvm::cl::init(""),
     llvm::cl::desc(
@@ -518,7 +521,6 @@ void SILPassManager::runPassOnFunction(unsigned TransIdx, SILFunction *F) {
     F->dump(getOptions().EmitVerboseSIL);
   }
 
-  llvm::sys::TimePoint<> StartTime = std::chrono::system_clock::now();
   if (breakBeforeRunning(F->getName(), SFT))
     LLVM_BUILTIN_DEBUGTRAP;
   if (SILForceVerifyAll ||
@@ -531,31 +533,64 @@ void SILPassManager::runPassOnFunction(unsigned TransIdx, SILFunction *F) {
   assert(changeNotifications == SILAnalysis::InvalidationKind::Nothing
          && "change notifications not cleared");
 
-  swiftPassInvocation.startFunctionPassRun(SFT);
+  llvm::sys::TimePoint<> startTime = std::chrono::system_clock::now();
+  std::chrono::nanoseconds duration(0);
+
+  enum {
+    // In future we might want to make snapshots with positive number (e.g.
+    // corresponding to pass indices). Therefore use -1 here to avoid collisions.
+    SnapshotID = -1
+  };
+
+  unsigned numRepeats = SILOptProfileRepeat;
+  if (numRepeats > 1) {
+    // Need to create a snapshot to restore the original state for consecutive runs.
+    F->createSnapshot(SnapshotID);
+  }
+  for (unsigned runIdx = 0; runIdx < numRepeats; runIdx++) {
+    swiftPassInvocation.startFunctionPassRun(SFT);
+
+    // Run it!
+    SFT->run();
+
+    if (changeNotifications != SILAnalysis::InvalidationKind::Nothing) {
+      // Pause time measurement while invalidating analysis and restoring the snapshot.
+      duration += (std::chrono::system_clock::now() - startTime);
 
-  // Run it!
-  SFT->run();
+      if (runIdx < numRepeats - 1) {
+        invalidateAnalysis(F, SILAnalysis::InvalidationKind::Everything);
+        F->restoreFromSnapshot(SnapshotID);
+      } else {
+        invalidateAnalysis(F, changeNotifications);
+      }
+      changeNotifications = SILAnalysis::InvalidationKind::Nothing;
+      
+      // Continue time measurement (including flushing deleted instructions).
+      startTime = std::chrono::system_clock::now();
+    }
+    Mod->flushDeletedInsts();
+    swiftPassInvocation.finishedFunctionPassRun();
+  }
 
-  if (changeNotifications != SILAnalysis::InvalidationKind::Nothing) {
-    invalidateAnalysis(F, changeNotifications);
-    changeNotifications = SILAnalysis::InvalidationKind::Nothing;
+  duration += (std::chrono::system_clock::now() - startTime);
+  totalPassRuntime += duration;
+  if (SILPrintPassTime) {
+    double milliSecs = (double)duration.count() / 1000000.;
+    llvm::dbgs() << llvm::format("%9.3f", milliSecs) << " ms: " << SFT->getTag()
+                 << " @" << F->getName() << "\n";
   }
-  swiftPassInvocation.finishedFunctionPassRun();
+
+  if (numRepeats > 1)
+    F->deleteSnapshot(SnapshotID);
+
+  assert(analysesUnlocked() && "Expected all analyses to be unlocked!");
 
   if (SILForceVerifyAll ||
       SILForceVerifyAroundPass.end() !=
           std::find_if(SILForceVerifyAroundPass.begin(),
                        SILForceVerifyAroundPass.end(), MatchFun)) {
     verifyAnalyses(F);
   }
-  assert(analysesUnlocked() && "Expected all analyses to be unlocked!");
-  Mod->flushDeletedInsts();
-
-  auto Delta = (std::chrono::system_clock::now() - StartTime).count();
-  if (SILPrintPassTime) {
-    llvm::dbgs() << Delta << " (" << SFT->getID() << "," << F->getName()
-                 << ")\n";
-  }
 
   // If this pass invalidated anything, print and verify.
   if (doPrintAfter(SFT, F, CurrentPassHasInvalidated)) {
@@ -564,7 +599,7 @@ void SILPassManager::runPassOnFunction(unsigned TransIdx, SILFunction *F) {
   }
 
   updateSILModuleStatsAfterTransform(F->getModule(), SFT, *this, NumPassesRun,
-                                     Delta);
+                                     duration.count());
 
   // Remember if this pass didn't change anything.
   if (!CurrentPassHasInvalidated)
@@ -697,9 +732,12 @@ void SILPassManager::runModulePass(unsigned TransIdx) {
   assert(analysesUnlocked() && "Expected all analyses to be unlocked!");
   Mod->flushDeletedInsts();
 
-  auto Delta = (std::chrono::system_clock::now() - StartTime).count();
+  std::chrono::nanoseconds duration = std::chrono::system_clock::now() - StartTime;
+  totalPassRuntime += duration;
+
   if (SILPrintPassTime) {
-    llvm::dbgs() << Delta << " (" << SMT->getID() << ",Module)\n";
+    double milliSecs = (double)duration.count() / 1000000.;
+    llvm::dbgs() << llvm::format("%9.3f", milliSecs) << " ms: " << SMT->getTag() << "\n";
   }
 
   // If this pass invalidated anything, print and verify.
@@ -708,7 +746,7 @@ void SILPassManager::runModulePass(unsigned TransIdx) {
     printModule(Mod, Options.EmitVerboseSIL);
   }
 
-  updateSILModuleStatsAfterTransform(*Mod, SMT, *this, NumPassesRun, Delta);
+  updateSILModuleStatsAfterTransform(*Mod, SMT, *this, NumPassesRun, duration.count());
 
   if (Options.VerifyAll &&
       (CurrentPassHasInvalidated || !SILVerifyWithoutInvalidation)) {
@@ -799,6 +837,12 @@ void SILPassManager::execute() {
 
 /// D'tor.
 SILPassManager::~SILPassManager() {
+
+  if (SILOptProfileRepeat > 1) {
+    double milliSecs = (double)totalPassRuntime.count() / 1000000.;
+    llvm::dbgs() << llvm::format("%9.3f", milliSecs) << " ms: total runtime of all passes\n";
+  }
+
   // Before we do anything further, verify the module and our analyses. These
   // are natural points with which to verify.
   //

test/SILOptimizer/pass_profiling.sil

@@ -0,0 +1,27 @@
+// RUN: %target-sil-opt -stack-promotion -sil-opt-profile-repeat=10 %s -o /dev/null 2>&1 | %FileCheck %s
+
+// REQUIRES: swift_in_compiler
+
+// CHECK: {{.*}} ms: total runtime of all passes
+
+sil_stage canonical
+
+import Builtin
+import Swift
+import SwiftShims
+
+class XX {
+	@_hasStorage var x: Int32
+
+	init()
+}
+
+sil @simple_promote : $@convention(thin) () -> Int32 {
+bb0:
+  %o1 = alloc_ref $XX
+  %l1 = ref_element_addr %o1 : $XX, #XX.x
+  %l2 = load %l1 : $*Int32
+  strong_release %o1 : $XX
+  return %l2 : $Int32
+}
+