1 //===-- timing_test.cpp -----------------------------------------*- C++ -*-===//
2 //
3 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
4 // See https://llvm.org/LICENSE.txt for license information.
5 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
6 //
7 //===----------------------------------------------------------------------===//
8
9 #include "tests/scudo_unit_test.h"
10
11 #include "timing.h"
12
13 #include <cstdlib>
14 #include <string>
15
16 class ScudoTimingTest : public Test {
17 public:
testFunc1()18 void testFunc1() { scudo::ScopedTimer ST(Manager, __func__); }
19
testFunc2()20 void testFunc2() {
21 scudo::ScopedTimer ST(Manager, __func__);
22 testFunc1();
23 }
24
testChainedCalls()25 void testChainedCalls() {
26 scudo::ScopedTimer ST(Manager, __func__);
27 testFunc2();
28 }
29
testIgnoredTimer()30 void testIgnoredTimer() {
31 scudo::ScopedTimer ST(Manager, __func__);
32 ST.ignore();
33 }
34
printAllTimersStats()35 void printAllTimersStats() { Manager.printAll(); }
36
getAllTimersStats(scudo::ScopedString & Str)37 void getAllTimersStats(scudo::ScopedString &Str) { Manager.getAll(Str); }
38
getTimingManager()39 scudo::TimingManager &getTimingManager() { return Manager; }
40
testCallTimers()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
49 private:
50 scudo::TimingManager Manager;
51 };
52
TEST_F(ScudoTimingTest,SimpleTimer)53 TEST_F(ScudoTimingTest, SimpleTimer) {
54 testIgnoredTimer();
55 testChainedCalls();
56 scudo::ScopedString Str;
57 getAllTimersStats(Str);
58
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);
64 }
65
TEST_F(ScudoTimingTest,NestedTimer)66 TEST_F(ScudoTimingTest, NestedTimer) {
67 {
68 scudo::ScopedTimer Outer(getTimingManager(), "Outer");
69 {
70 scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Inner1");
71 { scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Inner2"); }
72 }
73 }
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
TEST_F(ScudoTimingTest,VerifyChainedTimerCalculations)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
TEST_F(ScudoTimingTest,VerifyMax)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_GE(MaxNs, AvgNs);
158 }
159
TEST_F(ScudoTimingTest,VerifyMultipleTimerCalls)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
TEST_F(ScudoTimingTest,VerifyHeader)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
TEST_F(ScudoTimingTest,VerifyTimerFormat)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 }
228
229 #if SCUDO_LINUX
TEST_F(ScudoTimingTest,VerifyPrintMatchesGet)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 }
247 #endif
248
249 #if SCUDO_LINUX
TEST_F(ScudoTimingTest,VerifyReporting)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);
260 }
261 #endif
262