[scudo] Add a Timer class to assist performance measurement

[Chia-hungDuan]

Summary

Add Timer and TimingManager which provide convenient way to meause the
execution time of code snippets. The output looks like,

-- Average Operation Time -- -- Name (# of Calls) --
          1747.2(ns)            popBatch (59)
            92.3(ns)            popBatchImpl (73)
           101.6(ns)              EmptyBatchProcess (5)
          2587.0(ns)            pushBlocksImpl (13)

Note that EmptyBatchProcess is nested under the timer popBatchImpl.

[Chia-hungDuan]

Add more comments and make the printing interval configurable

[Chia-hungDuan]

Slightly adjust format

[Chia-hungDuan]

Verify the output only on linux

[Chia-hungDuan]

compiler-rt/lib/scudo/standalone/timing.h

62

Consider accessing the TimingManager from the parent timer.

[Chia-hungDuan]

1. Switch to use ScopedString
2. Change the default size to 50

compiler-rt/lib/scudo/standalone/timing.h

62

Given that Timer can be run without binding to TimingManager, we don't have a simple way to assert the TimingManager is not nullptr in ctor of ScopedTimer. Leave it as it is now

[Chia-hungDuan]

Add ScopedTimer::ignore() to skip some scoped events

[cferris]

compiler-rt/lib/scudo/standalone/timing.h

93

Should this be a CHECK not DCHECK? I would not expect this code to ever really be running in debug mode.

99

Same as above, this seems like it would be better as a CHECK.

110

I think this is supposed to T1.

173

maintenance

201

Don't you need to +1 this value to account for the '\0' terminator?

[Chia-hungDuan]

Address review comment and move the ignore() from ScopedTimer to Timer

compiler-rt/lib/scudo/standalone/timing.h

93

Yep, you're right! Turned all of them to CHECK

201

Oops, you're right! Done.

[cferris]

LGTM

[dyung]

Hi @Chia-hungDuan, your change is causing two test failures on a build bot:

https://lab.llvm.org/buildbot/#/builders/247/builds/2812

/usr/bin/ld: /usr/bin/ld: DWARF error: can't find .debug_ranges section.
/home/buildbot/buildbot-root/llvm-clang-x86_64-gcc-ubuntu/build/./lib/clang/17/lib/x86_64-unknown-linux-gnu/libclang_rt.scudo_standalone.a(timing.cpp.o): in function `scudo::ScopedTimer::~ScopedTimer()':
timing.cpp:(.text._ZN5scudo11ScopedTimerD0Ev[_ZN5scudo11ScopedTimerD5Ev]+0xc9): undefined reference to `operator delete(void*, unsigned long)'
/usr/bin/ld: /home/buildbot/buildbot-root/llvm-clang-x86_64-gcc-ubuntu/build/./lib/clang/17/lib/x86_64-unknown-linux-gnu/libclang_rt.scudo_standalone.a(timing.cpp.o): in function `scudo::Timer::~Timer()':
timing.cpp:(.text._ZN5scudo5TimerD0Ev+0xa0): undefined reference to `operator delete(void*, unsigned long)'
/usr/bin/ld: /home/buildbot/buildbot-root/llvm-clang-x86_64-gcc-ubuntu/build/./lib/clang/17/lib/x86_64-unknown-linux-gnu/libclang_rt.scudo_standalone.a(timing.cpp.o):(.data.rel.ro._ZTIN5scudo5TimerE[_ZTIN5scudo5TimerE]+0x0): undefined reference to `vtable for __cxxabiv1::__class_type_info'
/usr/bin/ld: /home/buildbot/buildbot-root/llvm-clang-x86_64-gcc-ubuntu/build/./lib/clang/17/lib/x86_64-unknown-linux-gnu/libclang_rt.scudo_standalone.a(timing.cpp.o):(.data.rel.ro._ZTIN5scudo11ScopedTimerE[_ZTIN5scudo11ScopedTimerE]+0x0): undefined reference to `vtable for __cxxabiv1::__si_class_type_info'
clang: error: linker command failed with exit code 1 (use -v to see invocation)

Can you take a look?

[Chia-hungDuan]

In D143626#4217786, @dyung wrote:

Hi @Chia-hungDuan, your change is causing two test failures on a build bot:

https://lab.llvm.org/buildbot/#/builders/247/builds/2812

/usr/bin/ld: /usr/bin/ld: DWARF error: can't find .debug_ranges section.
/home/buildbot/buildbot-root/llvm-clang-x86_64-gcc-ubuntu/build/./lib/clang/17/lib/x86_64-unknown-linux-gnu/libclang_rt.scudo_standalone.a(timing.cpp.o): in function `scudo::ScopedTimer::~ScopedTimer()':
timing.cpp:(.text._ZN5scudo11ScopedTimerD0Ev[_ZN5scudo11ScopedTimerD5Ev]+0xc9): undefined reference to `operator delete(void*, unsigned long)'
/usr/bin/ld: /home/buildbot/buildbot-root/llvm-clang-x86_64-gcc-ubuntu/build/./lib/clang/17/lib/x86_64-unknown-linux-gnu/libclang_rt.scudo_standalone.a(timing.cpp.o): in function `scudo::Timer::~Timer()':
timing.cpp:(.text._ZN5scudo5TimerD0Ev+0xa0): undefined reference to `operator delete(void*, unsigned long)'
/usr/bin/ld: /home/buildbot/buildbot-root/llvm-clang-x86_64-gcc-ubuntu/build/./lib/clang/17/lib/x86_64-unknown-linux-gnu/libclang_rt.scudo_standalone.a(timing.cpp.o):(.data.rel.ro._ZTIN5scudo5TimerE[_ZTIN5scudo5TimerE]+0x0): undefined reference to `vtable for __cxxabiv1::__class_type_info'
/usr/bin/ld: /home/buildbot/buildbot-root/llvm-clang-x86_64-gcc-ubuntu/build/./lib/clang/17/lib/x86_64-unknown-linux-gnu/libclang_rt.scudo_standalone.a(timing.cpp.o):(.data.rel.ro._ZTIN5scudo11ScopedTimerE[_ZTIN5scudo11ScopedTimerE]+0x0): undefined reference to `vtable for __cxxabiv1::__si_class_type_info'
clang: error: linker command failed with exit code 1 (use -v to see invocation)

Can you take a look?

Sorry for that. I'm looking into it

[Chia-hungDuan]

I'm going to revert it first

compiler-rt/lib/scudo/standalone/CMakeLists.txt

set(SCUDO_HEADERS
   release.h
   report.h
   rss_limit_checker.h
   secondary.h
   size_class_map.h
   stack_depot.h
   stats.h
   string_utils.h
+  timing.h
   tsd_exclusive.h
   tsd_shared.h
   tsd.h
   vector.h
   wrappers_c_checks.h
   wrappers_c.h
 
   include/scudo/interface.h
   )
 
 set(SCUDO_SOURCES
   checksum.cpp
   common.cpp
   crc32_hw.cpp
   flags_parser.cpp
   flags.cpp
   fuchsia.cpp
   linux.cpp
   release.cpp
   report.cpp
   rss_limit_checker.cpp
   string_utils.cpp
+  timing.cpp
   )
 
 # Enable the necessary instruction set for scudo_crc32.cpp, if available.
 # Newer compiler versions use -mcrc32 rather than -msse4.2.
 if (COMPILER_RT_HAS_MCRC32_FLAG)
   set_source_files_properties(crc32_hw.cpp PROPERTIES COMPILE_FLAGS -mcrc32)
 elseif (COMPILER_RT_HAS_MSSE4_2_FLAG)
   set_source_files_properties(crc32_hw.cpp PROPERTIES COMPILE_FLAGS -msse4.2)

compiler-rt/lib/scudo/standalone/tests/CMakeLists.txt

set(SCUDO_UNIT_TEST_SOURCES
   primary_test.cpp
   quarantine_test.cpp
   release_test.cpp
   report_test.cpp
   secondary_test.cpp
   size_class_map_test.cpp
   stats_test.cpp
   strings_test.cpp
+  timing_test.cpp
   tsd_test.cpp
   vector_test.cpp
   scudo_unit_test_main.cpp
   )
 
 add_scudo_unittest(ScudoUnitTest
   SOURCES ${SCUDO_UNIT_TEST_SOURCES})
 

compiler-rt/lib/scudo/standalone/tests/timing_test.cpp

+//===-- timing_test.cpp -----------------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#include "tests/scudo_unit_test.h"
+
+#include "timing.h"
+
+#include <string>
+
+class ScudoTimingTest : public Test {
+public:
+  void testFunc1() { scudo::ScopedTimer ST(Manager, __func__); }
+
+  void testFunc2() {
+    scudo::ScopedTimer ST(Manager, __func__);
+    testFunc1();
+  }
+
+  void testChainedCalls() {
+    scudo::ScopedTimer ST(Manager, __func__);
+    testFunc2();
+  }
+
+  void printAllTimersStats() { Manager.printAll(); }
+
+  scudo::TimingManager &getTimingManager() { return Manager; }
+
+private:
+  scudo::TimingManager Manager;
+};
+
+// Given that the output of statistics of timers are dumped through
+// `scudo::Printf` which is platform dependent, so we don't have a reliable way
+// to catch the output and verify the details. Now we only verify the number of
+// invocations on linux.
+TEST_F(ScudoTimingTest, SimpleTimer) {
+#if SCUDO_LINUX
+  testing::internal::LogToStderr();
+  testing::internal::CaptureStderr();
+#endif
+
+  testChainedCalls();
+  printAllTimersStats();
+
+#if SCUDO_LINUX
+  std::string output = testing::internal::GetCapturedStderr();
+  EXPECT_TRUE(output.find("testChainedCalls (1)") != std::string::npos);
+  EXPECT_TRUE(output.find("testFunc2 (1)") != std::string::npos);
+  EXPECT_TRUE(output.find("testFunc1 (1)") != std::string::npos);
+#endif
+}
+
+TEST_F(ScudoTimingTest, NestedTimer) {
+#if SCUDO_LINUX
+  testing::internal::LogToStderr();
+  testing::internal::CaptureStderr();
+#endif
+
+  {
+    scudo::ScopedTimer Outer(getTimingManager(), "Outer");
+    {
+      scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Inner1");
+      { scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Inner2"); }
+    }
+  }
+  printAllTimersStats();
+
+#if SCUDO_LINUX
+  std::string output = testing::internal::GetCapturedStderr();
+  EXPECT_TRUE(output.find("Outer (1)") != std::string::npos);
+  EXPECT_TRUE(output.find("Inner1 (1)") != std::string::npos);
+  EXPECT_TRUE(output.find("Inner2 (1)") != std::string::npos);
+#endif
+}

compiler-rt/lib/scudo/standalone/timing.h

+//===-- timing.h ------------------------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#include "common.h"
+#include "mutex.h"
+#include "string_utils.h"
+#include "thread_annotations.h"
+
+#include <string.h>
+
+namespace scudo {
+
+class TimingManager;
+
+// A simple timer for evaluating execution time of code snippets. It can be used
+// along with TimingManager or standalone.
+class Timer {
+public:
+  Timer() = default;
+  Timer(Timer &&Other)
+      : StartTime(0), AccTime(Other.AccTime), Manager(Other.Manager),
+        HandleId(Other.HandleId) {
+    Other.Manager = nullptr;
+  }
+
+  Timer(const Timer &) = delete;
+
+  virtual ~Timer();
+
+  void start() {
+    DCHECK_EQ(StartTime, 0U);
+    StartTime = getMonotonicTime();
+  }
+  void stop() {
+    AccTime += getMonotonicTime() - StartTime;
+    StartTime = 0;
+  }
+  u64 getAccumulatedTime() const { return AccTime; }
+
+protected:
+  friend class TimingManager;
+  Timer(TimingManager &Manager, u32 HandleId)
+      : Manager(&Manager), HandleId(HandleId) {}
+
+  u64 StartTime = 0;
+  u64 AccTime = 0;
+  TimingManager *Manager = nullptr;
+  u32 HandleId;
+};
+
+// A RAII-style wrapper for easy scope execution measurement. Note that in order
+// not to take additional space for the message like `Name`. It only works with
+// TimingManager.
+class ScopedTimer : public Timer {
+public:
+  ScopedTimer(TimingManager &Manager, const char *Name);
+  ScopedTimer(TimingManager &Manager, const Timer &Nest, const char *Name);
+  ~ScopedTimer() override { stop(); }
+};
+
+// In Scudo, the execution time of single run of code snippets may not be
+// useful, we are more interested in the average time from several runs.
+// TimingManager lets the registered timer report their data and reports the
+// average execution time for each timer periodically.
+class TimingManager {
+public:
+  TimingManager(u32 PrintingInterval = DefaultPrintingInterval)
+      : PrintingInterval(PrintingInterval) {}
+  ~TimingManager() {
+    if (NumAllocatedTimers != 0)
+      printAll();
+  }
+
+  Timer getOrCreateTimer(const char *Name) EXCLUDES(Mutex) {
+    ScopedLock L(Mutex);
+
+    DCHECK_LT(strlen(Name), MaxLenOfTimerName);
+    for (u32 I = 0; I < NumAllocatedTimers; ++I) {
+      if (strncmp(Name, Timers[I].Name, MaxLenOfTimerName) == 0)
+        return Timer(*this, I);
+    }
+
+    DCHECK_LT(NumAllocatedTimers, MaxNumberOfTimers);
+    strncpy(Timers[NumAllocatedTimers].Name, Name, MaxLenOfTimerName);
+    TimerRecords[NumAllocatedTimers].AccumulatedTime = 0;
+    TimerRecords[NumAllocatedTimers].Occurrence = 0;
+    return Timer(*this, NumAllocatedTimers++);
+  }
+
+  // Add a sub-Timer associated with another Timer. This is used when we want to
+  // detail the execution time in the scope of a Timer.
+  // For example,
+  //   void Foo() {
+  //     // T2 records the time spent in both first and second tasks.
+  //     ScopedTimer T1(getTimingManager(), "Task1");
+  //     {
+  //       // T2 records the time spent in first task
+  //       ScopedTimer T2(getTimingManager, T1, "Task2");
+  //       // Do first task.
+  //     }
+  //     // Do second task.
+  //   }
+  //
+  // The report will show proper indents to indicate the nested relation like,
+  //   -- Average Operation Time -- -- Name (# of Calls) --
+  //             10.0(ns)            Task1 (1)
+  //              5.0(na)              Task2 (1)
+  Timer nest(const Timer &T, const char *Name) EXCLUDES(Mutex) {
+    Timer Nesting = getOrCreateTimer(Name);
+
+    ScopedLock L(Mutex);
+    DCHECK_NE(Nesting.HandleId, T.HandleId);
+    Timers[Nesting.HandleId].Nesting = T.HandleId;
+    return Nesting;
+  }
+
+  void report(const Timer &T) EXCLUDES(Mutex) {
+    ScopedLock L(Mutex);
+
+    const u32 HandleId = T.HandleId;
+    DCHECK_LT(HandleId, MaxNumberOfTimers);
+    TimerRecords[HandleId].AccumulatedTime += T.getAccumulatedTime();
+    ++TimerRecords[HandleId].Occurrence;
+    ++NumEventsReported;
+    if (NumEventsReported % PrintingInterval == 0)
+      printAllImpl();
+  }
+
+  void printAll() EXCLUDES(Mutex) {
+    ScopedLock L(Mutex);
+    printAllImpl();
+  }
+
+private:
+  void printAllImpl() REQUIRES(Mutex) {
+    static char NameHeader[] = "-- Name (# of Calls) --";
+    static char AvgHeader[] = "-- Average Operation Time --";
+    Printf("%-15s %-15s\n", AvgHeader, NameHeader);
+
+    for (u32 I = 0; I < NumAllocatedTimers; ++I) {
+      if (Timers[I].Nesting != MaxNumberOfTimers)
+        continue;
+      printImpl(I);
+    }
+  }
+
+  void printImpl(const u32 HandleId, const u32 ExtraIndent = 0)
+      REQUIRES(Mutex) {
+    const uptr AccumulatedTime = TimerRecords[HandleId].AccumulatedTime;
+    const uptr Occurrence = TimerRecords[HandleId].Occurrence;
+    const uptr Integral = Occurrence == 0 ? 0 : AccumulatedTime / Occurrence;
+    // Only keep single digit of fraction is enough and it enables easier layout
+    // maintance.
+    const uptr Fraction =
+        Occurrence == 0 ? 0
+                        : ((AccumulatedTime % Occurrence) * 10) / Occurrence;
+
+    Printf("%14zu.%zu(ns) %-11s", Integral, Fraction, " ");
+
+    for (u32 I = 0; I < ExtraIndent; ++I)
+      Printf("%s", "  ");
+    Printf("%s (%zu)\n", Timers[HandleId].Name, Occurrence);
+
+    for (u32 I = 0; I < NumAllocatedTimers; ++I)
+      if (Timers[I].Nesting == HandleId)
+        printImpl(I, ExtraIndent + 1);
+  }
+
+  // Instead of maintaining pages for timer registration, a static buffer is
+  // sufficient for most use cases in Scudo.
+  static constexpr u32 MaxNumberOfTimers = 30;
+  static constexpr u32 MaxLenOfTimerName = 30;
+  static constexpr u32 DefaultPrintingInterval = 100;
+
+  struct Record {
+    uptr AccumulatedTime = 0;
+    uptr Occurrence = 0;
+  };
+
+  struct TimerInfo {
+    char Name[MaxLenOfTimerName];
+    u32 Nesting = MaxNumberOfTimers;
+  };
+
+  HybridMutex Mutex;
+  // The frequency of proactively dumping the timer statistics. For example, the
+  // default setting is to dump the statistics every 100 reported events.
+  u32 PrintingInterval GUARDED_BY(Mutex);
+  uptr NumEventsReported GUARDED_BY(Mutex) = 0;
+  u32 NumAllocatedTimers GUARDED_BY(Mutex) = 0;
+  TimerInfo Timers[MaxNumberOfTimers] GUARDED_BY(Mutex);
+  Record TimerRecords[MaxNumberOfTimers] GUARDED_BY(Mutex);
+};
+
+} // namespace scudo

compiler-rt/lib/scudo/standalone/timing.cpp

+//===-- timing.cpp ----------------------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#include "timing.h"
+
+namespace scudo {
+
+Timer::~Timer() {
+  if (Manager)
+    Manager->report(*this);
+}
+
+ScopedTimer::ScopedTimer(TimingManager &Manager, const char *Name)
+    : Timer(Manager.getOrCreateTimer(Name)) {
+  start();
+}
+
+ScopedTimer::ScopedTimer(TimingManager &Manager, const Timer &Nest,
+                         const char *Name)
+    : Timer(Manager.nest(Nest, Name)) {
+  start();
+}
+
+} // namespace scudo