Extend TimeTrace to LLVM's new pass manager
authorAndrew Monshizadeh <amonshiz@gmail.com>
Fri, 6 Mar 2020 22:16:19 +0000 (14:16 -0800)
committerReid Kleckner <rnk@google.com>
Fri, 6 Mar 2020 22:45:19 +0000 (14:45 -0800)
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/include/llvm/Analysis/CGSCCPassManager.h
llvm/include/llvm/IR/PassManager.h
llvm/include/llvm/Transforms/Scalar/LoopPassManager.h
llvm/lib/Analysis/CGSCCPassManager.cpp
llvm/lib/Transforms/Scalar/LoopPassManager.cpp
llvm/test/Other/new-pm-time-trace.ll [new file with mode: 0644]
llvm/tools/opt/opt.cpp

index 3e14a84..6e3b4aa 100644 (file)
@@ -494,7 +494,11 @@ public:
       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);
index 751c8f8..758ede0 100644 (file)
@@ -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 @@ public:
       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 @@ public:
       // 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);
 
index 9bbf39c..0018cc6 100644 (file)
@@ -316,7 +316,12 @@ public:
       // 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())
index 0aa1704..e83b6a3 100644 (file)
@@ -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);
index f3bfbd3..cc083c2 100644 (file)
@@ -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
new file mode 100644 (file)
index 0000000..07d0e2b
--- /dev/null
@@ -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()
+
index fe2500a..b0700ad 100644 (file)
@@ -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);