262 lines · cpp
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-exception6//7//===----------------------------------------------------------------------===//8 9#include "tests/scudo_unit_test.h"10 11#include "timing.h"12 13#include <cstdlib>14#include <string>15 16class ScudoTimingTest : public Test {17public: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 49private:50 scudo::TimingManager Manager;51};52 53TEST_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 66TEST_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 83TEST_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, then101 // 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 one134 // second.135 EXPECT_GT(Level1AvgNs - Level2AvgNs, 1000000000U);136 // The time between the second and third timer needs to be at least two137 // second.138 EXPECT_GT(Level2AvgNs - Level3AvgNs, 2000000000U);139}140 141TEST_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 160TEST_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 172TEST_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 183TEST_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_LINUX230TEST_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#endif248 249#if SCUDO_LINUX250TEST_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 the254 // 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#endif262