Skip to content

Commit 41de50b

Browse files
cferris1000cferris1000
authored
[scudo] Add a maximum value into the timer. (#96989)
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.
1 parent 5cb7e49 commit 41de50b

File tree

2 files changed

+235
-42
lines changed

2 files changed

+235
-42
lines changed

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

Lines changed: 202 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@
1010

1111
#include "timing.h"
1212

13+
#include <cstdlib>
1314
#include <string>
1415

1516
class ScudoTimingTest : public Test {
@@ -33,54 +34,228 @@ class ScudoTimingTest : public Test {
3334

3435
void printAllTimersStats() { Manager.printAll(); }
3536

37+
void getAllTimersStats(scudo::ScopedString &Str) { Manager.getAll(Str); }
38+
3639
scudo::TimingManager &getTimingManager() { return Manager; }
3740

41+
void testCallTimers() {
42+
scudo::ScopedTimer Outer(getTimingManager(), "Level1");
43+
{
44+
scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Level2");
45+
{ scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Level3"); }
46+
}
47+
}
48+
3849
private:
3950
scudo::TimingManager Manager;
4051
};
4152

42-
// Given that the output of statistics of timers are dumped through
43-
// `scudo::Printf` which is platform dependent, so we don't have a reliable way
44-
// to catch the output and verify the details. Now we only verify the number of
45-
// invocations on linux.
4653
TEST_F(ScudoTimingTest, SimpleTimer) {
47-
#if SCUDO_LINUX
48-
testing::internal::LogToStderr();
49-
testing::internal::CaptureStderr();
50-
#endif
51-
5254
testIgnoredTimer();
5355
testChainedCalls();
54-
printAllTimersStats();
56+
scudo::ScopedString Str;
57+
getAllTimersStats(Str);
5558

56-
#if SCUDO_LINUX
57-
std::string output = testing::internal::GetCapturedStderr();
58-
EXPECT_TRUE(output.find("testIgnoredTimer (1)") == std::string::npos);
59-
EXPECT_TRUE(output.find("testChainedCalls (1)") != std::string::npos);
60-
EXPECT_TRUE(output.find("testFunc2 (1)") != std::string::npos);
61-
EXPECT_TRUE(output.find("testFunc1 (1)") != std::string::npos);
62-
#endif
59+
std::string Output(Str.data());
60+
EXPECT_TRUE(Output.find("testIgnoredTimer (1)") == std::string::npos);
61+
EXPECT_TRUE(Output.find("testChainedCalls (1)") != std::string::npos);
62+
EXPECT_TRUE(Output.find("testFunc2 (1)") != std::string::npos);
63+
EXPECT_TRUE(Output.find("testFunc1 (1)") != std::string::npos);
6364
}
6465

6566
TEST_F(ScudoTimingTest, NestedTimer) {
66-
#if SCUDO_LINUX
67-
testing::internal::LogToStderr();
68-
testing::internal::CaptureStderr();
69-
#endif
70-
7167
{
7268
scudo::ScopedTimer Outer(getTimingManager(), "Outer");
7369
{
7470
scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Inner1");
7571
{ scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Inner2"); }
7672
}
7773
}
78-
printAllTimersStats();
74+
scudo::ScopedString Str;
75+
getAllTimersStats(Str);
76+
77+
std::string Output(Str.data());
78+
EXPECT_TRUE(Output.find("Outer (1)") != std::string::npos);
79+
EXPECT_TRUE(Output.find("Inner1 (1)") != std::string::npos);
80+
EXPECT_TRUE(Output.find("Inner2 (1)") != std::string::npos);
81+
}
82+
83+
TEST_F(ScudoTimingTest, VerifyChainedTimerCalculations) {
84+
{
85+
scudo::ScopedTimer Outer(getTimingManager(), "Level1");
86+
sleep(1);
87+
{
88+
scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Level2");
89+
sleep(2);
90+
{
91+
scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Level3");
92+
sleep(3);
93+
}
94+
}
95+
}
96+
scudo::ScopedString Str;
97+
getAllTimersStats(Str);
98+
std::string Output(Str.data());
99+
100+
// Get the individual timer values for the average and maximum, then
101+
// verify that the timer values are being calculated properly.
102+
Output = Output.substr(Output.find('\n') + 1);
103+
char *end;
104+
unsigned long long Level1AvgNs = std::strtoull(Output.c_str(), &end, 10);
105+
ASSERT_TRUE(end != nullptr);
106+
unsigned long long Level1MaxNs = std::strtoull(&end[6], &end, 10);
107+
ASSERT_TRUE(end != nullptr);
108+
EXPECT_EQ(Level1AvgNs, Level1MaxNs);
109+
110+
Output = Output.substr(Output.find('\n') + 1);
111+
unsigned long long Level2AvgNs = std::strtoull(Output.c_str(), &end, 10);
112+
ASSERT_TRUE(end != nullptr);
113+
unsigned long long Level2MaxNs = std::strtoull(&end[6], &end, 10);
114+
ASSERT_TRUE(end != nullptr);
115+
EXPECT_EQ(Level2AvgNs, Level2MaxNs);
116+
117+
Output = Output.substr(Output.find('\n') + 1);
118+
unsigned long long Level3AvgNs = std::strtoull(Output.c_str(), &end, 10);
119+
ASSERT_TRUE(end != nullptr);
120+
unsigned long long Level3MaxNs = std::strtoull(&end[6], &end, 10);
121+
ASSERT_TRUE(end != nullptr);
122+
EXPECT_EQ(Level3AvgNs, Level3MaxNs);
123+
124+
EXPECT_GT(Level1AvgNs, Level2AvgNs);
125+
EXPECT_GT(Level2AvgNs, Level3AvgNs);
126+
127+
// The time for the first timer needs to be at least six seconds.
128+
EXPECT_GT(Level1AvgNs, 6000000000U);
129+
// The time for the second timer needs to be at least five seconds.
130+
EXPECT_GT(Level2AvgNs, 5000000000U);
131+
// The time for the third timer needs to be at least three seconds.
132+
EXPECT_GT(Level3AvgNs, 3000000000U);
133+
// The time between the first and second timer needs to be at least one
134+
// second.
135+
EXPECT_GT(Level1AvgNs - Level2AvgNs, 1000000000U);
136+
// The time between the second and third timer needs to be at least two
137+
// second.
138+
EXPECT_GT(Level2AvgNs - Level3AvgNs, 2000000000U);
139+
}
140+
141+
TEST_F(ScudoTimingTest, VerifyMax) {
142+
for (size_t i = 0; i < 3; i++) {
143+
scudo::ScopedTimer Outer(getTimingManager(), "Level1");
144+
sleep(1);
145+
}
146+
scudo::ScopedString Str;
147+
getAllTimersStats(Str);
148+
std::string Output(Str.data());
149+
150+
Output = Output.substr(Output.find('\n') + 1);
151+
char *end;
152+
unsigned long long AvgNs = std::strtoull(Output.c_str(), &end, 10);
153+
ASSERT_TRUE(end != nullptr);
154+
unsigned long long MaxNs = std::strtoull(&end[6], &end, 10);
155+
ASSERT_TRUE(end != nullptr);
156+
157+
EXPECT_GT(MaxNs, AvgNs);
158+
}
159+
160+
TEST_F(ScudoTimingTest, VerifyMultipleTimerCalls) {
161+
for (size_t i = 0; i < 5; i++)
162+
testCallTimers();
163+
164+
scudo::ScopedString Str;
165+
getAllTimersStats(Str);
166+
std::string Output(Str.data());
167+
EXPECT_TRUE(Output.find("Level1 (5)") != std::string::npos);
168+
EXPECT_TRUE(Output.find("Level2 (5)") != std::string::npos);
169+
EXPECT_TRUE(Output.find("Level3 (5)") != std::string::npos);
170+
}
171+
172+
TEST_F(ScudoTimingTest, VerifyHeader) {
173+
{ scudo::ScopedTimer Outer(getTimingManager(), "Timer"); }
174+
scudo::ScopedString Str;
175+
getAllTimersStats(Str);
176+
177+
std::string Output(Str.data());
178+
std::string Header(Output.substr(0, Output.find('\n')));
179+
EXPECT_EQ(Header, "-- Average Operation Time -- -- Maximum Operation Time -- "
180+
"-- Name (# of Calls) --");
181+
}
182+
183+
TEST_F(ScudoTimingTest, VerifyTimerFormat) {
184+
testCallTimers();
185+
scudo::ScopedString Str;
186+
getAllTimersStats(Str);
187+
std::string Output(Str.data());
188+
189+
// Check the top level line, should look similar to:
190+
// 11718.0(ns) 11718(ns) Level1 (1)
191+
Output = Output.substr(Output.find('\n') + 1);
192+
193+
// Verify that the Average Operation Time is in the correct location.
194+
EXPECT_EQ(".0(ns) ", Output.substr(14, 7));
195+
196+
// Verify that the Maximum Operation Time is in the correct location.
197+
EXPECT_EQ("(ns) ", Output.substr(45, 5));
198+
199+
// Verify that the first timer name is in the correct location.
200+
EXPECT_EQ("Level1 (1)\n", Output.substr(61, 11));
201+
202+
// Check a chained timer, should look similar to:
203+
// 5331.0(ns) 5331(ns) Level2 (1)
204+
Output = Output.substr(Output.find('\n') + 1);
205+
206+
// Verify that the Average Operation Time is in the correct location.
207+
EXPECT_EQ(".0(ns) ", Output.substr(14, 7));
208+
209+
// Verify that the Maximum Operation Time is in the correct location.
210+
EXPECT_EQ("(ns) ", Output.substr(45, 5));
211+
212+
// Verify that the first timer name is in the correct location.
213+
EXPECT_EQ(" Level2 (1)\n", Output.substr(61, 13));
214+
215+
// Check a secondary chained timer, should look similar to:
216+
// 814.0(ns) 814(ns) Level3 (1)
217+
Output = Output.substr(Output.find('\n') + 1);
218+
219+
// Verify that the Average Operation Time is in the correct location.
220+
EXPECT_EQ(".0(ns) ", Output.substr(14, 7));
221+
222+
// Verify that the Maximum Operation Time is in the correct location.
223+
EXPECT_EQ("(ns) ", Output.substr(45, 5));
224+
225+
// Verify that the first timer name is in the correct location.
226+
EXPECT_EQ(" Level3 (1)\n", Output.substr(61, 15));
227+
}
79228

80229
#if SCUDO_LINUX
81-
std::string output = testing::internal::GetCapturedStderr();
82-
EXPECT_TRUE(output.find("Outer (1)") != std::string::npos);
83-
EXPECT_TRUE(output.find("Inner1 (1)") != std::string::npos);
84-
EXPECT_TRUE(output.find("Inner2 (1)") != std::string::npos);
230+
TEST_F(ScudoTimingTest, VerifyPrintMatchesGet) {
231+
testing::internal::LogToStderr();
232+
testing::internal::CaptureStderr();
233+
testCallTimers();
234+
235+
{ scudo::ScopedTimer Outer(getTimingManager(), "Timer"); }
236+
printAllTimersStats();
237+
std::string PrintOutput = testing::internal::GetCapturedStderr();
238+
EXPECT_TRUE(PrintOutput.size() != 0);
239+
240+
scudo::ScopedString Str;
241+
getAllTimersStats(Str);
242+
std::string GetOutput(Str.data());
243+
EXPECT_TRUE(GetOutput.size() != 0);
244+
245+
EXPECT_EQ(PrintOutput, GetOutput);
246+
}
85247
#endif
248+
249+
#if SCUDO_LINUX
250+
TEST_F(ScudoTimingTest, VerifyReporting) {
251+
testing::internal::LogToStderr();
252+
testing::internal::CaptureStderr();
253+
// Every 100 calls generates a report, but run a few extra to verify the
254+
// report happened at call 100.
255+
for (size_t i = 0; i < 110; i++)
256+
scudo::ScopedTimer Outer(getTimingManager(), "VerifyReportTimer");
257+
258+
std::string Output = testing::internal::GetCapturedStderr();
259+
EXPECT_TRUE(Output.find("VerifyReportTimer (100)") != std::string::npos);
86260
}
261+
#endif

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

Lines changed: 33 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -104,6 +104,7 @@ class TimingManager {
104104
strncpy(Timers[NumAllocatedTimers].Name, Name, MaxLenOfTimerName);
105105
TimerRecords[NumAllocatedTimers].AccumulatedTime = 0;
106106
TimerRecords[NumAllocatedTimers].Occurrence = 0;
107+
TimerRecords[NumAllocatedTimers].MaxTime = 0;
107108
return Timer(*this, NumAllocatedTimers++);
108109
}
109110

@@ -140,36 +141,47 @@ class TimingManager {
140141

141142
const u32 HandleId = T.HandleId;
142143
CHECK_LT(HandleId, MaxNumberOfTimers);
143-
TimerRecords[HandleId].AccumulatedTime += T.getAccumulatedTime();
144+
u64 AccTime = T.getAccumulatedTime();
145+
TimerRecords[HandleId].AccumulatedTime += AccTime;
146+
if (AccTime > TimerRecords[HandleId].MaxTime) {
147+
TimerRecords[HandleId].MaxTime = AccTime;
148+
}
144149
++TimerRecords[HandleId].Occurrence;
145150
++NumEventsReported;
146-
if (NumEventsReported % PrintingInterval == 0)
147-
printAllImpl();
151+
if (NumEventsReported % PrintingInterval == 0) {
152+
ScopedString Str;
153+
getAllImpl(Str);
154+
Str.output();
155+
}
148156
}
149157

150158
void printAll() EXCLUDES(Mutex) {
159+
ScopedString Str;
160+
getAll(Str);
161+
Str.output();
162+
}
163+
164+
void getAll(ScopedString &Str) EXCLUDES(Mutex) {
151165
ScopedLock L(Mutex);
152-
printAllImpl();
166+
getAllImpl(Str);
153167
}
154168

155169
private:
156-
void printAllImpl() REQUIRES(Mutex) {
157-
static char NameHeader[] = "-- Name (# of Calls) --";
170+
void getAllImpl(ScopedString &Str) REQUIRES(Mutex) {
158171
static char AvgHeader[] = "-- Average Operation Time --";
159-
ScopedString Str;
160-
Str.append("%-15s %-15s\n", AvgHeader, NameHeader);
172+
static char MaxHeader[] = "-- Maximum Operation Time --";
173+
static char NameHeader[] = "-- Name (# of Calls) --";
174+
Str.append("%-15s %-15s %-15s\n", AvgHeader, MaxHeader, NameHeader);
161175

162176
for (u32 I = 0; I < NumAllocatedTimers; ++I) {
163177
if (Timers[I].Nesting != MaxNumberOfTimers)
164178
continue;
165-
printImpl(Str, I);
179+
getImpl(Str, I);
166180
}
167-
168-
Str.output();
169181
}
170182

171-
void printImpl(ScopedString &Str, const u32 HandleId,
172-
const u32 ExtraIndent = 0) REQUIRES(Mutex) {
183+
void getImpl(ScopedString &Str, const u32 HandleId, const u32 ExtraIndent = 0)
184+
REQUIRES(Mutex) {
173185
const u64 AccumulatedTime = TimerRecords[HandleId].AccumulatedTime;
174186
const u64 Occurrence = TimerRecords[HandleId].Occurrence;
175187
const u64 Integral = Occurrence == 0 ? 0 : AccumulatedTime / Occurrence;
@@ -179,15 +191,20 @@ class TimingManager {
179191
Occurrence == 0 ? 0
180192
: ((AccumulatedTime % Occurrence) * 10) / Occurrence;
181193

182-
Str.append("%14" PRId64 ".%" PRId64 "(ns) %-11s", Integral, Fraction, " ");
194+
// Average time.
195+
Str.append("%14" PRId64 ".%" PRId64 "(ns) %-8s", Integral, Fraction, " ");
196+
197+
// Maximum time.
198+
Str.append("%16" PRId64 "(ns) %-11s", TimerRecords[HandleId].MaxTime, " ");
183199

200+
// Name and num occurrences.
184201
for (u32 I = 0; I < ExtraIndent; ++I)
185202
Str.append("%s", " ");
186203
Str.append("%s (%" PRId64 ")\n", Timers[HandleId].Name, Occurrence);
187204

188205
for (u32 I = 0; I < NumAllocatedTimers; ++I)
189206
if (Timers[I].Nesting == HandleId)
190-
printImpl(Str, I, ExtraIndent + 1);
207+
getImpl(Str, I, ExtraIndent + 1);
191208
}
192209

193210
// Instead of maintaining pages for timer registration, a static buffer is
@@ -199,6 +216,7 @@ class TimingManager {
199216
struct Record {
200217
u64 AccumulatedTime = 0;
201218
u64 Occurrence = 0;
219+
u64 MaxTime = 0;
202220
};
203221

204222
struct TimerInfo {

0 commit comments

Comments
 (0)