1/**
2 * Copyright (c) Glow Contributors. See CONTRIBUTORS file.
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17#include "BackendTestUtils.h"
18
19#include "glow/Backends/DeviceManager.h"
20#include "glow/ExecutionContext/ExecutionContext.h"
21#include "glow/ExecutionEngine/ExecutionEngine.h"
22#include "glow/Graph/Graph.h"
23#include "glow/IR/IRBuilder.h"
24#include "glow/Optimizer/GraphOptimizer/GraphOptimizer.h"
25
26#include "gtest/gtest.h"
27
28#include "llvm/ADT/STLExtras.h"
29#include "llvm/Support/Casting.h"
30#include "llvm/Support/raw_ostream.h"
31
32#include <chrono>
33#include <thread>
34
35using namespace glow;
36
37class TraceEventsTest : public ::testing::TestWithParam<std::string> {
38public:
39 ExecutionEngine EE_{GetParam()};
40 Tensor inputs{ElemKind::FloatTy, {1, 32, 32, 3}};
41 Placeholder *inputPH;
42
43 Function *F;
44
45 void SetUp() override {
46 auto &mod = EE_.getModule();
47 inputPH = mod.createPlaceholder(ElemKind::FloatTy, {1, 32, 32, 3}, "input",
48 false);
49 F = mod.createFunction("main");
50 }
51
52 // Split a sample network into four parts to make it easy to insert
53 // TraceEventNodes.
54 NodeValue part_one(Function *F, ExecutionContext &context) {
55 auto *CV0 = F->createConv(*context.getPlaceholderBindings(), "conv1",
56 inputPH, 16, 5, 1, 2, 1);
57 auto *RL0 = F->createRELU("relu1", CV0);
58 auto *MP0 = F->createMaxPool("pool1", RL0, 2, 2, 0);
59 return MP0->getResult();
60 }
61
62 NodeValue part_two(Function *F, ExecutionContext &context, NodeValue last) {
63 auto *CV1 = F->createConv(*context.getPlaceholderBindings(), "conv2", last,
64 20, 5, 1, 2, 1);
65 auto *RL1 = F->createRELU("relu2", CV1);
66 auto *MP1 = F->createMaxPool("pool2", RL1, 2, 2, 0);
67 return MP1->getResult();
68 }
69
70 NodeValue part_three(Function *F, ExecutionContext &context, NodeValue last) {
71 auto *CV2 = F->createConv(*context.getPlaceholderBindings(), "conv3", last,
72 20, 5, 1, 2, 1);
73 auto *RL2 = F->createRELU("relu3", CV2);
74 auto *MP2 = F->createMaxPool("pool3", RL2, 2, 2, 0);
75 return MP2->getResult();
76 }
77
78 Node *part_four(Function *F, ExecutionContext &context, NodeValue last) {
79 auto *ex = F->getParent()->createPlaceholder(ElemKind::Int64ITy, {1, 1},
80 "exp", false);
81 auto *FCL1 = F->createFullyConnected(*context.getPlaceholderBindings(),
82 "fc", last, 10);
83 auto *RL3 = F->createRELU("relu4", FCL1);
84 auto *SM = F->createSoftMax("sm", RL3, ex);
85 auto *S = F->createSave("ret", SM);
86 return S;
87 }
88
89 Placeholder *createEventPlaceholder(dim_t numEvents) {
90 std::unique_ptr<Backend> backend(createBackend(EE_.getBackendName()));
91 return EE_.getModule().createPlaceholder(
92 ElemKind::Int64ITy,
93 {numEvents, (dim_t)backend->getTraceEventDataSize() /
94 Type::getElementSize(ElemKind::Int64ITy)},
95 "", false);
96 }
97
98 // Compares generated TraceEvents with their expected names and types.
99 void checkEventMetadata(const std::list<TraceEvent> &traceEvents,
100 std::vector<std::pair<std::string, char>> expected) {
101
102 ASSERT_EQ(traceEvents.size(), expected.size());
103 unsigned index = 0;
104 for (const auto &event : traceEvents) {
105 const auto &pair = expected[index++];
106 ASSERT_EQ(pair.first, event.name);
107 ASSERT_EQ(pair.second, event.type);
108 }
109 }
110
111 // In the function below we're trying to compare auto instrumented trace
112 // output with optimized model graph. Since the code generation may make
113 // further changes to the graph representation we limit checking to a set of
114 // convolution / maxpool / cpumaxsplat kinds which are never changed.
115 std::set<std::string> checkedKinds = {"convolution", "maxpool",
116 "cpumaxsplat"};
117
118 template <class ExecutionEngineTy>
119 std::vector<std::pair<std::string, std::string>>
120 prepareKindsForComparison(ExecutionEngineTy &ExecutionEngine) {
121 std::vector<std::pair<std::string, std::string>> expectedKinds;
122 for (auto &i :
123 ExecutionEngine.getModule().getFunctions().front()->getNodes()) {
124 std::string kind(Kinded::getKindName(i.getKind()));
125 std::transform(kind.begin(), kind.end(), kind.begin(),
126 [](unsigned char c) { return ::tolower(c); });
127 if (checkedKinds.find(kind) != checkedKinds.end()) {
128 std::string name(Module::getPrefix(i.getName()));
129 // Let's remove all digits at the end of name since the code generation
130 // may create new nodes with names consisting of existing node names
131 // and additional numeric indexes
132 expectedKinds.emplace_back(name, kind);
133 }
134 }
135 std::sort(expectedKinds.begin(), expectedKinds.end());
136 return expectedKinds;
137 }
138
139 void checkEventMetadata(
140 const std::list<TraceEvent> &traceEvents,
141 const std::vector<std::pair<std::string, std::string>> &expected) {
142
143 const auto &backend = GetParam();
144 if (backend != "Interpreter" && backend != "CPU") {
145 return;
146 }
147
148 auto map_element = [](const std::map<std::string, std::string> &m,
149 const std::string &k) {
150 return m.find(k) == m.end() ? std::string() : m.find(k)->second;
151 };
152 std::vector<std::pair<std::string, std::string>> events_for_checking;
153 for (auto &i : traceEvents) {
154 std::string kind = map_element(i.args, "kind");
155 if (checkedKinds.find(kind) != checkedKinds.end()) {
156 std::string name(Module::getPrefix(i.name));
157 // Let's remove all digits at the end of the name since the code
158 // generation may create new nodes with names consisting of existing
159 // node names and additional numeric indexes
160 events_for_checking.emplace_back(name, kind);
161 }
162 }
163 std::sort(events_for_checking.begin(), events_for_checking.end());
164 ASSERT_EQ(expected, events_for_checking);
165 }
166
167 // Check timestamps are non-zero and monotonically increasing.
168 void checkEventTimestamps(const std::list<TraceEvent> &traceEvents) {
169 uint64_t last = 0;
170 for (const auto &event : traceEvents) {
171 ASSERT_NE(event.timestamp, 0);
172 ASSERT_GE(event.timestamp, last);
173 last = event.timestamp;
174 }
175 }
176};
177
178TEST_P(TraceEventsTest, manualEvents) {
179 CHECK_IF_ENABLED();
180 ExecutionContext context;
181 context.setTraceContext(
182 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
183
184 size_t numEvents = 4;
185 auto *eventData = createEventPlaceholder(numEvents);
186 unsigned eventId = 0;
187
188 F->createTraceEvent("first half", "B", eventData, eventId++);
189 auto n = part_one(F, context);
190 n = part_two(F, context, n);
191
192 F->createTraceEvent("first half", "E", eventData, eventId++);
193 F->createTraceEvent("second half", "B", eventData, eventId++);
194
195 n = part_three(F, context, n);
196 part_four(F, context, n);
197
198 F->createTraceEvent("second half", "E", eventData, eventId++);
199
200 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
201 CompilationContext cctx;
202 cctx.compMode = CompilationMode::Infer;
203 EE_.compile(cctx);
204
205 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
206 {&inputs});
207 EE_.run(context);
208
209 auto &traceEvents = context.getTraceContext()->getTraceEvents();
210 ASSERT_EQ(traceEvents.size(), numEvents);
211 checkEventMetadata(traceEvents, {{"first half", 'B'},
212 {"first half", 'E'},
213 {"second half", 'B'},
214 {"second half", 'E'}});
215
216 checkEventTimestamps(traceEvents);
217
218 // Check that each timestamp matches the tensor
219 auto eventHandle =
220 context.getPlaceholderBindings()->get(eventData)->getHandle<int64_t>();
221 eventId = 0;
222 for (const auto &event : traceEvents) {
223 ASSERT_EQ(event.timestamp, eventHandle.at({eventId++, 0}));
224 }
225}
226
227TEST_P(TraceEventsTest, incompleteCoverage) {
228 CHECK_IF_ENABLED();
229 ExecutionContext context;
230 context.setTraceContext(
231 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
232
233 size_t numEvents = 2;
234 auto *eventData = createEventPlaceholder(numEvents);
235 unsigned eventId = 0;
236
237 auto n = part_one(F, context);
238 n = part_two(F, context, n);
239
240 F->createTraceEvent("second half", "B", eventData, eventId++);
241
242 n = part_three(F, context, n);
243 part_four(F, context, n);
244
245 F->createTraceEvent("second half", "E", eventData, eventId++);
246
247 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
248 CompilationContext cctx;
249 cctx.compMode = CompilationMode::Infer;
250 EE_.compile(cctx);
251
252 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
253 {&inputs});
254 EE_.run(context);
255
256 auto &traceEvents = context.getTraceContext()->getTraceEvents();
257
258 ASSERT_GE(traceEvents.size(), numEvents);
259 checkEventMetadata(traceEvents, {{"second half", 'B'}, {"second half", 'E'}});
260
261 checkEventTimestamps(traceEvents);
262
263 // Check that each timestamp matches the tensor
264 auto eventHandle =
265 context.getPlaceholderBindings()->get(eventData)->getHandle<int64_t>();
266 eventId = 0;
267 for (const auto &event : traceEvents) {
268 ASSERT_EQ(event.timestamp, eventHandle.at({eventId++, 0}));
269 }
270}
271
272TEST_P(TraceEventsTest, internalGap) {
273 CHECK_IF_ENABLED();
274 ExecutionContext context;
275 context.setTraceContext(
276 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
277
278 size_t numEvents = 2;
279 auto *eventData = createEventPlaceholder(numEvents);
280 unsigned eventId = 0;
281
282 auto n = part_one(F, context);
283
284 F->createTraceEvent("middle section", "B", eventData, eventId++);
285 n = part_two(F, context, n);
286 n = part_three(F, context, n);
287 F->createTraceEvent("middle section", "E", eventData, eventId++);
288
289 part_four(F, context, n);
290
291 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
292 CompilationContext cctx;
293 cctx.compMode = CompilationMode::Infer;
294 EE_.compile(cctx);
295
296 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
297 {&inputs});
298 EE_.run(context);
299
300 auto &traceEvents = context.getTraceContext()->getTraceEvents();
301
302 ASSERT_GE(traceEvents.size(), numEvents);
303 checkEventMetadata(traceEvents,
304 {{"middle section", 'B'}, {"middle section", 'E'}});
305
306 checkEventTimestamps(traceEvents);
307
308 // Check that each timestamp matches the tensor
309 auto eventHandle =
310 context.getPlaceholderBindings()->get(eventData)->getHandle<int64_t>();
311 eventId = 0;
312 for (const auto &event : traceEvents) {
313 ASSERT_EQ(event.timestamp, eventHandle.at({eventId++, 0}));
314 }
315}
316
317TEST_P(TraceEventsTest, automaticInstrumentation) {
318 CHECK_IF_ENABLED();
319 ExecutionContext context;
320 context.setTraceContext(
321 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
322
323 auto n = part_one(F, context);
324 n = part_two(F, context, n);
325 n = part_three(F, context, n);
326 part_four(F, context, n);
327
328 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
329 CompilationContext cctx;
330 cctx.compMode = CompilationMode::Infer;
331 cctx.backendOpts.autoInstrument = true;
332 EE_.compile(cctx);
333
334 auto expectedKinds = prepareKindsForComparison(EE_);
335
336 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
337 {&inputs});
338 EE_.run(context);
339
340 auto &traceEvents = context.getTraceContext()->getTraceEvents();
341
342 ASSERT_GT(traceEvents.size(), 0);
343 checkEventMetadata(traceEvents, expectedKinds);
344 checkEventTimestamps(traceEvents);
345}
346
347TEST_P(TraceEventsTest, manualAndAutomatic) {
348 CHECK_IF_ENABLED();
349 ExecutionContext context;
350 context.setTraceContext(
351 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
352
353 size_t numEvents = 4;
354 auto *eventData = createEventPlaceholder(numEvents);
355 unsigned eventId = 0;
356
357 F->createTraceEvent("first half", "B", eventData, eventId++);
358 auto n = part_one(F, context);
359 n = part_two(F, context, n);
360
361 F->createTraceEvent("first half", "E", eventData, eventId++);
362 F->createTraceEvent("second half", "B", eventData, eventId++);
363
364 n = part_three(F, context, n);
365 part_four(F, context, n);
366
367 F->createTraceEvent("second half", "E", eventData, eventId++);
368
369 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
370 CompilationContext cctx;
371 cctx.compMode = CompilationMode::Infer;
372 cctx.backendOpts.autoInstrument = true;
373 EE_.compile(cctx);
374
375 auto expectedKinds = prepareKindsForComparison(EE_);
376
377 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
378 {&inputs});
379 EE_.run(context);
380
381 auto &traceEvents = context.getTraceContext()->getTraceEvents();
382 // Can't use CheckTimestamps here because the manual & auto inserted
383 // timestamps are not sorted by time.
384
385 ASSERT_GT(traceEvents.size(), numEvents);
386 size_t manualEvents = 0;
387 for (const auto &event : traceEvents) {
388 if (event.name == "first half" || event.name == "second half") {
389 manualEvents++;
390 }
391 }
392 ASSERT_EQ(manualEvents, numEvents);
393 checkEventMetadata(traceEvents, expectedKinds);
394}
395
396/// Compile the same function twice with auto instrumentation on - ensure that
397/// instrumentation doesn't break future compiles.
398TEST_P(TraceEventsTest, twoCompiles) {
399 CHECK_IF_ENABLED();
400 ExecutionContext context;
401 context.setTraceContext(
402 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
403
404 size_t numEvents = 4;
405 auto *eventData = createEventPlaceholder(numEvents);
406 unsigned eventId = 0;
407
408 F->createTraceEvent("first half", "B", eventData, eventId++);
409 auto n = part_one(F, context);
410 F->createTraceEvent("first half", "E", eventData, eventId++);
411 F->createTraceEvent("second half", "B", eventData, eventId++);
412 part_four(F, context, n);
413 F->createTraceEvent("second half", "E", eventData, eventId++);
414
415 ExecutionContext context2{context.clone()};
416 context2.setTraceContext(
417 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
418
419 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
420
421 std::unique_ptr<Backend> backend(createBackend(EE_.getBackendName()));
422 CompilationContext cctx;
423 cctx.compMode = CompilationMode::Infer;
424 cctx.backendOpts.autoInstrument = true;
425 cctx.backendOpts.collectConstants = true;
426 EXIT_ON_ERR(::glow::optimizeFunction(F, *backend, cctx));
427
428 std::string name = F->getName().str();
429 auto config =
430 glow::make_unique<runtime::DeviceConfig>(backend->getBackendName());
431 std::unique_ptr<runtime::DeviceManager> device(
432 runtime::DeviceManager::createDeviceManager(*config));
433 EXIT_ON_ERR(device->init());
434 auto func1 = EXIT_ON_ERR(backend->compile(F, cctx.backendOpts));
435
436 insertCompiledFunction(name, func1.get(), device.get(), &EE_.getModule());
437
438 std::string name2 = name + "2";
439 auto func2 = EXIT_ON_ERR(backend->compile(F, cctx.backendOpts));
440 insertCompiledFunction(name2, func2.get(), device.get(), &EE_.getModule());
441 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
442 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
443 {&inputs});
444
445 runOnDevice(context, name, device.get());
446 auto &traceEvents = context.getTraceContext()->getTraceEvents();
447
448 ASSERT_GT(traceEvents.size(), 0);
449
450 context2.getPlaceholderBindings()->allocate(
451 EE_.getModule().getPlaceholders());
452
453 // Add a little delay to ensure the timestamps don't happen to occur in the
454 // same millisecond.
455 std::this_thread::sleep_for(std::chrono::milliseconds(1));
456
457 updateInputPlaceholders(*context2.getPlaceholderBindings(), {inputPH},
458 {&inputs});
459 runOnDevice(context2, name2, device.get());
460 auto &traceEvents2 = context2.getTraceContext()->getTraceEvents();
461
462 ASSERT_GT(traceEvents2.size(), 0);
463
464 ASSERT_EQ(traceEvents.size(), traceEvents2.size());
465
466 auto iter = traceEvents.begin();
467 auto iter2 = traceEvents2.begin();
468 while (iter != traceEvents.end()) {
469 ASSERT_EQ(iter2->name, iter->name);
470 ASSERT_EQ(iter2->type, iter->type);
471 ASSERT_NE(iter2->timestamp, iter->timestamp);
472 ++iter;
473 ++iter2;
474 }
475}
476
477TEST_P(TraceEventsTest, onlyTraceEvents) {
478 CHECK_IF_ENABLED();
479 ExecutionContext context;
480 context.setTraceContext(
481 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
482
483 size_t numEvents = 16;
484 auto *eventData = createEventPlaceholder(numEvents);
485 unsigned eventId = 0;
486
487 std::vector<std::pair<std::string, char>> expected;
488 for (unsigned eventId = 0; eventId < numEvents; ++eventId) {
489 std::string name = "event_" + std::to_string(eventId);
490 F->createTraceEvent(name, "X", eventData, eventId);
491 expected.push_back({name, 'X'});
492 }
493
494 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
495 CompilationContext cctx;
496 cctx.compMode = CompilationMode::Infer;
497 EE_.compile(cctx);
498
499 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
500 {&inputs});
501 EE_.run(context);
502
503 auto &traceEvents = context.getTraceContext()->getTraceEvents();
504
505 ASSERT_GE(traceEvents.size(), numEvents);
506 checkEventMetadata(traceEvents, expected);
507 checkEventTimestamps(traceEvents);
508
509 // Check that each timestamp matches the tensor
510 auto eventHandle =
511 context.getPlaceholderBindings()->get(eventData)->getHandle<int64_t>();
512 eventId = 0;
513 for (const auto &event : traceEvents) {
514 ASSERT_EQ(event.timestamp, eventHandle.at({eventId++, 0}));
515 }
516}
517
518TEST_P(TraceEventsTest, multipleBackingTensors) {
519 CHECK_IF_ENABLED();
520 ExecutionContext context;
521 context.setTraceContext(
522 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
523
524 size_t numEvents = 6;
525 auto *eventData1 = createEventPlaceholder(3);
526 auto *eventData2 = createEventPlaceholder(3);
527
528 F->createTraceEvent("event1", "B", eventData1, 0);
529 auto n = part_one(F, context);
530 F->createTraceEvent("event1", "E", eventData1, 1);
531
532 F->createTraceEvent("event2", "B", eventData2, 0);
533 n = part_two(F, context, n);
534 F->createTraceEvent("event2", "E", eventData2, 1);
535
536 // now lets split between two tensors
537
538 auto *eventData3 = createEventPlaceholder(1);
539 auto *eventData4 = createEventPlaceholder(1);
540
541 F->createTraceEvent("event3", "B", eventData3, 0);
542 n = part_three(F, context, n);
543 part_four(F, context, n);
544 F->createTraceEvent("event3", "E", eventData4, 0);
545
546 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
547 CompilationContext cctx;
548 cctx.compMode = CompilationMode::Infer;
549 EE_.compile(cctx);
550
551 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
552 {&inputs});
553 EE_.run(context);
554
555 auto &traceEvents = context.getTraceContext()->getTraceEvents();
556
557 ASSERT_GE(traceEvents.size(), numEvents);
558
559 // Can't use checkEventMetadata since events aren't ordered
560 size_t event1{0}, event2{0}, event3{0};
561 for (const auto &event : traceEvents) {
562 if (event.name == "event1") {
563 event1++;
564 } else if (event.name == "event2") {
565 event2++;
566 } else if (event.name == "event3") {
567 event3++;
568 } else {
569 ASSERT_FALSE("unknown event name");
570 }
571 }
572
573 ASSERT_EQ(event1, 2);
574 ASSERT_EQ(event2, 2);
575 ASSERT_EQ(event3, 2);
576}
577
578TEST_P(TraceEventsTest, multipleRunsAreDistinct) {
579 CHECK_IF_ENABLED();
580 ExecutionContext context;
581 context.setTraceContext(
582 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
583
584 size_t numEvents = 4;
585 auto *eventData = createEventPlaceholder(numEvents);
586 unsigned eventId = 0;
587
588 F->createTraceEvent("first half", "B", eventData, eventId++);
589 auto n = part_one(F, context);
590 n = part_two(F, context, n);
591
592 F->createTraceEvent("first half", "E", eventData, eventId++);
593 F->createTraceEvent("second half", "B", eventData, eventId++);
594
595 n = part_three(F, context, n);
596 part_four(F, context, n);
597
598 F->createTraceEvent("second half", "E", eventData, eventId++);
599
600 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
601 CompilationContext cctx;
602 cctx.compMode = CompilationMode::Infer;
603 EE_.compile(cctx);
604
605 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
606 {&inputs});
607
608 ExecutionContext context2{context.clone()};
609 context2.setTraceContext(
610 glow::make_unique<TraceContext>(TraceLevel::OPERATOR));
611
612 // run twice
613 EE_.run(context);
614 EE_.run(context2);
615
616 auto &traceEvents = context.getTraceContext()->getTraceEvents();
617 auto &traceEvents2 = context2.getTraceContext()->getTraceEvents();
618
619 ASSERT_GE(traceEvents.size(), numEvents);
620 ASSERT_GE(traceEvents2.size(), numEvents);
621
622 auto iter = traceEvents.begin();
623 auto iter2 = traceEvents2.begin();
624 while (iter != traceEvents.end()) {
625 ASSERT_EQ(iter2->name, iter->name);
626 ASSERT_EQ(iter2->type, iter->type);
627 // timestamps are not equal
628 ASSERT_NE(iter2->timestamp, iter->timestamp);
629 ++iter;
630 ++iter2;
631 }
632}
633
634TEST_P(TraceEventsTest, deviceManagerEvents) {
635 CHECK_IF_ENABLED();
636 ExecutionContext context;
637 context.setTraceContext(glow::make_unique<TraceContext>(
638 TraceLevel::RUNTIME | TraceLevel::OPERATOR));
639
640 auto n = part_one(F, context);
641 n = part_two(F, context, n);
642 n = part_three(F, context, n);
643 part_four(F, context, n);
644
645 context.getPlaceholderBindings()->allocate(EE_.getModule().getPlaceholders());
646
647 CompilationContext cctx;
648 cctx.compMode = CompilationMode::Infer;
649 EE_.compile(cctx);
650
651 updateInputPlaceholders(*context.getPlaceholderBindings(), {inputPH},
652 {&inputs});
653 EE_.run(context);
654
655 auto &traceEvents = context.getTraceContext()->getTraceEvents();
656
657 ASSERT_GT(traceEvents.size(), 0);
658 // CompleteEvents are not necessarily monotonically increasing since they are
659 // added to the log when they end, not when they start.
660}
661
662/// Test that ScopedTraceBlocks can be nested.
663TEST(TraceEventsTest, nestedScopedEvents) {
664 CHECK_IF_ENABLED();
665 ExecutionContext context;
666 context.setTraceContext(glow::make_unique<TraceContext>(
667 TraceLevel::RUNTIME | TraceLevel::OPERATOR));
668
669 TraceContext *tc = context.getTraceContext();
670
671 ScopedTraceBlock block_one(tc, TraceLevel::RUNTIME, "one");
672 {
673 ScopedTraceBlock block_two(tc, TraceLevel::RUNTIME, "two");
674 /* sleep_override */ std::this_thread::sleep_for(
675 std::chrono::milliseconds(1));
676 }
677
678 {
679 ScopedTraceBlock block_three(tc, TraceLevel::RUNTIME, "three");
680 /* sleep_override */ std::this_thread::sleep_for(
681 std::chrono::milliseconds(1));
682 {
683 ScopedTraceBlock block_four(tc, TraceLevel::RUNTIME, "four");
684 /* sleep_override */ std::this_thread::sleep_for(
685 std::chrono::milliseconds(1));
686 }
687 }
688
689 block_one.end();
690
691 auto &traceEvents = tc->getTraceEvents();
692 ASSERT_EQ(traceEvents.size(), 4);
693 llvm::StringMap<uint64_t> durations;
694 for (auto &tc : traceEvents) {
695 durations[tc.name] = tc.duration;
696 }
697
698 ASSERT_GE(durations["one"], durations["two"] + durations["three"]);
699 ASSERT_GE(durations["three"], durations["four"]);
700}
701
702/// Test that nesting scoped events work with the macro versions.
703TEST(TraceEventsTest, nestedScopedEventsMacro) {
704 CHECK_IF_ENABLED();
705 ExecutionContext context;
706 context.setTraceContext(glow::make_unique<TraceContext>(
707 TraceLevel::RUNTIME | TraceLevel::OPERATOR));
708
709 TraceContext *tc = context.getTraceContext();
710
711 TRACE_EVENT_SCOPE(tc, TraceLevel::RUNTIME, "one");
712 {
713 TRACE_EVENT_SCOPE(tc, TraceLevel::RUNTIME, "two");
714 /* sleep_override */ std::this_thread::sleep_for(
715 std::chrono::milliseconds(1));
716 }
717
718 {
719 TRACE_EVENT_SCOPE(tc, TraceLevel::RUNTIME, "three");
720 /* sleep_override */ std::this_thread::sleep_for(
721 std::chrono::milliseconds(1));
722 {
723 TRACE_EVENT_SCOPE(tc, TraceLevel::RUNTIME, "four");
724 /* sleep_override */ std::this_thread::sleep_for(
725 std::chrono::milliseconds(1));
726 }
727 }
728
729 TRACE_EVENT_SCOPE_END();
730
731 auto &traceEvents = tc->getTraceEvents();
732 ASSERT_EQ(traceEvents.size(), 4);
733 llvm::StringMap<uint64_t> durations;
734 for (auto &tc : traceEvents) {
735 durations[tc.name] = tc.duration;
736 }
737
738 ASSERT_GE(durations["one"], durations["two"] + durations["three"]);
739 ASSERT_GT(durations["three"], durations["four"]);
740}
741
742/// Test that terminating a scoped event logs final timestamp at the end, not at
743/// scope exit.
744TEST(TraceEventsTest, nestedScopedEventsTerm) {
745 CHECK_IF_ENABLED();
746 ExecutionContext context;
747 context.setTraceContext(glow::make_unique<TraceContext>(
748 TraceLevel::RUNTIME | TraceLevel::OPERATOR));
749
750 TraceContext *tc = context.getTraceContext();
751
752 {
753 TRACE_EVENT_SCOPE_NAMED(tc, TraceLevel::RUNTIME, "one", one);
754 TRACE_EVENT_SCOPE_NAMED(tc, TraceLevel::RUNTIME, "two", two);
755 /* sleep_override */ std::this_thread::sleep_for(
756 std::chrono::milliseconds(1));
757 TRACE_EVENT_SCOPE_END_NAMED(one);
758 /* sleep_override */ std::this_thread::sleep_for(
759 std::chrono::milliseconds(1));
760 }
761
762 {
763 TRACE_EVENT_SCOPE_NAMED(tc, TraceLevel::RUNTIME, "three", three);
764 TRACE_EVENT_SCOPE_NAMED(tc, TraceLevel::RUNTIME, "four", four);
765 {
766 TRACE_EVENT_SCOPE_NAMED(tc, TraceLevel::RUNTIME, "five", five);
767 /* sleep_override */ std::this_thread::sleep_for(
768 std::chrono::milliseconds(1));
769 TRACE_EVENT_SCOPE_END_NAMED(four);
770 /* sleep_override */ std::this_thread::sleep_for(
771 std::chrono::milliseconds(1));
772 }
773 /* sleep_override */ std::this_thread::sleep_for(
774 std::chrono::milliseconds(1));
775 }
776
777 auto &traceEvents = tc->getTraceEvents();
778 ASSERT_EQ(traceEvents.size(), 5);
779 llvm::StringMap<uint64_t> durations;
780 for (auto &tc : traceEvents) {
781 durations[tc.name] = tc.duration;
782 }
783
784 // Two should have two sleeps to one's one.
785 ASSERT_GT(durations["two"], durations["one"]);
786
787 // Three includes both four and five but theres some overlap so can't just
788 // add.
789 ASSERT_GT(durations["three"], durations["four"]);
790 ASSERT_GT(durations["three"], durations["five"]);
791 ASSERT_GT(durations["five"], durations["four"]);
792}
793
794TEST(TraceEventsTest, TraceLevels) {
795 CHECK_IF_ENABLED();
796 std::array<TraceLevel, 5> levels = {{TraceLevel::NONE, TraceLevel::REQUEST,
797 TraceLevel::RUNTIME, TraceLevel::COPY,
798 TraceLevel::OPERATOR}};
799 for (auto L : levels) {
800 TraceContext context(L);
801 for (auto evl : levels) {
802 context.logTraceEvent("event", evl);
803 }
804
805 if (L == TraceLevel::NONE) {
806 EXPECT_EQ(context.getTraceEvents().size(), 0);
807 } else {
808 ASSERT_EQ(context.getTraceEvents().size(), 1);
809 ASSERT_EQ(context.getTraceEvents().front().name, "event");
810 }
811 }
812
813 TraceContext context(TraceLevel::STANDARD);
814 for (auto evl : levels) {
815 context.logTraceEvent("event", evl);
816 }
817 ASSERT_EQ(context.getTraceEvents().size(), 4);
818}
819
820TEST(TraceEventsTest, MergeEvents) {
821 auto tc1 = glow::make_unique<TraceContext>(TraceLevel::RUNTIME |
822 TraceLevel::OPERATOR);
823 auto tc2 = glow::make_unique<TraceContext>(TraceLevel::RUNTIME |
824 TraceLevel::OPERATOR);
825
826 TRACE_EVENT_BEGIN(tc1, TraceLevel::RUNTIME, "ev1");
827 TRACE_EVENT_END(tc1, TraceLevel::RUNTIME, "ev1");
828
829 ASSERT_EQ(tc1->getTraceEvents().size(), 2);
830 ASSERT_EQ(tc2->getTraceEvents().size(), 0);
831
832 tc2->merge(tc1.get());
833
834 ASSERT_EQ(tc1->getTraceEvents().size(), 0);
835 ASSERT_EQ(tc2->getTraceEvents().size(), 2);
836
837 TRACE_EVENT_BEGIN(tc1, TraceLevel::RUNTIME, "ev2");
838 TRACE_EVENT_END(tc1, TraceLevel::RUNTIME, "ev2");
839
840 ASSERT_EQ(tc1->getTraceEvents().size(), 2);
841 ASSERT_EQ(tc2->getTraceEvents().size(), 2);
842
843 tc2->merge(tc1.get());
844
845 ASSERT_EQ(tc1->getTraceEvents().size(), 0);
846 ASSERT_EQ(tc2->getTraceEvents().size(), 4);
847}
848
849INSTANTIATE_BACKEND_TEST(TraceEventsTest);
850