[compiler-rt] 4dc3bcf - Reland "[scudo] Add a Timer class to assist performance measurement"
Chia-hung Duan via llvm-commits
llvm-commits at lists.llvm.org
Mon Apr 3 15:50:46 PDT 2023
Author: Chia-hung Duan
Date: 2023-04-03T22:47:59Z
New Revision: 4dc3bcf0124aba07f885025c903c12f6c4124187
URL: https://github.com/llvm/llvm-project/commit/4dc3bcf0124aba07f885025c903c12f6c4124187
DIFF: https://github.com/llvm/llvm-project/commit/4dc3bcf0124aba07f885025c903c12f6c4124187.diff
LOG: Reland "[scudo] Add a Timer class to assist performance measurement"
This reverts commit 2e9bcadb7c8acaa8f6ec7d807e5666246923e468.
Differential Revision: https://reviews.llvm.org/D146772
Added:
compiler-rt/lib/scudo/standalone/tests/timing_test.cpp
compiler-rt/lib/scudo/standalone/timing.cpp
compiler-rt/lib/scudo/standalone/timing.h
Modified:
compiler-rt/lib/scudo/standalone/CMakeLists.txt
compiler-rt/lib/scudo/standalone/tests/CMakeLists.txt
Removed:
################################################################################
diff --git a/compiler-rt/lib/scudo/standalone/CMakeLists.txt b/compiler-rt/lib/scudo/standalone/CMakeLists.txt
index eefcffd4cfc5..6fcd4deddf71 100644
--- a/compiler-rt/lib/scudo/standalone/CMakeLists.txt
+++ b/compiler-rt/lib/scudo/standalone/CMakeLists.txt
@@ -85,6 +85,7 @@ set(SCUDO_HEADERS
stack_depot.h
stats.h
string_utils.h
+ timing.h
tsd_exclusive.h
tsd_shared.h
tsd.h
@@ -107,6 +108,7 @@ set(SCUDO_SOURCES
report.cpp
rss_limit_checker.cpp
string_utils.cpp
+ timing.cpp
)
# Enable the necessary instruction set for scudo_crc32.cpp, if available.
diff --git a/compiler-rt/lib/scudo/standalone/tests/CMakeLists.txt b/compiler-rt/lib/scudo/standalone/tests/CMakeLists.txt
index 50468d9c6ddc..335e4b7dbd89 100644
--- a/compiler-rt/lib/scudo/standalone/tests/CMakeLists.txt
+++ b/compiler-rt/lib/scudo/standalone/tests/CMakeLists.txt
@@ -105,6 +105,7 @@ set(SCUDO_UNIT_TEST_SOURCES
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
diff --git a/compiler-rt/lib/scudo/standalone/tests/timing_test.cpp b/compiler-rt/lib/scudo/standalone/tests/timing_test.cpp
new file mode 100644
index 000000000000..09a6c3122467
--- /dev/null
+++ b/compiler-rt/lib/scudo/standalone/tests/timing_test.cpp
@@ -0,0 +1,86 @@
+//===-- 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 testIgnoredTimer() {
+ scudo::ScopedTimer ST(Manager, __func__);
+ ST.ignore();
+ }
+
+ 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
+
+ testIgnoredTimer();
+ testChainedCalls();
+ printAllTimersStats();
+
+#if SCUDO_LINUX
+ std::string output = testing::internal::GetCapturedStderr();
+ EXPECT_TRUE(output.find("testIgnoredTimer (1)") == std::string::npos);
+ 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
+}
diff --git a/compiler-rt/lib/scudo/standalone/timing.cpp b/compiler-rt/lib/scudo/standalone/timing.cpp
new file mode 100644
index 000000000000..59ae21d10f0f
--- /dev/null
+++ b/compiler-rt/lib/scudo/standalone/timing.cpp
@@ -0,0 +1,29 @@
+//===-- 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
diff --git a/compiler-rt/lib/scudo/standalone/timing.h b/compiler-rt/lib/scudo/standalone/timing.h
new file mode 100644
index 000000000000..29eb894fa0a0
--- /dev/null
+++ b/compiler-rt/lib/scudo/standalone/timing.h
@@ -0,0 +1,220 @@
+//===-- 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
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef SCUDO_TIMING_H_
+#define SCUDO_TIMING_H_
+
+#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:
+ // The use of Timer without binding to a TimingManager is supposed to do the
+ // timer logging manually. Otherwise, TimingManager will do the logging stuff
+ // for you.
+ Timer() = default;
+ Timer(Timer &&Other)
+ : StartTime(0), AccTime(Other.AccTime), Manager(Other.Manager),
+ HandleId(Other.HandleId) {
+ Other.Manager = nullptr;
+ }
+
+ Timer(const Timer &) = delete;
+
+ ~Timer();
+
+ void start() {
+ CHECK_EQ(StartTime, 0U);
+ StartTime = getMonotonicTime();
+ }
+ void stop() {
+ AccTime += getMonotonicTime() - StartTime;
+ StartTime = 0;
+ }
+ u64 getAccumulatedTime() const { return AccTime; }
+
+ // Unset the bound TimingManager so that we don't report the data back. This
+ // is useful if we only want to track subset of certain scope events.
+ void ignore() {
+ StartTime = 0;
+ AccTime = 0;
+ Manager = nullptr;
+ }
+
+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() { 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);
+
+ CHECK_LT(strlen(Name), MaxLenOfTimerName);
+ for (u32 I = 0; I < NumAllocatedTimers; ++I) {
+ if (strncmp(Name, Timers[I].Name, MaxLenOfTimerName) == 0)
+ return Timer(*this, I);
+ }
+
+ CHECK_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() {
+ // // T1 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(ns) Task2 (1)
+ Timer nest(const Timer &T, const char *Name) EXCLUDES(Mutex) {
+ CHECK_EQ(T.Manager, this);
+ Timer Nesting = getOrCreateTimer(Name);
+
+ ScopedLock L(Mutex);
+ CHECK_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;
+ CHECK_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 --";
+ ScopedString Str;
+ Str.append("%-15s %-15s\n", AvgHeader, NameHeader);
+
+ for (u32 I = 0; I < NumAllocatedTimers; ++I) {
+ if (Timers[I].Nesting != MaxNumberOfTimers)
+ continue;
+ printImpl(Str, I);
+ }
+
+ Str.output();
+ }
+
+ void printImpl(ScopedString &Str, const u32 HandleId,
+ const u32 ExtraIndent = 0) REQUIRES(Mutex) {
+ const u64 AccumulatedTime = TimerRecords[HandleId].AccumulatedTime;
+ const u64 Occurrence = TimerRecords[HandleId].Occurrence;
+ const u64 Integral = Occurrence == 0 ? 0 : AccumulatedTime / Occurrence;
+ // Only keep single digit of fraction is enough and it enables easier layout
+ // maintenance.
+ const u64 Fraction =
+ Occurrence == 0 ? 0
+ : ((AccumulatedTime % Occurrence) * 10) / Occurrence;
+
+ Str.append("%14llu.%llu(ns) %-11s", Integral, Fraction, " ");
+
+ for (u32 I = 0; I < ExtraIndent; ++I)
+ Str.append("%s", " ");
+ Str.append("%s (%llu)\n", Timers[HandleId].Name, Occurrence);
+
+ for (u32 I = 0; I < NumAllocatedTimers; ++I)
+ if (Timers[I].Nesting == HandleId)
+ printImpl(Str, 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 = 50;
+ static constexpr u32 MaxLenOfTimerName = 50;
+ static constexpr u32 DefaultPrintingInterval = 100;
+
+ struct Record {
+ u64 AccumulatedTime = 0;
+ u64 Occurrence = 0;
+ };
+
+ struct TimerInfo {
+ char Name[MaxLenOfTimerName + 1];
+ 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);
+ u64 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
+
+#endif // SCUDO_TIMING_H_
More information about the llvm-commits
mailing list