lldb/source/Utility/Timer.cpp

   1 //===-- Timer.cpp ---------------------------------------------------------===//
   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 #include "lldb/Utility/Timer.h"
   9 #include "lldb/Utility/Stream.h"
  10 #include "llvm/Support/ManagedStatic.h"
  11 #include "llvm/Support/Signposts.h"
  12
  13 #include <algorithm>
  14 #include <map>
  15 #include <mutex>
  16 #include <utility>
  17 #include <vector>
  18
  19 #include <cassert>
  20 #include <cinttypes>
  21 #include <cstdarg>
  22 #include <cstdio>
  23
  24 using namespace lldb_private;
  25
  26 #define TIMER_INDENT_AMOUNT 2
  27
  28 namespace {
  29 typedef std::vector<Timer *> TimerStack;
  30 static std::atomic<Timer::Category *> g_categories;
  31 } // end of anonymous namespace
  32
  33 /// Allows llvm::Timer to emit signposts when supported.
  34 static llvm::ManagedStatic<llvm::SignpostEmitter> Signposts;
  35
  36 std::atomic<bool> Timer::g_quiet(true);
  37 std::atomic<unsigned> Timer::g_display_depth(0);
  38 static std::mutex &GetFileMutex() {
  39   static std::mutex *g_file_mutex_ptr = new std::mutex();
  40   return *g_file_mutex_ptr;
  41 }
  42
  43 static TimerStack &GetTimerStackForCurrentThread() {
  44   static thread_local TimerStack g_stack;
  45   return g_stack;
  46 }
  47
  48 Timer::Category::Category(const char *cat) : m_name(cat) {
  49   m_nanos.store(0, std::memory_order_release);
  50   m_nanos_total.store(0, std::memory_order_release);
  51   m_count.store(0, std::memory_order_release);
  52   Category *expected = g_categories;
  53   do {
  54     m_next = expected;
  55   } while (!g_categories.compare_exchange_weak(expected, this));
  56 }
  57
  58 void Timer::SetQuiet(bool value) { g_quiet = value; }
  59
  60 Timer::Timer(Timer::Category &category, const char *format, ...)
  61     : m_category(category), m_total_start(std::chrono::steady_clock::now()) {
  62   Signposts->startInterval(this, m_category.GetName());
  63   TimerStack &stack = GetTimerStackForCurrentThread();
  64
  65   stack.push_back(this);
  66   if (!g_quiet && stack.size() <= g_display_depth) {
  67     std::lock_guard<std::mutex> lock(GetFileMutex());
  68
  69     // Indent
  70     ::fprintf(stdout, "%*s", int(stack.size() - 1) * TIMER_INDENT_AMOUNT, "");
  71     // Print formatted string
  72     va_list args;
  73     va_start(args, format);
  74     ::vfprintf(stdout, format, args);
  75     va_end(args);
  76
  77     // Newline
  78     ::fprintf(stdout, "\n");
  79   }
  80 }
  81
  82 Timer::~Timer() {
  83   using namespace std::chrono;
  84
  85   auto stop_time = steady_clock::now();
  86   auto total_dur = stop_time - m_total_start;
  87   auto timer_dur = total_dur - m_child_duration;
  88
  89   Signposts->endInterval(this, m_category.GetName());
  90
  91   TimerStack &stack = GetTimerStackForCurrentThread();
  92   if (!g_quiet && stack.size() <= g_display_depth) {
  93     std::lock_guard<std::mutex> lock(GetFileMutex());
  94     ::fprintf(stdout, "%*s%.9f sec (%.9f sec)\n",
  95               int(stack.size() - 1) * TIMER_INDENT_AMOUNT, "",
  96               duration<double>(total_dur).count(),
  97               duration<double>(timer_dur).count());
  98   }
  99
 100   assert(stack.back() == this);
 101   stack.pop_back();
 102   if (!stack.empty())
 103     stack.back()->ChildDuration(total_dur);
 104
 105   // Keep total results for each category so we can dump results.
 106   m_category.m_nanos += std::chrono::nanoseconds(timer_dur).count();
 107   m_category.m_nanos_total += std::chrono::nanoseconds(total_dur).count();
 108   m_category.m_count++;
 109 }
 110
 111 void Timer::SetDisplayDepth(uint32_t depth) { g_display_depth = depth; }
 112
 113 /* binary function predicate:
 114  * - returns whether a person is less than another person
 115  */
 116 namespace {
 117 struct Stats {
 118   const char *name;
 119   uint64_t nanos;
 120   uint64_t nanos_total;
 121   uint64_t count;
 122 };
 123 } // namespace
 124
 125 static bool CategoryMapIteratorSortCriterion(const Stats &lhs,
 126                                              const Stats &rhs) {
 127   return lhs.nanos > rhs.nanos;
 128 }
 129
 130 void Timer::ResetCategoryTimes() {
 131   for (Category *i = g_categories; i; i = i->m_next) {
 132     i->m_nanos.store(0, std::memory_order_release);
 133     i->m_nanos_total.store(0, std::memory_order_release);
 134     i->m_count.store(0, std::memory_order_release);
 135   }
 136 }
 137
 138 void Timer::DumpCategoryTimes(Stream &s) {
 139   std::vector<Stats> sorted;
 140   for (Category *i = g_categories; i; i = i->m_next) {
 141     uint64_t nanos = i->m_nanos.load(std::memory_order_acquire);
 142     if (nanos) {
 143       uint64_t nanos_total = i->m_nanos_total.load(std::memory_order_acquire);
 144       uint64_t count = i->m_count.load(std::memory_order_acquire);
 145       Stats stats{i->m_name, nanos, nanos_total, count};
 146       sorted.push_back(stats);
 147     }
 148   }
 149   if (sorted.empty())
 150     return; // Later code will break without any elements.
 151
 152   // Sort by time
 153   llvm::sort(sorted, CategoryMapIteratorSortCriterion);
 154
 155   for (const auto &stats : sorted)
 156     s.Printf("%.9f sec (total: %.3fs; child: %.3fs; count: %" PRIu64
 157              ") for %s\n",
 158              stats.nanos / 1000000000., stats.nanos_total / 1000000000.,
 159              (stats.nanos_total - stats.nanos) / 1000000000., stats.count,
 160              stats.name);
 161 }