| 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(i: 0, m: std::memory_order_release); |
| 50 | m_nanos_total.store(i: 0, m: std::memory_order_release); |
| 51 | m_count.store(i: 0, m: std::memory_order_release); |
| 52 | Category *expected = g_categories; |
| 53 | do { |
| 54 | m_next = expected; |
| 55 | } while (!g_categories.compare_exchange_weak(p1&: expected, p2: 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(O: this, Name: m_category.GetName()); |
| 63 | TimerStack &stack = GetTimerStackForCurrentThread(); |
| 64 | |
| 65 | stack.push_back(x: this); |
| 66 | if (!g_quiet && stack.size() <= g_display_depth) { |
| 67 | std::lock_guard<std::mutex> lock(GetFileMutex()); |
| 68 | |
| 69 | // Indent |
| 70 | ::fprintf(stdout, format: "%*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: format, arg: args); |
| 75 | va_end(args); |
| 76 | |
| 77 | // Newline |
| 78 | ::fprintf(stdout, format: "\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(O: this, Name: 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, format: "%*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(dur: 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(i: 0, m: std::memory_order_release); |
| 133 | i->m_nanos_total.store(i: 0, m: std::memory_order_release); |
| 134 | i->m_count.store(i: 0, m: 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(m: std::memory_order_acquire); |
| 142 | if (nanos) { |
| 143 | uint64_t nanos_total = i->m_nanos_total.load(m: std::memory_order_acquire); |
| 144 | uint64_t count = i->m_count.load(m: std::memory_order_acquire); |
| 145 | Stats stats{.name: i->m_name, .nanos: nanos, .nanos_total: nanos_total, .count: count}; |
| 146 | sorted.push_back(x: stats); |
| 147 | } |
| 148 | } |
| 149 | if (sorted.empty()) |
| 150 | return; // Later code will break without any elements. |
| 151 | |
| 152 | // Sort by time |
| 153 | llvm::sort(C&: sorted, Comp: CategoryMapIteratorSortCriterion); |
| 154 | |
| 155 | for (const auto &stats : sorted) |
| 156 | s.Printf(format: "%.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 | } |
| 162 | |