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