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-exception
6 //
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 
28 namespace __xray {
29 namespace {
30 
31 using ::llvm::HasValue;
32 using ::llvm::xray::testing::FuncId;
33 using ::llvm::xray::testing::HasArg;
34 using ::llvm::xray::testing::RecordType;
35 using ::llvm::xray::testing::TSCIs;
36 using ::testing::AllOf;
37 using ::testing::ElementsAre;
38 using ::testing::Eq;
39 using ::testing::Field;
40 using ::testing::Gt;
41 using ::testing::IsEmpty;
42 using ::testing::SizeIs;
43 
44 class FunctionSequenceTest : public ::testing::Test {
45 protected:
46   BufferQueue::Buffer B{};
47   std::unique_ptr<BufferQueue> BQ;
48   std::unique_ptr<FDRLogWriter> W;
49   std::unique_ptr<FDRController<>> C;
50 
51 public:
SetUp()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 
TEST_F(FunctionSequenceTest,DefaultInitFinalizeFlush)62 TEST_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 
TEST_F(FunctionSequenceTest,BoundaryFuncIdEncoding)79 TEST_F(FunctionSequenceTest, BoundaryFuncIdEncoding) {
80   // We ensure that we can write function id's that are at the boundary of the
81   // 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 
TEST_F(FunctionSequenceTest,ThresholdsAreEnforced)105 TEST_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, because
113   // 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 
TEST_F(FunctionSequenceTest,ArgsAreHandledAndKept)120 TEST_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 arg
128   // 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 
TEST_F(FunctionSequenceTest,PreservedCallsHaveCorrectTSC)140 TEST_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 
TEST_F(FunctionSequenceTest,PreservedCallsSupportLargeDeltas)165 TEST_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 large
176   // 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 
TEST_F(FunctionSequenceTest,RewindingMultipleCalls)189 TEST_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 been
209   // 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 
TEST_F(FunctionSequenceTest,RewindingIntermediaryTailExits)216 TEST_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 been
243   // 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 
TEST_F(FunctionSequenceTest,RewindingAfterMigration)250 TEST_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 the
281   // 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 
294 class BufferManagementTest : public ::testing::Test {
295 protected:
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 
303 public:
SetUp()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 
316 constexpr size_t BufferManagementTest::kBuffers;
317 
TEST_F(BufferManagementTest,HandlesOverflow)318 TEST_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 
TEST_F(BufferManagementTest,HandlesOverflowWithArgs)334 TEST_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 
TEST_F(BufferManagementTest,HandlesOverflowWithCustomEvents)351 TEST_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 up
368   // in the Trace.
369   EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(SizeIs(kBuffers + (kBuffers / 2))));
370 }
371 
TEST_F(BufferManagementTest,HandlesFinalizedBufferQueue)372 TEST_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 logging
380   // 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 not
390   // 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 
TEST_F(BufferManagementTest,HandlesGenerationalBufferQueue)399 TEST_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, but
412   // not the function enter event, since we only have information about the new
413   // 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 } // namespace
423 } // namespace __xray
424