Extend TimeTrace to LLVM's new pass manager

With the addition of the LLD time tracing it made sense to include coverage for LLVM's various passes. Doing so ensures that ThinLTO is also covered with a time trace. Before: {F11333974} After: {F11333928} Reviewed By: rnk Differential Revision: https://reviews.llvm.org/D74516
llvm · Mar 6, 2020 · c5a0601 · c5a0601
1 parent 3669f0e
commit c5a0601
Show file tree

Hide file tree

Showing 7 changed files with 98 additions and 7 deletions.
diff --git a/llvm/include/llvm/Analysis/CGSCCPassManager.h b/llvm/include/llvm/Analysis/CGSCCPassManager.h
@@ -494,7 +494,11 @@ class CGSCCToFunctionPassAdaptor
       if (!PI.runBeforePass<Function>(Pass, F))
         continue;
 
-      PreservedAnalyses PassPA = Pass.run(F, FAM);
+      PreservedAnalyses PassPA;
+      {
+        TimeTraceScope TimeScope(Pass.name());
+        PassPA = Pass.run(F, FAM);
+      }
 
       PI.runAfterPass<Function>(Pass, F);
 
@@ -870,7 +874,11 @@ ModuleToPostOrderCGSCCPassAdaptor<CGSCCPassT>::run(Module &M,
           if (!PI.runBeforePass<LazyCallGraph::SCC>(Pass, *C))
             continue;
 
-          PreservedAnalyses PassPA = Pass.run(*C, CGAM, CG, UR);
+          PreservedAnalyses PassPA;
+          {
+            TimeTraceScope TimeScope(Pass.name());
+            PassPA = Pass.run(*C, CGAM, CG, UR);
+          }
 
           if (UR.InvalidatedSCCs.count(C))
             PI.runAfterPassInvalidated<LazyCallGraph::SCC>(Pass);

diff --git a/llvm/include/llvm/IR/PassManager.h b/llvm/include/llvm/IR/PassManager.h
@@ -47,6 +47,7 @@
 #include "llvm/IR/PassManagerInternal.h"
 #include "llvm/Pass.h"
 #include "llvm/Support/Debug.h"
+#include "llvm/Support/TimeProfiler.h"
 #include "llvm/Support/TypeName.h"
 #include "llvm/Support/raw_ostream.h"
 #include <algorithm>
@@ -513,7 +514,11 @@ class PassManager : public PassInfoMixin<
       if (!PI.runBeforePass<IRUnitT>(*P, IR))
         continue;
 
-      PreservedAnalyses PassPA = P->run(IR, AM, ExtraArgs...);
+      PreservedAnalyses PassPA;
+      {
+        TimeTraceScope TimeScope(P->name(), IR.getName());
+        PassPA = P->run(IR, AM, ExtraArgs...);
+      }
 
       // Call onto PassInstrumentation's AfterPass callbacks immediately after
       // running the pass.
@@ -1199,7 +1204,12 @@ class ModuleToFunctionPassAdaptor
       // false).
       if (!PI.runBeforePass<Function>(Pass, F))
         continue;
-      PreservedAnalyses PassPA = Pass.run(F, FAM);
+
+      PreservedAnalyses PassPA;
+      {
+        TimeTraceScope TimeScope(Pass.name(), F.getName());
+        PassPA = Pass.run(F, FAM);
+      }
 
       PI.runAfterPass(Pass, F);
 

diff --git a/llvm/include/llvm/Transforms/Scalar/LoopPassManager.h b/llvm/include/llvm/Transforms/Scalar/LoopPassManager.h
@@ -316,7 +316,12 @@ class FunctionToLoopPassAdaptor
       // false).
       if (!PI.runBeforePass<Loop>(Pass, *L))
         continue;
-      PreservedAnalyses PassPA = Pass.run(*L, LAM, LAR, Updater);
+
+      PreservedAnalyses PassPA;
+      {
+        TimeTraceScope TimeScope(Pass.name());
+        PassPA = Pass.run(*L, LAM, LAR, Updater);
+      }
 
       // Do not pass deleted Loop into the instrumentation.
       if (Updater.skipCurrentLoop())

diff --git a/llvm/lib/Analysis/CGSCCPassManager.cpp b/llvm/lib/Analysis/CGSCCPassManager.cpp
@@ -24,6 +24,7 @@
 #include "llvm/Support/Casting.h"
 #include "llvm/Support/Debug.h"
 #include "llvm/Support/raw_ostream.h"
+#include "llvm/Support/TimeProfiler.h"
 #include <algorithm>
 #include <cassert>
 #include <iterator>
@@ -77,7 +78,11 @@ PassManager<LazyCallGraph::SCC, CGSCCAnalysisManager, LazyCallGraph &,
     if (!PI.runBeforePass(*Pass, *C))
       continue;
 
-    PreservedAnalyses PassPA = Pass->run(*C, AM, G, UR);
+    PreservedAnalyses PassPA;
+    {
+      TimeTraceScope TimeScope(Pass->name());
+      PassPA = Pass->run(*C, AM, G, UR);
+    }
 
     if (UR.InvalidatedSCCs.count(C))
       PI.runAfterPassInvalidated<LazyCallGraph::SCC>(*Pass);

diff --git a/llvm/lib/Transforms/Scalar/LoopPassManager.cpp b/llvm/lib/Transforms/Scalar/LoopPassManager.cpp
@@ -6,6 +6,7 @@
 //
 //===----------------------------------------------------------------------===//
 
+#include "llvm/Support/TimeProfiler.h"
 #include "llvm/Transforms/Scalar/LoopPassManager.h"
 #include "llvm/Analysis/LoopInfo.h"
 
@@ -41,7 +42,11 @@ PassManager<Loop, LoopAnalysisManager, LoopStandardAnalysisResults &,
     if (!PI.runBeforePass<Loop>(*Pass, L))
       continue;
 
-    PreservedAnalyses PassPA = Pass->run(L, AM, AR, U);
+    PreservedAnalyses PassPA;
+    {
+      TimeTraceScope TimeScope(Pass->name(), L.getName());
+      PassPA = Pass->run(L, AM, AR, U);
+    }
 
     // do not pass deleted Loop into the instrumentation
     if (U.skipCurrentLoop())

diff --git a/llvm/test/Other/new-pm-time-trace.ll b/llvm/test/Other/new-pm-time-trace.ll
@@ -0,0 +1,24 @@
+; RUN: opt -time-trace -time-trace-file %t.json \
+; RUN:     -disable-output -disable-verify \
+; RUN:     -passes='default<O3>' %s
+; RUN: cat %t.json \
+; RUN:  | %python -c 'import json, sys; json.dump(json.loads(sys.stdin.read()), sys.stdout, sort_keys=True, indent=2)' \
+; RUN:  | FileCheck %s
+
+; CHECK: "name": "Total FunctionToLoopPassAdaptor
+
+define void @foo(i1 %x, i8* %p1, i8* %p2) {
+entry:
+  store i8 42, i8* %p1
+  br i1 %x, label %loop, label %exit
+
+loop:
+  %tmp1 = load i8, i8* %p2
+  br label %loop
+
+exit:
+  ret void
+}
+
+declare void @bar()
+
diff --git a/llvm/tools/opt/opt.cpp b/llvm/tools/opt/opt.cpp
@@ -258,6 +258,20 @@ static cl::opt<bool> Coroutines(
   cl::desc("Enable coroutine passes."),
   cl::init(false), cl::Hidden);
 
+static cl::opt<bool> TimeTrace(
+    "time-trace",
+    cl::desc("Record time trace"));
+
+static cl::opt<unsigned> TimeTraceGranularity(
+    "time-trace-granularity",
+    cl::desc("Minimum time granularity (in microseconds) traced by time profiler"),
+    cl::init(500), cl::Hidden);
+
+static cl::opt<std::string>
+    TimeTraceFile("time-trace-file",
+                    cl::desc("Specify time trace file destination"),
+                    cl::value_desc("filename"));
+
 static cl::opt<bool> RemarksWithHotness(
     "pass-remarks-with-hotness",
     cl::desc("With PGO, include profile count in optimization remarks"),
@@ -509,6 +523,24 @@ void exportDebugifyStats(llvm::StringRef Path, const DebugifyStatsMap &Map) {
   }
 }
 
+struct TimeTracerRAII {
+  TimeTracerRAII(StringRef ProgramName) {
+    if (TimeTrace)
+      timeTraceProfilerInitialize(TimeTraceGranularity, ProgramName);
+  }
+  ~TimeTracerRAII() {
+    if (TimeTrace) {
+      if (auto E = timeTraceProfilerWrite(TimeTraceFile, OutputFilename)) {
+        handleAllErrors(std::move(E), [&](const StringError &SE) {
+          errs() << SE.getMessage() << "\n";
+        });
+        return;
+      }
+      timeTraceProfilerCleanup();
+    }
+  }
+};
+
 //===----------------------------------------------------------------------===//
 // main for opt
 //
@@ -576,6 +608,8 @@ int main(int argc, char **argv) {
     return 1;
   }
 
+  TimeTracerRAII TimeTracer(argv[0]);
+
   SMDiagnostic Err;
 
   Context.setDiscardValueNames(DiscardValueNames);