1//===-- timing.h ------------------------------------------------*- C++ -*-===//
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#ifndef SCUDO_TIMING_H_
10#define SCUDO_TIMING_H_
11
12#include "common.h"
13#include "mutex.h"
14#include "string_utils.h"
15#include "thread_annotations.h"
16
17#include <inttypes.h>
18#include <string.h>
19
20namespace scudo {
21
22class TimingManager;
23
24// A simple timer for evaluating execution time of code snippets. It can be used
25// along with TimingManager or standalone.
26class Timer {
27public:
28 // The use of Timer without binding to a TimingManager is supposed to do the
29 // timer logging manually. Otherwise, TimingManager will do the logging stuff
30 // for you.
31 Timer() = default;
32 Timer(Timer &&Other)
33 : StartTime(0), AccTime(Other.AccTime), Manager(Other.Manager),
34 HandleId(Other.HandleId) {
35 Other.Manager = nullptr;
36 }
37
38 Timer(const Timer &) = delete;
39
40 ~Timer();
41
42 void start() {
43 CHECK_EQ(StartTime, 0U);
44 StartTime = getMonotonicTime();
45 }
46 void stop() {
47 AccTime += getMonotonicTime() - StartTime;
48 StartTime = 0;
49 }
50 u64 getAccumulatedTime() const { return AccTime; }
51
52 // Unset the bound TimingManager so that we don't report the data back. This
53 // is useful if we only want to track subset of certain scope events.
54 void ignore() {
55 StartTime = 0;
56 AccTime = 0;
57 Manager = nullptr;
58 }
59
60protected:
61 friend class TimingManager;
62 Timer(TimingManager &Manager, u32 HandleId)
63 : Manager(&Manager), HandleId(HandleId) {}
64
65 u64 StartTime = 0;
66 u64 AccTime = 0;
67 TimingManager *Manager = nullptr;
68 u32 HandleId;
69};
70
71// A RAII-style wrapper for easy scope execution measurement. Note that in order
72// not to take additional space for the message like `Name`. It only works with
73// TimingManager.
74class ScopedTimer : public Timer {
75public:
76 ScopedTimer(TimingManager &Manager, const char *Name);
77 ScopedTimer(TimingManager &Manager, const Timer &Nest, const char *Name);
78 ~ScopedTimer() { stop(); }
79};
80
81// In Scudo, the execution time of single run of code snippets may not be
82// useful, we are more interested in the average time from several runs.
83// TimingManager lets the registered timer report their data and reports the
84// average execution time for each timer periodically.
85class TimingManager {
86public:
87 TimingManager(u32 PrintingInterval = DefaultPrintingInterval)
88 : PrintingInterval(PrintingInterval) {}
89 ~TimingManager() {
90 if (NumAllocatedTimers != 0)
91 printAll();
92 }
93
94 Timer getOrCreateTimer(const char *Name) EXCLUDES(Mutex) {
95 ScopedLock L(Mutex);
96
97 CHECK_LT(strlen(Name), MaxLenOfTimerName);
98 for (u32 I = 0; I < NumAllocatedTimers; ++I) {
99 if (strncmp(s1: Name, s2: Timers[I].Name, n: MaxLenOfTimerName) == 0)
100 return Timer(*this, I);
101 }
102
103 CHECK_LT(NumAllocatedTimers, MaxNumberOfTimers);
104 strncpy(dest: Timers[NumAllocatedTimers].Name, src: Name, n: MaxLenOfTimerName);
105 TimerRecords[NumAllocatedTimers].AccumulatedTime = 0;
106 TimerRecords[NumAllocatedTimers].Occurrence = 0;
107 TimerRecords[NumAllocatedTimers].MaxTime = 0;
108 return Timer(*this, NumAllocatedTimers++);
109 }
110
111 // Add a sub-Timer associated with another Timer. This is used when we want to
112 // detail the execution time in the scope of a Timer.
113 // For example,
114 // void Foo() {
115 // // T1 records the time spent in both first and second tasks.
116 // ScopedTimer T1(getTimingManager(), "Task1");
117 // {
118 // // T2 records the time spent in first task
119 // ScopedTimer T2(getTimingManager, T1, "Task2");
120 // // Do first task.
121 // }
122 // // Do second task.
123 // }
124 //
125 // The report will show proper indents to indicate the nested relation like,
126 // -- Average Operation Time -- -- Name (# of Calls) --
127 // 10.0(ns) Task1 (1)
128 // 5.0(ns) Task2 (1)
129 Timer nest(const Timer &T, const char *Name) EXCLUDES(Mutex) {
130 CHECK_EQ(T.Manager, this);
131 Timer Nesting = getOrCreateTimer(Name);
132
133 ScopedLock L(Mutex);
134 CHECK_NE(Nesting.HandleId, T.HandleId);
135 Timers[Nesting.HandleId].Nesting = T.HandleId;
136 return Nesting;
137 }
138
139 void report(const Timer &T) EXCLUDES(Mutex) {
140 ScopedLock L(Mutex);
141
142 const u32 HandleId = T.HandleId;
143 CHECK_LT(HandleId, MaxNumberOfTimers);
144 u64 AccTime = T.getAccumulatedTime();
145 TimerRecords[HandleId].AccumulatedTime += AccTime;
146 if (AccTime > TimerRecords[HandleId].MaxTime) {
147 TimerRecords[HandleId].MaxTime = AccTime;
148 }
149 ++TimerRecords[HandleId].Occurrence;
150 ++NumEventsReported;
151 if (NumEventsReported % PrintingInterval == 0) {
152 ScopedString Str;
153 getAllImpl(Str);
154 Str.output();
155 }
156 }
157
158 void printAll() EXCLUDES(Mutex) {
159 ScopedString Str;
160 getAll(Str);
161 Str.output();
162 }
163
164 void getAll(ScopedString &Str) EXCLUDES(Mutex) {
165 ScopedLock L(Mutex);
166 getAllImpl(Str);
167 }
168
169private:
170 void getAllImpl(ScopedString &Str) REQUIRES(Mutex) {
171 static char AvgHeader[] = "-- Average Operation Time --";
172 static char MaxHeader[] = "-- Maximum Operation Time --";
173 static char NameHeader[] = "-- Name (# of Calls) --";
174 Str.append(Format: "%-15s %-15s %-15s\n", AvgHeader, MaxHeader, NameHeader);
175
176 for (u32 I = 0; I < NumAllocatedTimers; ++I) {
177 if (Timers[I].Nesting != MaxNumberOfTimers)
178 continue;
179 getImpl(Str, HandleId: I);
180 }
181 }
182
183 void getImpl(ScopedString &Str, const u32 HandleId, const u32 ExtraIndent = 0)
184 REQUIRES(Mutex) {
185 const u64 AccumulatedTime = TimerRecords[HandleId].AccumulatedTime;
186 const u64 Occurrence = TimerRecords[HandleId].Occurrence;
187 const u64 Integral = Occurrence == 0 ? 0 : AccumulatedTime / Occurrence;
188 // Only keep single digit of fraction is enough and it enables easier layout
189 // maintenance.
190 const u64 Fraction =
191 Occurrence == 0 ? 0
192 : ((AccumulatedTime % Occurrence) * 10) / Occurrence;
193
194 // Average time.
195 Str.append(Format: "%14" PRId64 ".%" PRId64 "(ns) %-8s", Integral, Fraction, " ");
196
197 // Maximum time.
198 Str.append(Format: "%16" PRId64 "(ns) %-11s", TimerRecords[HandleId].MaxTime, " ");
199
200 // Name and num occurrences.
201 for (u32 I = 0; I < ExtraIndent; ++I)
202 Str.append(Format: "%s", " ");
203 Str.append(Format: "%s (%" PRId64 ")\n", Timers[HandleId].Name, Occurrence);
204
205 for (u32 I = 0; I < NumAllocatedTimers; ++I)
206 if (Timers[I].Nesting == HandleId)
207 getImpl(Str, HandleId: I, ExtraIndent: ExtraIndent + 1);
208 }
209
210 // Instead of maintaining pages for timer registration, a static buffer is
211 // sufficient for most use cases in Scudo.
212 static constexpr u32 MaxNumberOfTimers = 50;
213 static constexpr u32 MaxLenOfTimerName = 50;
214 static constexpr u32 DefaultPrintingInterval = 100;
215
216 struct Record {
217 u64 AccumulatedTime = 0;
218 u64 Occurrence = 0;
219 u64 MaxTime = 0;
220 };
221
222 struct TimerInfo {
223 char Name[MaxLenOfTimerName + 1];
224 u32 Nesting = MaxNumberOfTimers;
225 };
226
227 HybridMutex Mutex;
228 // The frequency of proactively dumping the timer statistics. For example, the
229 // default setting is to dump the statistics every 100 reported events.
230 u32 PrintingInterval GUARDED_BY(Mutex);
231 u64 NumEventsReported GUARDED_BY(Mutex) = 0;
232 u32 NumAllocatedTimers GUARDED_BY(Mutex) = 0;
233 TimerInfo Timers[MaxNumberOfTimers] GUARDED_BY(Mutex);
234 Record TimerRecords[MaxNumberOfTimers] GUARDED_BY(Mutex);
235};
236
237} // namespace scudo
238
239#endif // SCUDO_TIMING_H_
240