timing.h 6.9 KB

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