lib/Support/TimeProfiler.cpp

   1 //===-- TimeProfiler.cpp - Hierarchical Time Profiler ---------------------===//
   2 //
   3 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
   4 // See https://llvm.org/LICENSE.txt for license information.
   5 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
   6 //
   7 //===----------------------------------------------------------------------===//
   8 //
   9 // This file implements hierarchical time profiler.
  10 //
  11 //===----------------------------------------------------------------------===//
  12
  13 #include "llvm/Support/TimeProfiler.h"
  14 #include "llvm/ADT/StringMap.h"
  15 #include "llvm/Support/CommandLine.h"
  16 #include "llvm/Support/FileSystem.h"
  17 #include "llvm/Support/JSON.h"
  18 #include <cassert>
  19 #include <chrono>
  20 #include <string>
  21 #include <vector>
  22
  23 using namespace std::chrono;
  24
  25 namespace llvm {
  26
  27 TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
  28
  29 typedef duration<steady_clock::rep, steady_clock::period> DurationType;
  30 typedef time_point<steady_clock> TimePointType;
  31 typedef std::pair<size_t, DurationType> CountAndDurationType;
  32 typedef std::pair<std::string, CountAndDurationType>
  33     NameAndCountAndDurationType;
  34
  35 struct Entry {
  36   TimePointType Start;
  37   TimePointType End;
  38   std::string Name;
  39   std::string Detail;
  40
  41   Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt)
  42       : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
  43         Detail(std::move(Dt)){};
  44
  45   // Calculate timings for FlameGraph. Cast time points to microsecond precision
  46   // rather than casting duration. This avoid truncation issues causing inner
  47   // scopes overruning outer scopes.
  48   steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const {
  49     return (time_point_cast<microseconds>(Start) -
  50             time_point_cast<microseconds>(StartTime))
  51         .count();
  52   }
  53
  54   steady_clock::rep getFlameGraphDurUs() const {
  55     return (time_point_cast<microseconds>(End) -
  56             time_point_cast<microseconds>(Start))
  57         .count();
  58   }
  59 };
  60
  61 struct TimeTraceProfiler {
  62   TimeTraceProfiler() {
  63     StartTime = steady_clock::now();
  64   }
  65
  66   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
  67     Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name),
  68                        Detail());
  69   }
  70
  71   void end() {
  72     assert(!Stack.empty() && "Must call begin() first");
  73     auto &E = Stack.back();
  74     E.End = steady_clock::now();
  75
  76     // Check that end times monotonically increase.
  77     assert((Entries.empty() ||
  78             (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
  79              Entries.back().getFlameGraphStartUs(StartTime) +
  80                  Entries.back().getFlameGraphDurUs())) &&
  81            "TimeProfiler scope ended earlier than previous scope");
  82
  83     // Calculate duration at full precision for overall counts.
  84     DurationType Duration = E.End - E.Start;
  85
  86     // Only include sections longer or equal to TimeTraceGranularity msec.
  87     if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
  88       Entries.emplace_back(E);
  89
  90     // Track total time taken by each "name", but only the topmost levels of
  91     // them; e.g. if there's a template instantiation that instantiates other
  92     // templates from within, we only want to add the topmost one. "topmost"
  93     // happens to be the ones that don't have any currently open entries above
  94     // itself.
  95     if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
  96           return Val.Name == E.Name;
  97         }) == Stack.rend()) {
  98       auto &CountAndTotal = CountAndTotalPerName[E.Name];
  99       CountAndTotal.first++;
 100       CountAndTotal.second += Duration;
 101     }
 102
 103     Stack.pop_back();
 104   }
 105
 106   void Write(raw_pwrite_stream &OS) {
 107     assert(Stack.empty() &&
 108            "All profiler sections should be ended when calling Write");
 109     json::OStream J(OS);
 110     J.objectBegin();
 111     J.attributeBegin("traceEvents");
 112     J.arrayBegin();
 113
 114     // Emit all events for the main flame graph.
 115     for (const auto &E : Entries) {
 116       auto StartUs = E.getFlameGraphStartUs(StartTime);
 117       auto DurUs = E.getFlameGraphDurUs();
 118
 119       J.object([&]{
 120         J.attribute("pid", 1);
 121         J.attribute("tid", 0);
 122         J.attribute("ph", "X");
 123         J.attribute("ts", StartUs);
 124         J.attribute("dur", DurUs);
 125         J.attribute("name", E.Name);
 126         J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
 127       });
 128     }
 129
 130     // Emit totals by section name as additional "thread" events, sorted from
 131     // longest one.
 132     int Tid = 1;
 133     std::vector<NameAndCountAndDurationType> SortedTotals;
 134     SortedTotals.reserve(CountAndTotalPerName.size());
 135     for (const auto &E : CountAndTotalPerName)
 136       SortedTotals.emplace_back(E.getKey(), E.getValue());
 137
 138     llvm::sort(SortedTotals.begin(), SortedTotals.end(),
 139                [](const NameAndCountAndDurationType &A,
 140                   const NameAndCountAndDurationType &B) {
 141                  return A.second.second > B.second.second;
 142                });
 143     for (const auto &E : SortedTotals) {
 144       auto DurUs = duration_cast<microseconds>(E.second.second).count();
 145       auto Count = CountAndTotalPerName[E.first].first;
 146
 147       J.object([&]{
 148         J.attribute("pid", 1);
 149         J.attribute("tid", Tid);
 150         J.attribute("ph", "X");
 151         J.attribute("ts", 0);
 152         J.attribute("dur", DurUs);
 153         J.attribute("name", "Total " + E.first);
 154         J.attributeObject("args", [&] {
 155           J.attribute("count", int64_t(Count));
 156           J.attribute("avg ms", int64_t(DurUs / Count / 1000));
 157         });
 158       });
 159
 160       ++Tid;
 161     }
 162
 163     // Emit metadata event with process name.
 164     J.object([&] {
 165       J.attribute("cat", "");
 166       J.attribute("pid", 1);
 167       J.attribute("tid", 0);
 168       J.attribute("ts", 0);
 169       J.attribute("ph", "M");
 170       J.attribute("name", "process_name");
 171       J.attributeObject("args", [&] { J.attribute("name", "clang"); });
 172     });
 173
 174     J.arrayEnd();
 175     J.attributeEnd();
 176     J.objectEnd();
 177   }
 178
 179   SmallVector<Entry, 16> Stack;
 180   SmallVector<Entry, 128> Entries;
 181   StringMap<CountAndDurationType> CountAndTotalPerName;
 182   TimePointType StartTime;
 183
 184   // Minimum time granularity (in microseconds)
 185   unsigned TimeTraceGranularity;
 186 };
 187
 188 void timeTraceProfilerInitialize(unsigned TimeTraceGranularity) {
 189   assert(TimeTraceProfilerInstance == nullptr &&
 190          "Profiler should not be initialized");
 191   TimeTraceProfilerInstance = new TimeTraceProfiler();
 192   TimeTraceProfilerInstance->TimeTraceGranularity = TimeTraceGranularity;
 193 }
 194
 195 void timeTraceProfilerCleanup() {
 196   delete TimeTraceProfilerInstance;
 197   TimeTraceProfilerInstance = nullptr;
 198 }
 199
 200 void timeTraceProfilerWrite(raw_pwrite_stream &OS) {
 201   assert(TimeTraceProfilerInstance != nullptr &&
 202          "Profiler object can't be null");
 203   TimeTraceProfilerInstance->Write(OS);
 204 }
 205
 206 void timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
 207   if (TimeTraceProfilerInstance != nullptr)
 208     TimeTraceProfilerInstance->begin(Name, [&]() { return Detail; });
 209 }
 210
 211 void timeTraceProfilerBegin(StringRef Name,
 212                             llvm::function_ref<std::string()> Detail) {
 213   if (TimeTraceProfilerInstance != nullptr)
 214     TimeTraceProfilerInstance->begin(Name, Detail);
 215 }
 216
 217 void timeTraceProfilerEnd() {
 218   if (TimeTraceProfilerInstance != nullptr)
 219     TimeTraceProfilerInstance->end();
 220 }
 221
 222 } // namespace llvm