[scudo] Add a maximum value into the timer.

[cferris1000]

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.

[llvmbot]

@llvm/pr-subscribers-compiler-rt-sanitizer

Author: Christopher Ferris (cferris1000)

Changes

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 --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 {

[ChiaHungDuan]

Nice! LGTM!