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: |
52 | void SetUp() override { |
53 | bool Success; |
54 | BQ = std::make_unique<BufferQueue>(args: 4096, args: 1, args&: Success); |
55 | ASSERT_TRUE(Success); |
56 | ASSERT_EQ(BQ->getBuffer(Buf&: B), BufferQueue::ErrorCode::Ok); |
57 | W = std::make_unique<FDRLogWriter>(args&: B); |
58 | C = std::make_unique<FDRController<>>(args: BQ.get(), args&: B, args&: *W, args&: clock_gettime, args: 0); |
59 | } |
60 | }; |
61 | |
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(Extractor: 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 | |
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(Extractor: 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 | |
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(Extractor: DE); |
117 | EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(IsEmpty())); |
118 | } |
119 | |
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(Extractor: 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 | |
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(Extractor: 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 | |
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(Extractor: 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 | |
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(Extractor: DE); |
213 | EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(IsEmpty())); |
214 | } |
215 | |
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(Extractor: DE); |
247 | EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(IsEmpty())); |
248 | } |
249 | |
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(Extractor: 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: |
304 | void SetUp() override { |
305 | bool Success; |
306 | BQ = std::make_unique<BufferQueue>(args: sizeof(MetadataRecord) * 5 + |
307 | sizeof(FunctionRecord) * 2, |
308 | args: kBuffers, args&: Success); |
309 | ASSERT_TRUE(Success); |
310 | ASSERT_EQ(BQ->getBuffer(Buf&: B), BufferQueue::ErrorCode::Ok); |
311 | W = std::make_unique<FDRLogWriter>(args&: B); |
312 | C = std::make_unique<FDRController<>>(args: BQ.get(), args&: B, args&: *W, args&: clock_gettime, args: 0); |
313 | } |
314 | }; |
315 | |
316 | constexpr size_t BufferManagementTest::kBuffers; |
317 | |
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(Extractor: DE); |
331 | EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(SizeIs(kBuffers * 2))); |
332 | } |
333 | |
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(Extractor: DE); |
348 | EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(SizeIs(kBuffers))); |
349 | } |
350 | |
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(Extractor: 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 | |
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(Extractor: DE); |
394 | EXPECT_THAT_EXPECTED( |
395 | TraceOrErr, HasValue(ElementsAre(AllOf( |
396 | FuncId(1), RecordType(llvm::xray::RecordTypes::ENTER))))); |
397 | } |
398 | |
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(Extractor: 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 | |