Adds `-ftime-trace` option to clang that produces Chrome `chrome://tracing` compatible JSON profiling output dumps.

This change adds hierarchical "time trace" profiling blocks that can be visualized in Chrome, in a "flame chart" style. Each profiling block can have a "detail" string that for example indicates the file being processed, template name being instantiated, function being optimized etc.

This is taken from GitHub PR: https://github.com/aras-p/llvm-project-20170507/pull/2

Patch by Aras Pranckevičius.

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

llvm-svn: 357340

1 files changed, 184 insertions, 0 deletions

diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp
new file mode 100644
index 00000000000..6b999cad71a
--- /dev/null
+++ b/llvm/lib/Support/TimeProfiler.cpp
@@ -0,0 +1,184 @@
+//===-- TimeProfiler.cpp - Hierarchical Time Profiler ---------------------===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+//
+/// \file Hierarchical time profiler implementation.
+//
+//===----------------------------------------------------------------------===//
+
+#include "llvm/Support/TimeProfiler.h"
+#include "llvm/ADT/StringExtras.h"
+#include "llvm/Support/FileSystem.h"
+#include <cassert>
+#include <chrono>
+#include <string>
+#include <unordered_map>
+#include <vector>
+
+using namespace std::chrono;
+
+namespace llvm {
+
+TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
+
+static std::string escapeString(StringRef Src) {
+  std::string OS;
+  for (const unsigned char &C : Src) {
+    switch (C) {
+    case '"':
+    case '/':
+    case '\\':
+    case '\b':
+    case '\f':
+    case '\n':
+    case '\r':
+    case '\t':
+      OS += '\\';
+      OS += C;
+      break;
+    default:
+      if (isPrint(C)) {
+        OS += C;
+      }
+    }
+  }
+  return OS;
+}
+
+typedef duration<steady_clock::rep, steady_clock::period> DurationType;
+typedef std::pair<std::string, DurationType> NameAndDuration;
+
+struct Entry {
+  time_point<steady_clock> Start;
+  DurationType Duration;
+  std::string Name;
+  std::string Detail;
+};
+
+struct TimeTraceProfiler {
+  TimeTraceProfiler() {
+    Stack.reserve(8);
+    Entries.reserve(128);
+    StartTime = steady_clock::now();
+  }
+
+  void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
+    Entry E = {steady_clock::now(), {}, Name, Detail()};
+    Stack.push_back(std::move(E));
+  }
+
+  void end() {
+    assert(!Stack.empty() && "Must call begin() first");
+    auto &E = Stack.back();
+    E.Duration = steady_clock::now() - E.Start;
+
+    // Only include sections longer than 500us.
+    if (duration_cast<microseconds>(E.Duration).count() > 500)
+      Entries.emplace_back(E);
+
+    // Track total time taken by each "name", but only the topmost levels of
+    // them; e.g. if there's a template instantiation that instantiates other
+    // templates from within, we only want to add the topmost one. "topmost"
+    // happens to be the ones that don't have any currently open entries above
+    // itself.
+    if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
+          return Val.Name == E.Name;
+        }) == Stack.rend()) {
+      TotalPerName[E.Name] += E.Duration;
+      CountPerName[E.Name]++;
+    }
+
+    Stack.pop_back();
+  }
+
+  void Write(std::unique_ptr<raw_pwrite_stream> &OS) {
+    assert(Stack.empty() &&
+           "All profiler sections should be ended when calling Write");
+
+    *OS << "{ \"traceEvents\": [\n";
+
+    // Emit all events for the main flame graph.
+    for (const auto &E : Entries) {
+      auto StartUs = duration_cast<microseconds>(E.Start - StartTime).count();
+      auto DurUs = duration_cast<microseconds>(E.Duration).count();
+      *OS << "{ \"pid\":1, \"tid\":0, \"ph\":\"X\", \"ts\":" << StartUs
+          << ", \"dur\":" << DurUs << ", \"name\":\"" << escapeString(E.Name)
+          << "\", \"args\":{ \"detail\":\"" << escapeString(E.Detail)
+          << "\"} },\n";
+    }
+
+    // Emit totals by section name as additional "thread" events, sorted from
+    // longest one.
+    int Tid = 1;
+    std::vector<NameAndDuration> SortedTotals;
+    SortedTotals.reserve(TotalPerName.size());
+    for (const auto &E : TotalPerName) {
+      SortedTotals.push_back(E);
+    }
+    std::sort(SortedTotals.begin(), SortedTotals.end(),
+              [](const NameAndDuration &A, const NameAndDuration &B) {
+                return A.second > B.second;
+              });
+    for (const auto &E : SortedTotals) {
+      auto DurUs = duration_cast<microseconds>(E.second).count();
+      *OS << "{ \"pid\":1, \"tid\":" << Tid << ", \"ph\":\"X\", \"ts\":" << 0
+          << ", \"dur\":" << DurUs << ", \"name\":\"Total "
+          << escapeString(E.first)
+          << "\", \"args\":{ \"count\":" << CountPerName[E.first]
+          << ", \"avg ms\":" << (DurUs / CountPerName[E.first] / 1000)
+          << "} },\n";
+      ++Tid;
+    }
+
+    // Emit metadata event with process name.
+    *OS << "{ \"cat\":\"\", \"pid\":1, \"tid\":0, \"ts\":0, \"ph\":\"M\", "
+           "\"name\":\"process_name\", \"args\":{ \"name\":\"clang\" } }\n";
+    *OS << "] }\n";
+  }
+
+  std::vector<Entry> Stack;
+  std::vector<Entry> Entries;
+  std::unordered_map<std::string, DurationType> TotalPerName;
+  std::unordered_map<std::string, size_t> CountPerName;
+  time_point<steady_clock> StartTime;
+};
+
+void timeTraceProfilerInitialize() {
+  assert(TimeTraceProfilerInstance == nullptr &&
+         "Profiler should not be initialized");
+  TimeTraceProfilerInstance = new TimeTraceProfiler();
+}
+
+void timeTraceProfilerCleanup() {
+  delete TimeTraceProfilerInstance;
+  TimeTraceProfilerInstance = nullptr;
+}
+
+void timeTraceProfilerWrite(std::unique_ptr<raw_pwrite_stream> &OS) {
+  assert(TimeTraceProfilerInstance != nullptr &&
+         "Profiler object can't be null");
+  TimeTraceProfilerInstance->Write(OS);
+}
+
+void timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
+  if (TimeTraceProfilerInstance != nullptr)
+    TimeTraceProfilerInstance->begin(Name, [&]() { return Detail; });
+}
+
+void timeTraceProfilerBegin(StringRef Name,
+                            llvm::function_ref<std::string()> Detail) {
+  if (TimeTraceProfilerInstance != nullptr)
+    TimeTraceProfilerInstance->begin(Name, Detail);
+}
+
+void timeTraceProfilerEnd() {
+  if (TimeTraceProfilerInstance != nullptr)
+    TimeTraceProfilerInstance->end();
+}
+
+} // namespace llvm