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: 18 void testFunc1() { scudo::ScopedTimer ST(Manager, __func__); } 19 20 void testFunc2() { 21 scudo::ScopedTimer ST(Manager, __func__); 22 testFunc1(); 23 } 24 25 void testChainedCalls() { 26 scudo::ScopedTimer ST(Manager, __func__); 27 testFunc2(); 28 } 29 30 void testIgnoredTimer() { 31 scudo::ScopedTimer ST(Manager, __func__); 32 ST.ignore(); 33 } 34 35 void printAllTimersStats() { Manager.printAll(); } 36 37 void getAllTimersStats(scudo::ScopedString &Str) { Manager.getAll(Str); } 38 39 scudo::TimingManager &getTimingManager() { return Manager; } 40 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 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 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 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_GE(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 } 228 229 #if SCUDO_LINUX 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 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