424 lines · cpp
1//===-- fdr_controller_test.cpp -------------------------------------------===//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// This file is a part of XRay, a function call tracing system.10//11//===----------------------------------------------------------------------===//12#include <algorithm>13#include <memory>14#include <time.h>15 16#include "test_helpers.h"17#include "xray/xray_records.h"18#include "xray_buffer_queue.h"19#include "xray_fdr_controller.h"20#include "xray_fdr_log_writer.h"21#include "llvm/Support/DataExtractor.h"22#include "llvm/Testing/Support/Error.h"23#include "llvm/XRay/Trace.h"24#include "llvm/XRay/XRayRecord.h"25#include "gmock/gmock.h"26#include "gtest/gtest.h"27 28namespace __xray {29namespace {30 31using ::llvm::HasValue;32using ::llvm::xray::testing::FuncId;33using ::llvm::xray::testing::HasArg;34using ::llvm::xray::testing::RecordType;35using ::llvm::xray::testing::TSCIs;36using ::testing::AllOf;37using ::testing::ElementsAre;38using ::testing::Eq;39using ::testing::Field;40using ::testing::Gt;41using ::testing::IsEmpty;42using ::testing::SizeIs;43 44class FunctionSequenceTest : public ::testing::Test {45protected:46 BufferQueue::Buffer B{};47 std::unique_ptr<BufferQueue> BQ;48 std::unique_ptr<FDRLogWriter> W;49 std::unique_ptr<FDRController<>> C;50 51public:52 void SetUp() override {53 bool Success;54 BQ = std::make_unique<BufferQueue>(4096, 1, Success);55 ASSERT_TRUE(Success);56 ASSERT_EQ(BQ->getBuffer(B), BufferQueue::ErrorCode::Ok);57 W = std::make_unique<FDRLogWriter>(B);58 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 0);59 }60};61 62TEST_F(FunctionSequenceTest, DefaultInitFinalizeFlush) {63 ASSERT_TRUE(C->functionEnter(1, 2, 3));64 ASSERT_TRUE(C->functionExit(1, 2, 3));65 ASSERT_TRUE(C->flush());66 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);67 68 // Serialize the buffers then test to see we find the expected records.69 std::string Serialized = serialize(*BQ, 3);70 llvm::DataExtractor DE(Serialized, true, 8);71 auto TraceOrErr = llvm::xray::loadTrace(DE);72 EXPECT_THAT_EXPECTED(73 TraceOrErr,74 HasValue(ElementsAre(75 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::ENTER)),76 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT)))));77}78 79TEST_F(FunctionSequenceTest, BoundaryFuncIdEncoding) {80 // We ensure that we can write function id's that are at the boundary of the81 // acceptable function ids.82 int32_t FId = (1 << 28) - 1;83 uint64_t TSC = 2;84 uint16_t CPU = 1;85 ASSERT_TRUE(C->functionEnter(FId, TSC++, CPU));86 ASSERT_TRUE(C->functionExit(FId, TSC++, CPU));87 ASSERT_TRUE(C->functionEnterArg(FId, TSC++, CPU, 1));88 ASSERT_TRUE(C->functionTailExit(FId, TSC++, CPU));89 ASSERT_TRUE(C->flush());90 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);91 92 // Serialize the buffers then test to see we find the expected records.93 std::string Serialized = serialize(*BQ, 3);94 llvm::DataExtractor DE(Serialized, true, 8);95 auto TraceOrErr = llvm::xray::loadTrace(DE);96 EXPECT_THAT_EXPECTED(97 TraceOrErr,98 HasValue(ElementsAre(99 AllOf(FuncId(FId), RecordType(llvm::xray::RecordTypes::ENTER)),100 AllOf(FuncId(FId), RecordType(llvm::xray::RecordTypes::EXIT)),101 AllOf(FuncId(FId), RecordType(llvm::xray::RecordTypes::ENTER_ARG)),102 AllOf(FuncId(FId), RecordType(llvm::xray::RecordTypes::TAIL_EXIT)))));103}104 105TEST_F(FunctionSequenceTest, ThresholdsAreEnforced) {106 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);107 ASSERT_TRUE(C->functionEnter(1, 2, 3));108 ASSERT_TRUE(C->functionExit(1, 2, 3));109 ASSERT_TRUE(C->flush());110 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);111 112 // Serialize the buffers then test to see we find the *no* records, because113 // the function entry-exit comes under the cycle threshold.114 std::string Serialized = serialize(*BQ, 3);115 llvm::DataExtractor DE(Serialized, true, 8);116 auto TraceOrErr = llvm::xray::loadTrace(DE);117 EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(IsEmpty()));118}119 120TEST_F(FunctionSequenceTest, ArgsAreHandledAndKept) {121 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);122 ASSERT_TRUE(C->functionEnterArg(1, 2, 3, 4));123 ASSERT_TRUE(C->functionExit(1, 2, 3));124 ASSERT_TRUE(C->flush());125 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);126 127 // Serialize the buffers then test to see we find the function enter arg128 // record with the specified argument.129 std::string Serialized = serialize(*BQ, 3);130 llvm::DataExtractor DE(Serialized, true, 8);131 auto TraceOrErr = llvm::xray::loadTrace(DE);132 EXPECT_THAT_EXPECTED(133 TraceOrErr,134 HasValue(ElementsAre(135 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::ENTER_ARG),136 HasArg(4)),137 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT)))));138}139 140TEST_F(FunctionSequenceTest, PreservedCallsHaveCorrectTSC) {141 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);142 uint64_t TSC = 1;143 uint16_t CPU = 0;144 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));145 ASSERT_TRUE(C->functionEnter(2, TSC++, CPU));146 ASSERT_TRUE(C->functionExit(2, TSC++, CPU));147 ASSERT_TRUE(C->functionExit(1, TSC += 1000, CPU));148 ASSERT_TRUE(C->flush());149 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);150 151 // Serialize the buffers then test to see if we find the remaining records,152 // because the function entry-exit comes under the cycle threshold.153 std::string Serialized = serialize(*BQ, 3);154 llvm::DataExtractor DE(Serialized, true, 8);155 auto TraceOrErr = llvm::xray::loadTrace(DE);156 EXPECT_THAT_EXPECTED(157 TraceOrErr,158 HasValue(ElementsAre(159 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::ENTER),160 TSCIs(Eq(1uL))),161 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT),162 TSCIs(Gt(1000uL))))));163}164 165TEST_F(FunctionSequenceTest, PreservedCallsSupportLargeDeltas) {166 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);167 uint64_t TSC = 1;168 uint16_t CPU = 0;169 const auto LargeDelta = uint64_t{std::numeric_limits<int32_t>::max()};170 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));171 ASSERT_TRUE(C->functionExit(1, TSC += LargeDelta, CPU));172 ASSERT_TRUE(C->flush());173 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);174 175 // Serialize the buffer then test to see if we find the right TSC with a large176 // delta.177 std::string Serialized = serialize(*BQ, 3);178 llvm::DataExtractor DE(Serialized, true, 8);179 auto TraceOrErr = llvm::xray::loadTrace(DE);180 EXPECT_THAT_EXPECTED(181 TraceOrErr,182 HasValue(ElementsAre(183 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::ENTER),184 TSCIs(Eq(1uL))),185 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT),186 TSCIs(Gt(LargeDelta))))));187}188 189TEST_F(FunctionSequenceTest, RewindingMultipleCalls) {190 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);191 192 // First we construct an arbitrarily deep function enter/call stack.193 // We also ensure that we are in the same CPU.194 uint64_t TSC = 1;195 uint16_t CPU = 1;196 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));197 ASSERT_TRUE(C->functionEnter(2, TSC++, CPU));198 ASSERT_TRUE(C->functionEnter(3, TSC++, CPU));199 200 // Then we exit them one at a time, in reverse order of entry.201 ASSERT_TRUE(C->functionExit(3, TSC++, CPU));202 ASSERT_TRUE(C->functionExit(2, TSC++, CPU));203 ASSERT_TRUE(C->functionExit(1, TSC++, CPU));204 205 ASSERT_TRUE(C->flush());206 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);207 208 // Serialize the buffers then test to see we find that all the calls have been209 // unwound because all of them are under the cycle counter threshold.210 std::string Serialized = serialize(*BQ, 3);211 llvm::DataExtractor DE(Serialized, true, 8);212 auto TraceOrErr = llvm::xray::loadTrace(DE);213 EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(IsEmpty()));214}215 216TEST_F(FunctionSequenceTest, RewindingIntermediaryTailExits) {217 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);218 219 // First we construct an arbitrarily deep function enter/call stack.220 // We also ensure that we are in the same CPU.221 uint64_t TSC = 1;222 uint16_t CPU = 1;223 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));224 ASSERT_TRUE(C->functionEnter(2, TSC++, CPU));225 ASSERT_TRUE(C->functionEnter(3, TSC++, CPU));226 227 // Next we tail-exit into a new function multiple times.228 ASSERT_TRUE(C->functionTailExit(3, TSC++, CPU));229 ASSERT_TRUE(C->functionEnter(4, TSC++, CPU));230 ASSERT_TRUE(C->functionTailExit(4, TSC++, CPU));231 ASSERT_TRUE(C->functionEnter(5, TSC++, CPU));232 ASSERT_TRUE(C->functionTailExit(5, TSC++, CPU));233 ASSERT_TRUE(C->functionEnter(6, TSC++, CPU));234 235 // Then we exit them one at a time, in reverse order of entry.236 ASSERT_TRUE(C->functionExit(6, TSC++, CPU));237 ASSERT_TRUE(C->functionExit(2, TSC++, CPU));238 ASSERT_TRUE(C->functionExit(1, TSC++, CPU));239 ASSERT_TRUE(C->flush());240 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);241 242 // Serialize the buffers then test to see we find that all the calls have been243 // unwound because all of them are under the cycle counter threshold.244 std::string Serialized = serialize(*BQ, 3);245 llvm::DataExtractor DE(Serialized, true, 8);246 auto TraceOrErr = llvm::xray::loadTrace(DE);247 EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(IsEmpty()));248}249 250TEST_F(FunctionSequenceTest, RewindingAfterMigration) {251 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);252 253 // First we construct an arbitrarily deep function enter/call stack.254 // We also ensure that we are in the same CPU.255 uint64_t TSC = 1;256 uint16_t CPU = 1;257 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));258 ASSERT_TRUE(C->functionEnter(2, TSC++, CPU));259 ASSERT_TRUE(C->functionEnter(3, TSC++, CPU));260 261 // Next we tail-exit into a new function multiple times.262 ASSERT_TRUE(C->functionTailExit(3, TSC++, CPU));263 ASSERT_TRUE(C->functionEnter(4, TSC++, CPU));264 ASSERT_TRUE(C->functionTailExit(4, TSC++, CPU));265 266 // But before we enter the next function, we migrate to a different CPU.267 CPU = 2;268 ASSERT_TRUE(C->functionEnter(5, TSC++, CPU));269 ASSERT_TRUE(C->functionTailExit(5, TSC++, CPU));270 ASSERT_TRUE(C->functionEnter(6, TSC++, CPU));271 272 // Then we exit them one at a time, in reverse order of entry.273 ASSERT_TRUE(C->functionExit(6, TSC++, CPU));274 ASSERT_TRUE(C->functionExit(2, TSC++, CPU));275 ASSERT_TRUE(C->functionExit(1, TSC++, CPU));276 277 ASSERT_TRUE(C->flush());278 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);279 280 // Serialize buffers then test that we can find all the events that span the281 // CPU migration.282 std::string Serialized = serialize(*BQ, 3);283 llvm::DataExtractor DE(Serialized, true, 8);284 auto TraceOrErr = llvm::xray::loadTrace(DE);285 EXPECT_THAT_EXPECTED(286 TraceOrErr,287 HasValue(ElementsAre(288 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::ENTER)),289 AllOf(FuncId(2), RecordType(llvm::xray::RecordTypes::ENTER)),290 AllOf(FuncId(2), RecordType(llvm::xray::RecordTypes::EXIT)),291 AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT)))));292}293 294class BufferManagementTest : public ::testing::Test {295protected:296 BufferQueue::Buffer B{};297 std::unique_ptr<BufferQueue> BQ;298 std::unique_ptr<FDRLogWriter> W;299 std::unique_ptr<FDRController<>> C;300 301 static constexpr size_t kBuffers = 10;302 303public:304 void SetUp() override {305 bool Success;306 BQ = std::make_unique<BufferQueue>(sizeof(MetadataRecord) * 5 +307 sizeof(FunctionRecord) * 2,308 kBuffers, Success);309 ASSERT_TRUE(Success);310 ASSERT_EQ(BQ->getBuffer(B), BufferQueue::ErrorCode::Ok);311 W = std::make_unique<FDRLogWriter>(B);312 C = std::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 0);313 }314};315 316constexpr size_t BufferManagementTest::kBuffers;317 318TEST_F(BufferManagementTest, HandlesOverflow) {319 uint64_t TSC = 1;320 uint16_t CPU = 1;321 for (size_t I = 0; I < kBuffers + 1; ++I) {322 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));323 ASSERT_TRUE(C->functionExit(1, TSC++, CPU));324 }325 ASSERT_TRUE(C->flush());326 ASSERT_THAT(BQ->finalize(), Eq(BufferQueue::ErrorCode::Ok));327 328 std::string Serialized = serialize(*BQ, 3);329 llvm::DataExtractor DE(Serialized, true, 8);330 auto TraceOrErr = llvm::xray::loadTrace(DE);331 EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(SizeIs(kBuffers * 2)));332}333 334TEST_F(BufferManagementTest, HandlesOverflowWithArgs) {335 uint64_t TSC = 1;336 uint16_t CPU = 1;337 uint64_t ARG = 1;338 for (size_t I = 0; I < kBuffers + 1; ++I) {339 ASSERT_TRUE(C->functionEnterArg(1, TSC++, CPU, ARG++));340 ASSERT_TRUE(C->functionExit(1, TSC++, CPU));341 }342 ASSERT_TRUE(C->flush());343 ASSERT_THAT(BQ->finalize(), Eq(BufferQueue::ErrorCode::Ok));344 345 std::string Serialized = serialize(*BQ, 3);346 llvm::DataExtractor DE(Serialized, true, 8);347 auto TraceOrErr = llvm::xray::loadTrace(DE);348 EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(SizeIs(kBuffers)));349}350 351TEST_F(BufferManagementTest, HandlesOverflowWithCustomEvents) {352 uint64_t TSC = 1;353 uint16_t CPU = 1;354 int32_t D = 0x9009;355 for (size_t I = 0; I < kBuffers; ++I) {356 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));357 ASSERT_TRUE(C->functionExit(1, TSC++, CPU));358 ASSERT_TRUE(C->customEvent(TSC++, CPU, &D, sizeof(D)));359 }360 ASSERT_TRUE(C->flush());361 ASSERT_THAT(BQ->finalize(), Eq(BufferQueue::ErrorCode::Ok));362 363 std::string Serialized = serialize(*BQ, 3);364 llvm::DataExtractor DE(Serialized, true, 8);365 auto TraceOrErr = llvm::xray::loadTrace(DE);366 367 // We expect to also now count the kBuffers/2 custom event records showing up368 // in the Trace.369 EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(SizeIs(kBuffers + (kBuffers / 2))));370}371 372TEST_F(BufferManagementTest, HandlesFinalizedBufferQueue) {373 uint64_t TSC = 1;374 uint16_t CPU = 1;375 376 // First write one function entry.377 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));378 379 // Then we finalize the buffer queue, simulating the case where the logging380 // has been finalized.381 ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);382 383 // At this point further calls to the controller must fail.384 ASSERT_FALSE(C->functionExit(1, TSC++, CPU));385 386 // But flushing should succeed.387 ASSERT_TRUE(C->flush());388 389 // We expect that we'll only be able to find the function enter event, but not390 // the function exit event.391 std::string Serialized = serialize(*BQ, 3);392 llvm::DataExtractor DE(Serialized, true, 8);393 auto TraceOrErr = llvm::xray::loadTrace(DE);394 EXPECT_THAT_EXPECTED(395 TraceOrErr, HasValue(ElementsAre(AllOf(396 FuncId(1), RecordType(llvm::xray::RecordTypes::ENTER)))));397}398 399TEST_F(BufferManagementTest, HandlesGenerationalBufferQueue) {400 uint64_t TSC = 1;401 uint16_t CPU = 1;402 403 ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));404 ASSERT_THAT(BQ->finalize(), Eq(BufferQueue::ErrorCode::Ok));405 ASSERT_THAT(BQ->init(sizeof(MetadataRecord) * 4 + sizeof(FunctionRecord) * 2,406 kBuffers),407 Eq(BufferQueue::ErrorCode::Ok));408 EXPECT_TRUE(C->functionExit(1, TSC++, CPU));409 ASSERT_TRUE(C->flush());410 411 // We expect that we will only be able to find the function exit event, but412 // not the function enter event, since we only have information about the new413 // generation of the buffers.414 std::string Serialized = serialize(*BQ, 3);415 llvm::DataExtractor DE(Serialized, true, 8);416 auto TraceOrErr = llvm::xray::loadTrace(DE);417 EXPECT_THAT_EXPECTED(418 TraceOrErr, HasValue(ElementsAre(AllOf(419 FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT)))));420}421 422} // namespace423} // namespace __xray424