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