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 | |