Skip to content

[scudo] Add a maximum value into the timer. #96989

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Jul 10, 2024
Merged

[scudo] Add a maximum value into the timer. #96989

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
229 changes: 202 additions & 27 deletions compiler-rt/lib/scudo/standalone/tests/timing_test.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@

#include "timing.h"

#include <cstdlib>
#include <string>

class ScudoTimingTest : public Test {
Expand All @@ -33,54 +34,228 @@ 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");
{
scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Inner1");
{ 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
48 changes: 33 additions & 15 deletions compiler-rt/lib/scudo/standalone/timing.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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++);
}

Expand Down Expand Up @@ -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;
Expand All @@ -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
Expand All @@ -199,6 +216,7 @@ class TimingManager {
struct Record {
u64 AccumulatedTime = 0;
u64 Occurrence = 0;
u64 MaxTime = 0;
};

struct TimerInfo {
Expand Down
Loading