[compiler-rt] [scudo] Add a maximum value into the timer. (PR #96989)
via llvm-commits
llvm-commits at lists.llvm.org
Thu Jun 27 17:57:13 PDT 2024
llvmbot wrote:
<!--LLVM PR SUMMARY COMMENT-->
@llvm/pr-subscribers-compiler-rt-sanitizer
Author: Christopher Ferris (cferris1000)
<details>
<summary>Changes</summary>
Modify the timer code to keep track of the maximum time that any call takes.
Add a method to get a ScopedString representing the timer data. Allows the testing of the timer on all platforms.
Add new unit tests for the maximum, and a lot of new tests.
---
Full diff: https://github.com/llvm/llvm-project/pull/96989.diff
2 Files Affected:
- (modified) compiler-rt/lib/scudo/standalone/tests/timing_test.cpp (+202-27)
- (modified) compiler-rt/lib/scudo/standalone/timing.h (+33-15)
``````````diff
diff --git a/compiler-rt/lib/scudo/standalone/tests/timing_test.cpp b/compiler-rt/lib/scudo/standalone/tests/timing_test.cpp
index 09a6c31224673..23f0a02ea4277 100644
--- a/compiler-rt/lib/scudo/standalone/tests/timing_test.cpp
+++ b/compiler-rt/lib/scudo/standalone/tests/timing_test.cpp
@@ -10,6 +10,7 @@
#include "timing.h"
+#include <cstdlib>
#include <string>
class ScudoTimingTest : public Test {
@@ -33,41 +34,36 @@ class ScudoTimingTest : public Test {
void printAllTimersStats() { Manager.printAll(); }
+ void getAllTimersStats(scudo::ScopedString &Str) { Manager.getAll(Str); }
+
scudo::TimingManager &getTimingManager() { return Manager; }
+ void testCallTimers() {
+ scudo::ScopedTimer Outer(getTimingManager(), "Level1");
+ {
+ scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Level2");
+ { scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Level3"); }
+ }
+ }
+
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();
+ scudo::ScopedString Str;
+ getAllTimersStats(Str);
-#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
+ std::string Output(Str.data());
+ 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);
}
TEST_F(ScudoTimingTest, NestedTimer) {
-#if SCUDO_LINUX
- testing::internal::LogToStderr();
- testing::internal::CaptureStderr();
-#endif
-
{
scudo::ScopedTimer Outer(getTimingManager(), "Outer");
{
@@ -75,12 +71,191 @@ TEST_F(ScudoTimingTest, NestedTimer) {
{ scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Inner2"); }
}
}
- printAllTimersStats();
+ scudo::ScopedString Str;
+ getAllTimersStats(Str);
+
+ std::string Output(Str.data());
+ 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);
+}
+
+TEST_F(ScudoTimingTest, VerifyChainedTimerCalculations) {
+ {
+ scudo::ScopedTimer Outer(getTimingManager(), "Level1");
+ sleep(1);
+ {
+ scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Level2");
+ sleep(2);
+ {
+ scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Level3");
+ sleep(3);
+ }
+ }
+ }
+ scudo::ScopedString Str;
+ getAllTimersStats(Str);
+ std::string Output(Str.data());
+
+ // Get the individual timer values for the average and maximum, then
+ // verify that the timer values are being calculated properly.
+ Output = Output.substr(Output.find('\n') + 1);
+ char *end;
+ unsigned long long Level1AvgNs = std::strtoull(Output.c_str(), &end, 10);
+ ASSERT_TRUE(end != nullptr);
+ unsigned long long Level1MaxNs = std::strtoull(&end[6], &end, 10);
+ ASSERT_TRUE(end != nullptr);
+ EXPECT_EQ(Level1AvgNs, Level1MaxNs);
+
+ Output = Output.substr(Output.find('\n') + 1);
+ unsigned long long Level2AvgNs = std::strtoull(Output.c_str(), &end, 10);
+ ASSERT_TRUE(end != nullptr);
+ unsigned long long Level2MaxNs = std::strtoull(&end[6], &end, 10);
+ ASSERT_TRUE(end != nullptr);
+ EXPECT_EQ(Level2AvgNs, Level2MaxNs);
+
+ Output = Output.substr(Output.find('\n') + 1);
+ unsigned long long Level3AvgNs = std::strtoull(Output.c_str(), &end, 10);
+ ASSERT_TRUE(end != nullptr);
+ unsigned long long Level3MaxNs = std::strtoull(&end[6], &end, 10);
+ ASSERT_TRUE(end != nullptr);
+ EXPECT_EQ(Level3AvgNs, Level3MaxNs);
+
+ EXPECT_GT(Level1AvgNs, Level2AvgNs);
+ EXPECT_GT(Level2AvgNs, Level3AvgNs);
+
+ // The time for the first timer needs to be at least six seconds.
+ EXPECT_GT(Level1AvgNs, 6000000000U);
+ // The time for the second timer needs to be at least five seconds.
+ EXPECT_GT(Level2AvgNs, 5000000000U);
+ // The time for the third timer needs to be at least three seconds.
+ EXPECT_GT(Level3AvgNs, 3000000000U);
+ // The time between the first and second timer needs to be at least one
+ // second.
+ EXPECT_GT(Level1AvgNs - Level2AvgNs, 1000000000U);
+ // The time between the second and third timer needs to be at least two
+ // second.
+ EXPECT_GT(Level2AvgNs - Level3AvgNs, 2000000000U);
+}
+
+TEST_F(ScudoTimingTest, VerifyMax) {
+ for (size_t i = 0; i < 3; i++) {
+ scudo::ScopedTimer Outer(getTimingManager(), "Level1");
+ sleep(1);
+ }
+ scudo::ScopedString Str;
+ getAllTimersStats(Str);
+ std::string Output(Str.data());
+
+ Output = Output.substr(Output.find('\n') + 1);
+ char *end;
+ unsigned long long AvgNs = std::strtoull(Output.c_str(), &end, 10);
+ ASSERT_TRUE(end != nullptr);
+ unsigned long long MaxNs = std::strtoull(&end[6], &end, 10);
+ ASSERT_TRUE(end != nullptr);
+
+ EXPECT_GT(MaxNs, AvgNs);
+}
+
+TEST_F(ScudoTimingTest, VerifyMultipleTimerCalls) {
+ for (size_t i = 0; i < 5; i++)
+ testCallTimers();
+
+ scudo::ScopedString Str;
+ getAllTimersStats(Str);
+ std::string Output(Str.data());
+ EXPECT_TRUE(Output.find("Level1 (5)") != std::string::npos);
+ EXPECT_TRUE(Output.find("Level2 (5)") != std::string::npos);
+ EXPECT_TRUE(Output.find("Level3 (5)") != std::string::npos);
+}
+
+TEST_F(ScudoTimingTest, VerifyHeader) {
+ { scudo::ScopedTimer Outer(getTimingManager(), "Timer"); }
+ scudo::ScopedString Str;
+ getAllTimersStats(Str);
+
+ std::string Output(Str.data());
+ std::string Header(Output.substr(0, Output.find('\n')));
+ EXPECT_EQ(Header, "-- Average Operation Time -- -- Maximum Operation Time -- "
+ "-- Name (# of Calls) --");
+}
+
+TEST_F(ScudoTimingTest, VerifyTimerFormat) {
+ testCallTimers();
+ scudo::ScopedString Str;
+ getAllTimersStats(Str);
+ std::string Output(Str.data());
+
+ // Check the top level line, should look similar to:
+ // 11718.0(ns) 11718(ns) Level1 (1)
+ Output = Output.substr(Output.find('\n') + 1);
+
+ // Verify that the Average Operation Time is in the correct location.
+ EXPECT_EQ(".0(ns) ", Output.substr(14, 7));
+
+ // Verify that the Maximum Operation Time is in the correct location.
+ EXPECT_EQ("(ns) ", Output.substr(45, 5));
+
+ // Verify that the first timer name is in the correct location.
+ EXPECT_EQ("Level1 (1)\n", Output.substr(61, 11));
+
+ // Check a chained timer, should look similar to:
+ // 5331.0(ns) 5331(ns) Level2 (1)
+ Output = Output.substr(Output.find('\n') + 1);
+
+ // Verify that the Average Operation Time is in the correct location.
+ EXPECT_EQ(".0(ns) ", Output.substr(14, 7));
+
+ // Verify that the Maximum Operation Time is in the correct location.
+ EXPECT_EQ("(ns) ", Output.substr(45, 5));
+
+ // Verify that the first timer name is in the correct location.
+ EXPECT_EQ(" Level2 (1)\n", Output.substr(61, 13));
+
+ // Check a secondary chained timer, should look similar to:
+ // 814.0(ns) 814(ns) Level3 (1)
+ Output = Output.substr(Output.find('\n') + 1);
+
+ // Verify that the Average Operation Time is in the correct location.
+ EXPECT_EQ(".0(ns) ", Output.substr(14, 7));
+
+ // Verify that the Maximum Operation Time is in the correct location.
+ EXPECT_EQ("(ns) ", Output.substr(45, 5));
+
+ // Verify that the first timer name is in the correct location.
+ EXPECT_EQ(" Level3 (1)\n", Output.substr(61, 15));
+}
#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);
+TEST_F(ScudoTimingTest, VerifyPrintMatchesGet) {
+ testing::internal::LogToStderr();
+ testing::internal::CaptureStderr();
+ testCallTimers();
+
+ { scudo::ScopedTimer Outer(getTimingManager(), "Timer"); }
+ printAllTimersStats();
+ std::string PrintOutput = testing::internal::GetCapturedStderr();
+ EXPECT_TRUE(PrintOutput.size() != 0);
+
+ scudo::ScopedString Str;
+ getAllTimersStats(Str);
+ std::string GetOutput(Str.data());
+ EXPECT_TRUE(GetOutput.size() != 0);
+
+ EXPECT_EQ(PrintOutput, GetOutput);
+}
#endif
+
+#if SCUDO_LINUX
+TEST_F(ScudoTimingTest, VerifyReporting) {
+ testing::internal::LogToStderr();
+ testing::internal::CaptureStderr();
+ // Every 100 calls generates a report, but run a few extra to verify the
+ // report happened at call 100.
+ for (size_t i = 0; i < 110; i++)
+ scudo::ScopedTimer Outer(getTimingManager(), "VerifyReportTimer");
+
+ std::string Output = testing::internal::GetCapturedStderr();
+ EXPECT_TRUE(Output.find("VerifyReportTimer (100)") != std::string::npos);
}
+#endif
diff --git a/compiler-rt/lib/scudo/standalone/timing.h b/compiler-rt/lib/scudo/standalone/timing.h
index 84caa79e5c3a2..de741edbff5ff 100644
--- a/compiler-rt/lib/scudo/standalone/timing.h
+++ b/compiler-rt/lib/scudo/standalone/timing.h
@@ -104,6 +104,7 @@ class TimingManager {
strncpy(Timers[NumAllocatedTimers].Name, Name, MaxLenOfTimerName);
TimerRecords[NumAllocatedTimers].AccumulatedTime = 0;
TimerRecords[NumAllocatedTimers].Occurrence = 0;
+ TimerRecords[NumAllocatedTimers].MaxTime = 0;
return Timer(*this, NumAllocatedTimers++);
}
@@ -140,36 +141,47 @@ class TimingManager {
const u32 HandleId = T.HandleId;
CHECK_LT(HandleId, MaxNumberOfTimers);
- TimerRecords[HandleId].AccumulatedTime += T.getAccumulatedTime();
+ u64 AccTime = T.getAccumulatedTime();
+ TimerRecords[HandleId].AccumulatedTime += AccTime;
+ if (AccTime > TimerRecords[HandleId].MaxTime) {
+ TimerRecords[HandleId].MaxTime = AccTime;
+ }
++TimerRecords[HandleId].Occurrence;
++NumEventsReported;
- if (NumEventsReported % PrintingInterval == 0)
- printAllImpl();
+ if (NumEventsReported % PrintingInterval == 0) {
+ ScopedString Str;
+ getAllImpl(Str);
+ Str.output();
+ }
}
void printAll() EXCLUDES(Mutex) {
+ ScopedString Str;
+ getAll(Str);
+ Str.output();
+ }
+
+ void getAll(ScopedString &Str) EXCLUDES(Mutex) {
ScopedLock L(Mutex);
- printAllImpl();
+ getAllImpl(Str);
}
private:
- void printAllImpl() REQUIRES(Mutex) {
- static char NameHeader[] = "-- Name (# of Calls) --";
+ void getAllImpl(ScopedString &Str) REQUIRES(Mutex) {
static char AvgHeader[] = "-- Average Operation Time --";
- ScopedString Str;
- Str.append("%-15s %-15s\n", AvgHeader, NameHeader);
+ static char MaxHeader[] = "-- Maximum Operation Time --";
+ static char NameHeader[] = "-- Name (# of Calls) --";
+ Str.append("%-15s %-15s %-15s\n", AvgHeader, MaxHeader, NameHeader);
for (u32 I = 0; I < NumAllocatedTimers; ++I) {
if (Timers[I].Nesting != MaxNumberOfTimers)
continue;
- printImpl(Str, I);
+ getImpl(Str, I);
}
-
- Str.output();
}
- void printImpl(ScopedString &Str, const u32 HandleId,
- const u32 ExtraIndent = 0) REQUIRES(Mutex) {
+ void getImpl(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;
@@ -179,15 +191,20 @@ class TimingManager {
Occurrence == 0 ? 0
: ((AccumulatedTime % Occurrence) * 10) / Occurrence;
- Str.append("%14" PRId64 ".%" PRId64 "(ns) %-11s", Integral, Fraction, " ");
+ // Average time.
+ Str.append("%14" PRId64 ".%" PRId64 "(ns) %-8s", Integral, Fraction, " ");
+
+ // Maximum time.
+ Str.append("%16" PRId64 "(ns) %-11s", TimerRecords[HandleId].MaxTime, " ");
+ // Name and num occurrences.
for (u32 I = 0; I < ExtraIndent; ++I)
Str.append("%s", " ");
Str.append("%s (%" PRId64 ")\n", Timers[HandleId].Name, Occurrence);
for (u32 I = 0; I < NumAllocatedTimers; ++I)
if (Timers[I].Nesting == HandleId)
- printImpl(Str, I, ExtraIndent + 1);
+ getImpl(Str, I, ExtraIndent + 1);
}
// Instead of maintaining pages for timer registration, a static buffer is
@@ -199,6 +216,7 @@ class TimingManager {
struct Record {
u64 AccumulatedTime = 0;
u64 Occurrence = 0;
+ u64 MaxTime = 0;
};
struct TimerInfo {
``````````
</details>
https://github.com/llvm/llvm-project/pull/96989
More information about the llvm-commits
mailing list