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 static cl::opt<unsigned> TimeTraceGranularity(
  28     "time-trace-granularity",
  29     cl::desc(
  30         "Minimum time granularity (in microseconds) traced by time profiler"),
  31     cl::init(500));
  32
  33 TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
  34
  35 typedef duration<steady_clock::rep, steady_clock::period> DurationType;
  36 typedef std::pair<size_t, DurationType> CountAndDurationType;
  37 typedef std::pair<std::string, CountAndDurationType>
  38     NameAndCountAndDurationType;
  39
  40 struct Entry {
  41   time_point<steady_clock> Start;
  42   DurationType Duration;
  43   std::string Name;
  44   std::string Detail;
  45
  46   Entry(time_point<steady_clock> &&S, DurationType &&D, std::string &&N,
  47         std::string &&Dt)
  48       : Start(std::move(S)), Duration(std::move(D)), Name(std::move(N)),
  49         Detail(std::move(Dt)){};
  50 };
  51
  52 struct TimeTraceProfiler {
  53   TimeTraceProfiler() {
  54     StartTime = steady_clock::now();
  55   }
  56
  57   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
  58     Stack.emplace_back(steady_clock::now(), DurationType{}, std::move(Name),
  59                        Detail());
  60   }
  61
  62   void end() {
  63     assert(!Stack.empty() && "Must call begin() first");
  64     auto &E = Stack.back();
  65     E.Duration = steady_clock::now() - E.Start;
  66
  67     // Only include sections longer than TimeTraceGranularity msec.
  68     if (duration_cast<microseconds>(E.Duration).count() > TimeTraceGranularity)
  69       Entries.emplace_back(E);
  70
  71     // Track total time taken by each "name", but only the topmost levels of
  72     // them; e.g. if there's a template instantiation that instantiates other
  73     // templates from within, we only want to add the topmost one. "topmost"
  74     // happens to be the ones that don't have any currently open entries above
  75     // itself.
  76     if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {
  77           return Val.Name == E.Name;
  78         }) == Stack.rend()) {
  79       auto &CountAndTotal = CountAndTotalPerName[E.Name];
  80       CountAndTotal.first++;
  81       CountAndTotal.second += E.Duration;
  82     }
  83
  84     Stack.pop_back();
  85   }
  86
  87   void Write(raw_pwrite_stream &OS) {
  88     assert(Stack.empty() &&
  89            "All profiler sections should be ended when calling Write");
  90     json::OStream J(OS);
  91     J.objectBegin();
  92     J.attributeBegin("traceEvents");
  93     J.arrayBegin();
  94
  95     // Emit all events for the main flame graph.
  96     for (const auto &E : Entries) {
  97       auto StartUs = duration_cast<microseconds>(E.Start - StartTime).count();
  98       auto DurUs = duration_cast<microseconds>(E.Duration).count();
  99
 100       J.object([&]{
 101         J.attribute("pid", 1);
 102         J.attribute("tid", 0);
 103         J.attribute("ph", "X");
 104         J.attribute("ts", StartUs);
 105         J.attribute("dur", DurUs);
 106         J.attribute("name", E.Name);
 107         J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
 108       });
 109     }
 110
 111     // Emit totals by section name as additional "thread" events, sorted from
 112     // longest one.
 113     int Tid = 1;
 114     std::vector<NameAndCountAndDurationType> SortedTotals;
 115     SortedTotals.reserve(CountAndTotalPerName.size());
 116     for (const auto &E : CountAndTotalPerName)
 117       SortedTotals.emplace_back(E.getKey(), E.getValue());
 118
 119     llvm::sort(SortedTotals.begin(), SortedTotals.end(),
 120                [](const NameAndCountAndDurationType &A,
 121                   const NameAndCountAndDurationType &B) {
 122                  return A.second.second > B.second.second;
 123                });
 124     for (const auto &E : SortedTotals) {
 125       auto DurUs = duration_cast<microseconds>(E.second.second).count();
 126       auto Count = CountAndTotalPerName[E.first].first;
 127
 128       J.object([&]{
 129         J.attribute("pid", 1);
 130         J.attribute("tid", Tid);
 131         J.attribute("ph", "X");
 132         J.attribute("ts", 0);
 133         J.attribute("dur", DurUs);
 134         J.attribute("name", "Total " + E.first);
 135         J.attributeObject("args", [&] {
 136           J.attribute("count", int64_t(Count));
 137           J.attribute("avg ms", int64_t(DurUs / Count / 1000));
 138         });
 139       });
 140
 141       ++Tid;
 142     }
 143
 144     // Emit metadata event with process name.
 145     J.object([&] {
 146       J.attribute("cat", "");
 147       J.attribute("pid", 1);
 148       J.attribute("tid", 0);
 149       J.attribute("ts", 0);
 150       J.attribute("ph", "M");
 151       J.attribute("name", "process_name");
 152       J.attributeObject("args", [&] { J.attribute("name", "clang"); });
 153     });
 154
 155     J.arrayEnd();
 156     J.attributeEnd();
 157     J.objectEnd();
 158   }
 159
 160   SmallVector<Entry, 16> Stack;
 161   SmallVector<Entry, 128> Entries;
 162   StringMap<CountAndDurationType> CountAndTotalPerName;
 163   time_point<steady_clock> StartTime;
 164 };
 165
 166 void timeTraceProfilerInitialize() {
 167   assert(TimeTraceProfilerInstance == nullptr &&
 168          "Profiler should not be initialized");
 169   TimeTraceProfilerInstance = new TimeTraceProfiler();
 170 }
 171
 172 void timeTraceProfilerCleanup() {
 173   delete TimeTraceProfilerInstance;
 174   TimeTraceProfilerInstance = nullptr;
 175 }
 176
 177 void timeTraceProfilerWrite(raw_pwrite_stream &OS) {
 178   assert(TimeTraceProfilerInstance != nullptr &&
 179          "Profiler object can't be null");
 180   TimeTraceProfilerInstance->Write(OS);
 181 }
 182
 183 void timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
 184   if (TimeTraceProfilerInstance != nullptr)
 185     TimeTraceProfilerInstance->begin(Name, [&]() { return Detail; });
 186 }
 187
 188 void timeTraceProfilerBegin(StringRef Name,
 189                             llvm::function_ref<std::string()> Detail) {
 190   if (TimeTraceProfilerInstance != nullptr)
 191     TimeTraceProfilerInstance->begin(Name, Detail);
 192 }
 193
 194 void timeTraceProfilerEnd() {
 195   if (TimeTraceProfilerInstance != nullptr)
 196     TimeTraceProfilerInstance->end();
 197 }
 198
 199 } // namespace llvm