244 lines · c
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-exception6//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_MACROS18// Ensure PRId64 macro is available19#define __STDC_FORMAT_MACROS 120#endif21#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 used29// along with TimingManager or standalone.30class Timer {31public:32 // The use of Timer without binding to a TimingManager is supposed to do the33 // timer logging manually. Otherwise, TimingManager will do the logging stuff34 // 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. This57 // 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 order76// not to take additional space for the message like `Name`. It only works with77// 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 be86// useful, we are more interested in the average time from several runs.87// TimingManager lets the registered timer report their data and reports the88// 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(Name, Timers[I].Name, MaxLenOfTimerName) == 0)104 return Timer(*this, I);105 }106 107 CHECK_LT(NumAllocatedTimers, MaxNumberOfTimers);108 strncpy(Timers[NumAllocatedTimers].Name, Name, 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 to116 // 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 task123 // 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("%-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, 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 layout193 // maintenance.194 const u64 Fraction =195 Occurrence == 0 ? 0196 : ((AccumulatedTime % Occurrence) * 10) / Occurrence;197 198 // Average time.199 Str.append("%14" PRId64 ".%" PRId64 "(ns) %-8s", Integral, Fraction, " ");200 201 // Maximum time.202 Str.append("%16" PRId64 "(ns) %-11s", TimerRecords[HandleId].MaxTime, " ");203 204 // Name and num occurrences.205 for (u32 I = 0; I < ExtraIndent; ++I)206 Str.append("%s", " ");207 Str.append("%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, I, ExtraIndent + 1);212 }213 214 // Instead of maintaining pages for timer registration, a static buffer is215 // 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, the233 // 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 scudo242 243#endif // SCUDO_TIMING_H_244