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 
20 namespace scudo {
21 
22 class TimingManager;
23 
24 // A simple timer for evaluating execution time of code snippets. It can be used
25 // along with TimingManager or standalone.
26 class Timer {
27 public:
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;
Timer(Timer && Other)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 
start()42   void start() {
43     CHECK_EQ(StartTime, 0U);
44     StartTime = getMonotonicTime();
45   }
stop()46   void stop() {
47     AccTime += getMonotonicTime() - StartTime;
48     StartTime = 0;
49   }
getAccumulatedTime()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.
ignore()54   void ignore() {
55     StartTime = 0;
56     AccTime = 0;
57     Manager = nullptr;
58   }
59 
60 protected:
61   friend class TimingManager;
Timer(TimingManager & Manager,u32 HandleId)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.
74 class ScopedTimer : public Timer {
75 public:
76   ScopedTimer(TimingManager &Manager, const char *Name);
77   ScopedTimer(TimingManager &Manager, const Timer &Nest, const char *Name);
~ScopedTimer()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.
85 class TimingManager {
86 public:
87   TimingManager(u32 PrintingInterval = DefaultPrintingInterval)
PrintingInterval(PrintingInterval)88       : PrintingInterval(PrintingInterval) {}
~TimingManager()89   ~TimingManager() {
90     if (NumAllocatedTimers != 0)
91       printAll();
92   }
93 
getOrCreateTimer(const char * Name)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(Name, Timers[I].Name, MaxLenOfTimerName) == 0)
100         return Timer(*this, I);
101     }
102 
103     CHECK_LT(NumAllocatedTimers, MaxNumberOfTimers);
104     strncpy(Timers[NumAllocatedTimers].Name, Name, MaxLenOfTimerName);
105     TimerRecords[NumAllocatedTimers].AccumulatedTime = 0;
106     TimerRecords[NumAllocatedTimers].Occurrence = 0;
107     return Timer(*this, NumAllocatedTimers++);
108   }
109 
110   // Add a sub-Timer associated with another Timer. This is used when we want to
111   // detail the execution time in the scope of a Timer.
112   // For example,
113   //   void Foo() {
114   //     // T1 records the time spent in both first and second tasks.
115   //     ScopedTimer T1(getTimingManager(), "Task1");
116   //     {
117   //       // T2 records the time spent in first task
118   //       ScopedTimer T2(getTimingManager, T1, "Task2");
119   //       // Do first task.
120   //     }
121   //     // Do second task.
122   //   }
123   //
124   // The report will show proper indents to indicate the nested relation like,
125   //   -- Average Operation Time -- -- Name (# of Calls) --
126   //             10.0(ns)            Task1 (1)
127   //              5.0(ns)              Task2 (1)
nest(const Timer & T,const char * Name)128   Timer nest(const Timer &T, const char *Name) EXCLUDES(Mutex) {
129     CHECK_EQ(T.Manager, this);
130     Timer Nesting = getOrCreateTimer(Name);
131 
132     ScopedLock L(Mutex);
133     CHECK_NE(Nesting.HandleId, T.HandleId);
134     Timers[Nesting.HandleId].Nesting = T.HandleId;
135     return Nesting;
136   }
137 
report(const Timer & T)138   void report(const Timer &T) EXCLUDES(Mutex) {
139     ScopedLock L(Mutex);
140 
141     const u32 HandleId = T.HandleId;
142     CHECK_LT(HandleId, MaxNumberOfTimers);
143     TimerRecords[HandleId].AccumulatedTime += T.getAccumulatedTime();
144     ++TimerRecords[HandleId].Occurrence;
145     ++NumEventsReported;
146     if (NumEventsReported % PrintingInterval == 0)
147       printAllImpl();
148   }
149 
printAll()150   void printAll() EXCLUDES(Mutex) {
151     ScopedLock L(Mutex);
152     printAllImpl();
153   }
154 
155 private:
printAllImpl()156   void printAllImpl() REQUIRES(Mutex) {
157     static char NameHeader[] = "-- Name (# of Calls) --";
158     static char AvgHeader[] = "-- Average Operation Time --";
159     ScopedString Str;
160     Str.append("%-15s %-15s\n", AvgHeader, NameHeader);
161 
162     for (u32 I = 0; I < NumAllocatedTimers; ++I) {
163       if (Timers[I].Nesting != MaxNumberOfTimers)
164         continue;
165       printImpl(Str, I);
166     }
167 
168     Str.output();
169   }
170 
171   void printImpl(ScopedString &Str, const u32 HandleId,
REQUIRES(Mutex)172                  const u32 ExtraIndent = 0) REQUIRES(Mutex) {
173     const u64 AccumulatedTime = TimerRecords[HandleId].AccumulatedTime;
174     const u64 Occurrence = TimerRecords[HandleId].Occurrence;
175     const u64 Integral = Occurrence == 0 ? 0 : AccumulatedTime / Occurrence;
176     // Only keep single digit of fraction is enough and it enables easier layout
177     // maintenance.
178     const u64 Fraction =
179         Occurrence == 0 ? 0
180                         : ((AccumulatedTime % Occurrence) * 10) / Occurrence;
181 
182     Str.append("%14" PRId64 ".%" PRId64 "(ns) %-11s", Integral, Fraction, " ");
183 
184     for (u32 I = 0; I < ExtraIndent; ++I)
185       Str.append("%s", "  ");
186     Str.append("%s (%" PRId64 ")\n", Timers[HandleId].Name, Occurrence);
187 
188     for (u32 I = 0; I < NumAllocatedTimers; ++I)
189       if (Timers[I].Nesting == HandleId)
190         printImpl(Str, I, ExtraIndent + 1);
191   }
192 
193   // Instead of maintaining pages for timer registration, a static buffer is
194   // sufficient for most use cases in Scudo.
195   static constexpr u32 MaxNumberOfTimers = 50;
196   static constexpr u32 MaxLenOfTimerName = 50;
197   static constexpr u32 DefaultPrintingInterval = 100;
198 
199   struct Record {
200     u64 AccumulatedTime = 0;
201     u64 Occurrence = 0;
202   };
203 
204   struct TimerInfo {
205     char Name[MaxLenOfTimerName + 1];
206     u32 Nesting = MaxNumberOfTimers;
207   };
208 
209   HybridMutex Mutex;
210   // The frequency of proactively dumping the timer statistics. For example, the
211   // default setting is to dump the statistics every 100 reported events.
212   u32 PrintingInterval GUARDED_BY(Mutex);
213   u64 NumEventsReported GUARDED_BY(Mutex) = 0;
214   u32 NumAllocatedTimers GUARDED_BY(Mutex) = 0;
215   TimerInfo Timers[MaxNumberOfTimers] GUARDED_BY(Mutex);
216   Record TimerRecords[MaxNumberOfTimers] GUARDED_BY(Mutex);
217 };
218 
219 } // namespace scudo
220 
221 #endif // SCUDO_TIMING_H_
222