llvm/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/STLFunctionalExtras.h"
  15 #include "llvm/ADT/StringMap.h"
  16 #include "llvm/Support/JSON.h"
  17 #include "llvm/Support/Path.h"
  18 #include "llvm/Support/Process.h"
  19 #include "llvm/Support/Threading.h"
  20 #include <algorithm>
  21 #include <cassert>
  22 #include <chrono>
  23 #include <mutex>
  24 #include <string>
  25 #include <vector>
  26
  27 using namespace llvm;
  28
  29 namespace {
  30
  31 using std::chrono::duration;
  32 using std::chrono::duration_cast;
  33 using std::chrono::microseconds;
  34 using std::chrono::steady_clock;
  35 using std::chrono::system_clock;
  36 using std::chrono::time_point;
  37 using std::chrono::time_point_cast;
  38
  39 struct TimeTraceProfilerInstances {
  40   std::mutex Lock;
  41   std::vector<TimeTraceProfiler *> List;
  42 };
  43
  44 TimeTraceProfilerInstances &getTimeTraceProfilerInstances() {
  45   static TimeTraceProfilerInstances Instances;
  46   return Instances;
  47 }
  48
  49 } // anonymous namespace
  50
  51 // Per Thread instance
  52 static LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
  53
  54 TimeTraceProfiler *llvm::getTimeTraceProfilerInstance() {
  55   return TimeTraceProfilerInstance;
  56 }
  57
  58 namespace {
  59
  60 using ClockType = steady_clock;
  61 using TimePointType = time_point<ClockType>;
  62 using DurationType = duration<ClockType::rep, ClockType::period>;
  63 using CountAndDurationType = std::pair<size_t, DurationType>;
  64 using NameAndCountAndDurationType =
  65     std::pair<std::string, CountAndDurationType>;
  66
  67 /// Represents an open or completed time section entry to be captured.
  68 struct TimeTraceProfilerEntry {
  69   const TimePointType Start;
  70   TimePointType End;
  71   const std::string Name;
  72   const std::string Detail;
  73
  74   TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
  75                          std::string &&Dt)
  76       : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
  77         Detail(std::move(Dt)) {}
  78
  79   // Calculate timings for FlameGraph. Cast time points to microsecond precision
  80   // rather than casting duration. This avoids truncation issues causing inner
  81   // scopes overruning outer scopes.
  82   ClockType::rep getFlameGraphStartUs(TimePointType StartTime) const {
  83     return (time_point_cast<microseconds>(Start) -
  84             time_point_cast<microseconds>(StartTime))
  85         .count();
  86   }
  87
  88   ClockType::rep getFlameGraphDurUs() const {
  89     return (time_point_cast<microseconds>(End) -
  90             time_point_cast<microseconds>(Start))
  91         .count();
  92   }
  93 };
  94
  95 } // anonymous namespace
  96
  97 struct llvm::TimeTraceProfiler {
  98   TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
  99       : BeginningOfTime(system_clock::now()), StartTime(ClockType::now()),
 100         ProcName(ProcName), Pid(sys::Process::getProcessId()),
 101         Tid(llvm::get_threadid()), TimeTraceGranularity(TimeTraceGranularity) {
 102     llvm::get_thread_name(ThreadName);
 103   }
 104
 105   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
 106     Stack.emplace_back(ClockType::now(), TimePointType(), std::move(Name),
 107                        Detail());
 108   }
 109
 110   void end() {
 111     assert(!Stack.empty() && "Must call begin() first");
 112     TimeTraceProfilerEntry &E = Stack.back();
 113     E.End = ClockType::now();
 114
 115     // Check that end times monotonically increase.
 116     assert((Entries.empty() ||
 117             (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
 118              Entries.back().getFlameGraphStartUs(StartTime) +
 119                  Entries.back().getFlameGraphDurUs())) &&
 120            "TimeProfiler scope ended earlier than previous scope");
 121
 122     // Calculate duration at full precision for overall counts.
 123     DurationType Duration = E.End - E.Start;
 124
 125     // Only include sections longer or equal to TimeTraceGranularity msec.
 126     if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
 127       Entries.emplace_back(E);
 128
 129     // Track total time taken by each "name", but only the topmost levels of
 130     // them; e.g. if there's a template instantiation that instantiates other
 131     // templates from within, we only want to add the topmost one. "topmost"
 132     // happens to be the ones that don't have any currently open entries above
 133     // itself.
 134     if (llvm::none_of(llvm::drop_begin(llvm::reverse(Stack)),
 135                       [&](const TimeTraceProfilerEntry &Val) {
 136                         return Val.Name == E.Name;
 137                       })) {
 138       auto &CountAndTotal = CountAndTotalPerName[E.Name];
 139       CountAndTotal.first++;
 140       CountAndTotal.second += Duration;
 141     }
 142
 143     Stack.pop_back();
 144   }
 145
 146   // Write events from this TimeTraceProfilerInstance and
 147   // ThreadTimeTraceProfilerInstances.
 148   void write(raw_pwrite_stream &OS) {
 149     // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
 150     auto &Instances = getTimeTraceProfilerInstances();
 151     std::lock_guard<std::mutex> Lock(Instances.Lock);
 152     assert(Stack.empty() &&
 153            "All profiler sections should be ended when calling write");
 154     assert(llvm::all_of(Instances.List,
 155                         [](const auto &TTP) { return TTP->Stack.empty(); }) &&
 156            "All profiler sections should be ended when calling write");
 157
 158     json::OStream J(OS);
 159     J.objectBegin();
 160     J.attributeBegin("traceEvents");
 161     J.arrayBegin();
 162
 163     // Emit all events for the main flame graph.
 164     auto writeEvent = [&](const auto &E, uint64_t Tid) {
 165       auto StartUs = E.getFlameGraphStartUs(StartTime);
 166       auto DurUs = E.getFlameGraphDurUs();
 167
 168       J.object([&] {
 169         J.attribute("pid", Pid);
 170         J.attribute("tid", int64_t(Tid));
 171         J.attribute("ph", "X");
 172         J.attribute("ts", StartUs);
 173         J.attribute("dur", DurUs);
 174         J.attribute("name", E.Name);
 175         if (!E.Detail.empty()) {
 176           J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
 177         }
 178       });
 179     };
 180     for (const TimeTraceProfilerEntry &E : Entries)
 181       writeEvent(E, this->Tid);
 182     for (const TimeTraceProfiler *TTP : Instances.List)
 183       for (const TimeTraceProfilerEntry &E : TTP->Entries)
 184         writeEvent(E, TTP->Tid);
 185
 186     // Emit totals by section name as additional "thread" events, sorted from
 187     // longest one.
 188     // Find highest used thread id.
 189     uint64_t MaxTid = this->Tid;
 190     for (const TimeTraceProfiler *TTP : Instances.List)
 191       MaxTid = std::max(MaxTid, TTP->Tid);
 192
 193     // Combine all CountAndTotalPerName from threads into one.
 194     StringMap<CountAndDurationType> AllCountAndTotalPerName;
 195     auto combineStat = [&](const auto &Stat) {
 196       StringRef Key = Stat.getKey();
 197       auto Value = Stat.getValue();
 198       auto &CountAndTotal = AllCountAndTotalPerName[Key];
 199       CountAndTotal.first += Value.first;
 200       CountAndTotal.second += Value.second;
 201     };
 202     for (const auto &Stat : CountAndTotalPerName)
 203       combineStat(Stat);
 204     for (const TimeTraceProfiler *TTP : Instances.List)
 205       for (const auto &Stat : TTP->CountAndTotalPerName)
 206         combineStat(Stat);
 207
 208     std::vector<NameAndCountAndDurationType> SortedTotals;
 209     SortedTotals.reserve(AllCountAndTotalPerName.size());
 210     for (const auto &Total : AllCountAndTotalPerName)
 211       SortedTotals.emplace_back(std::string(Total.getKey()), Total.getValue());
 212
 213     llvm::sort(SortedTotals, [](const NameAndCountAndDurationType &A,
 214                                 const NameAndCountAndDurationType &B) {
 215       return A.second.second > B.second.second;
 216     });
 217
 218     // Report totals on separate threads of tracing file.
 219     uint64_t TotalTid = MaxTid + 1;
 220     for (const NameAndCountAndDurationType &Total : SortedTotals) {
 221       auto DurUs = duration_cast<microseconds>(Total.second.second).count();
 222       auto Count = AllCountAndTotalPerName[Total.first].first;
 223
 224       J.object([&] {
 225         J.attribute("pid", Pid);
 226         J.attribute("tid", int64_t(TotalTid));
 227         J.attribute("ph", "X");
 228         J.attribute("ts", 0);
 229         J.attribute("dur", DurUs);
 230         J.attribute("name", "Total " + Total.first);
 231         J.attributeObject("args", [&] {
 232           J.attribute("count", int64_t(Count));
 233           J.attribute("avg ms", int64_t(DurUs / Count / 1000));
 234         });
 235       });
 236
 237       ++TotalTid;
 238     }
 239
 240     auto writeMetadataEvent = [&](const char *Name, uint64_t Tid,
 241                                   StringRef arg) {
 242       J.object([&] {
 243         J.attribute("cat", "");
 244         J.attribute("pid", Pid);
 245         J.attribute("tid", int64_t(Tid));
 246         J.attribute("ts", 0);
 247         J.attribute("ph", "M");
 248         J.attribute("name", Name);
 249         J.attributeObject("args", [&] { J.attribute("name", arg); });
 250       });
 251     };
 252
 253     writeMetadataEvent("process_name", Tid, ProcName);
 254     writeMetadataEvent("thread_name", Tid, ThreadName);
 255     for (const TimeTraceProfiler *TTP : Instances.List)
 256       writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName);
 257
 258     J.arrayEnd();
 259     J.attributeEnd();
 260
 261     // Emit the absolute time when this TimeProfiler started.
 262     // This can be used to combine the profiling data from
 263     // multiple processes and preserve actual time intervals.
 264     J.attribute("beginningOfTime",
 265                 time_point_cast<microseconds>(BeginningOfTime)
 266                     .time_since_epoch()
 267                     .count());
 268
 269     J.objectEnd();
 270   }
 271
 272   SmallVector<TimeTraceProfilerEntry, 16> Stack;
 273   SmallVector<TimeTraceProfilerEntry, 128> Entries;
 274   StringMap<CountAndDurationType> CountAndTotalPerName;
 275   // System clock time when the session was begun.
 276   const time_point<system_clock> BeginningOfTime;
 277   // Profiling clock time when the session was begun.
 278   const TimePointType StartTime;
 279   const std::string ProcName;
 280   const sys::Process::Pid Pid;
 281   SmallString<0> ThreadName;
 282   const uint64_t Tid;
 283
 284   // Minimum time granularity (in microseconds)
 285   const unsigned TimeTraceGranularity;
 286 };
 287
 288 void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity,
 289                                        StringRef ProcName) {
 290   assert(TimeTraceProfilerInstance == nullptr &&
 291          "Profiler should not be initialized");
 292   TimeTraceProfilerInstance = new TimeTraceProfiler(
 293       TimeTraceGranularity, llvm::sys::path::filename(ProcName));
 294 }
 295
 296 // Removes all TimeTraceProfilerInstances.
 297 // Called from main thread.
 298 void llvm::timeTraceProfilerCleanup() {
 299   delete TimeTraceProfilerInstance;
 300   TimeTraceProfilerInstance = nullptr;
 301
 302   auto &Instances = getTimeTraceProfilerInstances();
 303   std::lock_guard<std::mutex> Lock(Instances.Lock);
 304   for (auto *TTP : Instances.List)
 305     delete TTP;
 306   Instances.List.clear();
 307 }
 308
 309 // Finish TimeTraceProfilerInstance on a worker thread.
 310 // This doesn't remove the instance, just moves the pointer to global vector.
 311 void llvm::timeTraceProfilerFinishThread() {
 312   auto &Instances = getTimeTraceProfilerInstances();
 313   std::lock_guard<std::mutex> Lock(Instances.Lock);
 314   Instances.List.push_back(TimeTraceProfilerInstance);
 315   TimeTraceProfilerInstance = nullptr;
 316 }
 317
 318 void llvm::timeTraceProfilerWrite(raw_pwrite_stream &OS) {
 319   assert(TimeTraceProfilerInstance != nullptr &&
 320          "Profiler object can't be null");
 321   TimeTraceProfilerInstance->write(OS);
 322 }
 323
 324 Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName,
 325                                    StringRef FallbackFileName) {
 326   assert(TimeTraceProfilerInstance != nullptr &&
 327          "Profiler object can't be null");
 328
 329   std::string Path = PreferredFileName.str();
 330   if (Path.empty()) {
 331     Path = FallbackFileName == "-" ? "out" : FallbackFileName.str();
 332     Path += ".time-trace";
 333   }
 334
 335   std::error_code EC;
 336   raw_fd_ostream OS(Path, EC, sys::fs::OF_TextWithCRLF);
 337   if (EC)
 338     return createStringError(EC, "Could not open " + Path);
 339
 340   timeTraceProfilerWrite(OS);
 341   return Error::success();
 342 }
 343
 344 void llvm::timeTraceProfilerBegin(StringRef Name, StringRef Detail) {
 345   if (TimeTraceProfilerInstance != nullptr)
 346     TimeTraceProfilerInstance->begin(std::string(Name),
 347                                      [&]() { return std::string(Detail); });
 348 }
 349
 350 void llvm::timeTraceProfilerBegin(StringRef Name,
 351                                   llvm::function_ref<std::string()> Detail) {
 352   if (TimeTraceProfilerInstance != nullptr)
 353     TimeTraceProfilerInstance->begin(std::string(Name), Detail);
 354 }
 355
 356 void llvm::timeTraceProfilerEnd() {
 357   if (TimeTraceProfilerInstance != nullptr)
 358     TimeTraceProfilerInstance->end();
 359 }