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