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 | |
35 | using namespace glow; |
36 | |
37 | class TraceEventsTest : public ::testing::TestWithParam<std::string> { |
38 | public: |
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 | |
178 | TEST_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 | |
227 | TEST_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 | |
272 | TEST_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 | |
317 | TEST_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 | |
347 | TEST_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. |
398 | TEST_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 | |
477 | TEST_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 | |
518 | TEST_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 | |
578 | TEST_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 | |
634 | TEST_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. |
663 | TEST(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. |
703 | TEST(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. |
744 | TEST(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 | |
794 | TEST(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 | |
820 | TEST(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 | |
849 | INSTANTIATE_BACKEND_TEST(TraceEventsTest); |
850 | |