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 | |
24 | namespace scudo { |
25 | |
26 | class TimingManager; |
27 | |
28 | // A simple timer for evaluating execution time of code snippets. It can be used |
29 | // along with TimingManager or standalone. |
30 | class Timer { |
31 | public: |
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 | |
64 | protected: |
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. |
78 | class ScopedTimer : public Timer { |
79 | public: |
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. |
89 | class TimingManager { |
90 | public: |
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 | |
173 | private: |
174 | void getAllImpl(ScopedString &Str) REQUIRES(Mutex) { |
175 | static char [] = "-- Average Operation Time --" ; |
176 | static char [] = "-- Maximum Operation Time --" ; |
177 | static char [] = "-- 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 = 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 | |