//===-- timing_test.cpp -----------------------------------------*- C++ -*-===//
//
// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
// See https://llvm.org/LICENSE.txt for license information.
// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
//
//===----------------------------------------------------------------------===//
#include "tests/scudo_unit_test.h"
#include "timing.h"
#include <cstdlib>
#include <string>
class ScudoTimingTest : public Test {
public:
void testFunc1() { scudo::ScopedTimer ST(Manager, __func__); }
void testFunc2() {
scudo::ScopedTimer ST(Manager, __func__);
testFunc1();
}
void testChainedCalls() {
scudo::ScopedTimer ST(Manager, __func__);
testFunc2();
}
void testIgnoredTimer() {
scudo::ScopedTimer ST(Manager, __func__);
ST.ignore();
}
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;
};
TEST_F(ScudoTimingTest, SimpleTimer) {
testIgnoredTimer();
testChainedCalls();
scudo::ScopedString Str;
getAllTimersStats(Str);
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) {
{
scudo::ScopedTimer Outer(getTimingManager(), "Outer");
{
scudo::ScopedTimer Inner1(getTimingManager(), Outer, "Inner1");
{ scudo::ScopedTimer Inner2(getTimingManager(), Inner1, "Inner2"); }
}
}
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_GE(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
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
Codebase Browser
llvm