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#ifndef GLOW_BACKENDS_TRACEEVENTS_H
17#define GLOW_BACKENDS_TRACEEVENTS_H
18
19#include "glow/Graph/Nodes.h"
20#include "glow/Support/ThreadPool.h"
21#include "llvm/ADT/DenseMap.h"
22
23#include <list>
24#include <map>
25#include <mutex>
26#include <vector>
27
28namespace glow {
29
30class PlaceholderBindings;
31
32/// An individual tracing event, such as the begin or end of an instruction.
33/// Designed to match the Google Trace Event Format for Chrome:
34/// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU
35struct TraceEvent {
36 /// The amount and type of TraceEvents that should appear in the trace.
37 enum TraceLevel {
38 NONE = 0x00, // No trace events.
39 REQUEST = 0x01, // Request timing events only.
40 RUNTIME = 0x02, // Glow runtime events only.
41 COPY = 0x04, // Memory copies and DMA.
42 OPERATOR = 0x08, // Backend operator instrumentation only.
43 DEBUG = 0x10, // Full debug events with extra information.
44 STANDARD = REQUEST | RUNTIME | COPY |
45 OPERATOR, // Glow runtime events and backend operator events.
46 };
47
48 /// Event Types.
49 static constexpr auto BeginType = 'B';
50 static constexpr auto EndType = 'E';
51 static constexpr auto InstantType = 'I';
52 static constexpr auto CompleteType = 'X';
53 static constexpr auto AsyncBeginType = 'b';
54 static constexpr auto AsyncEndType = 'e';
55 /// MetadataType is used for the thread name mapping.
56 static constexpr auto MetadataType = 'M';
57
58 /// Human readable name for the item, will be used to match up begin and end.
59 std::string name;
60
61 /// Time of the event, in microseconds since epoch.
62 uint64_t timestamp;
63
64 /// Type of the event, a (usually) one char code (see Event Descriptions in
65 /// the Trace Event Format spec). e.g. 'B' for begin event, 'E' for end event.
66 char type;
67
68 /// Thread Id for this event. All Events on the same tid will be shown on the
69 /// same row of the trace.
70 int tid;
71
72 /// Duration of the event (for Complete events).
73 uint64_t duration{0};
74
75 /// Async event id (-1 == no id)
76 int id{-1};
77
78 /// The type/verbosity of this event.
79 TraceLevel level{NONE};
80
81 /// Arbitrary TraceEvent arguments (from spec).
82 std::map<std::string, std::string> args;
83
84 TraceEvent(llvm::StringRef n, TraceLevel l, uint64_t ts, char c, int t,
85 int d = -1)
86 : name(n), timestamp(ts), type(c), tid(t), id(d), level(l) {}
87
88 TraceEvent(llvm::StringRef n, TraceLevel l, uint64_t ts, char c, int t,
89 std::map<std::string, std::string> a, int d = -1)
90 : name(n), timestamp(ts), type(c), tid(t), id(d), level(l), args(a) {}
91
92 TraceEvent(llvm::StringRef n, TraceLevel l, uint64_t ts, uint64_t dur, int t,
93 std::map<std::string, std::string> a = {}, int d = -1)
94 : name(n), timestamp(ts), type(CompleteType), tid(t), duration(dur),
95 id(d), level(l), args(a) {}
96
97 static void
98 dumpTraceEvents(std::list<TraceEvent> &events, llvm::StringRef filename,
99 const std::string &processName = "",
100 const std::map<int, std::string> &threadNames = {});
101
102 /// Return the current time in microseconds in the timestamp domain.
103 static uint64_t now();
104
105 /// Returns a string representation of the provided \p level.
106 static llvm::StringRef traceLevelToString(TraceLevel level);
107};
108
109using TraceLevel = TraceEvent::TraceLevel;
110
111/// Tracing / Profiling events map for a CompiledFunction.
112/// This class encodes information on how to read event metrics out of Tensors
113/// and into TraceEvents, and is used by
114/// CompiledFunction::translateTraceEvents().
115struct TraceInfo {
116 TraceInfo() = default;
117 TraceInfo(bool e, size_t d) : enabled(e), dataSize(d) {}
118
119 /// Whether tracing is enabled for this run.
120 bool enabled{false};
121
122 /// Whether the function was auto instrumented.
123 bool autoInstrumented{false};
124
125 /// The size of each item in the backing Tensor.
126 size_t dataSize{0};
127
128 struct Event {
129 size_t startIndex;
130 size_t endIndex;
131 std::string name;
132 char type;
133
134 // additional info per backend. May not be present.
135 std::string context;
136 std::string kind;
137 };
138
139 std::map<Placeholder *, std::vector<Event>> events;
140
141 void add(Placeholder *PH, size_t index, std::string name, char type) {
142 events[PH].push_back({index, 0, std::move(name), std::move(type), ""});
143 }
144
145 void add(Placeholder *PH, size_t index, std::string name, char type,
146 std::string context) {
147 events[PH].push_back(
148 {index, 0, std::move(name), std::move(type), std::move(context)});
149 }
150
151 /// Add data for a Complete TraceEvent.
152 void add(Placeholder *PH, size_t startIndex, size_t endIndex,
153 std::string name, std::string context = "", std::string kind = "") {
154 events[PH].push_back({startIndex, endIndex, std::move(name),
155 TraceEvent::CompleteType, std::move(context),
156 std::move(kind)});
157 }
158};
159
160/// A context for storing TraceEvents throughout a run (ie. between
161/// partitioned CompiledFunctions).
162class TraceContext {
163 /// The list of materialized Events filled out with timestamp and metadata.
164 std::list<TraceEvent> traceEvents_;
165
166 /// Human readable name mapping for trace Threads.
167 std::map<int, std::string> threadNames_;
168
169 /// The detail level of tracing for this run.
170 int traceLevel_{TraceLevel::NONE};
171
172 /// Lock around traceEvents_.
173 std::mutex lock_;
174
175public:
176 TraceContext(int level) : traceLevel_(level) {}
177
178 /// \returns TraceEvents for the last run.
179 std::list<TraceEvent> &getTraceEvents() { return traceEvents_; }
180
181 /// \returns the level of verbosity allowed for TraceEvents.
182 int getTraceLevel() { return traceLevel_; }
183
184 /// Sets the level of verbosity for TraceEvents.
185 void setTraceLevel(TraceLevel level) { traceLevel_ = level; }
186
187 /// \returns true if should log an event of the provided \p level.
188 bool shouldLog(TraceLevel level) { return (traceLevel_ & level) != 0; }
189
190 /// Logs a new TraceEvent at the current time with the given \p name, \p
191 /// type and optionally additional attributes and threadId.
192 void
193 logTraceEvent(llvm::StringRef name, TraceLevel level,
194 char type = TraceEvent::InstantType,
195 std::map<std::string, std::string> additionalAttributes = {},
196 size_t tid = threads::getThreadId(), int id = -1);
197
198 /// Logs a new TraceEvent at the provided \p timestamp, with the given \p
199 /// name, \p type and optionally additional attributes.
200 void
201 logTraceEvent(llvm::StringRef name, TraceLevel level, char type,
202 uint64_t timestamp,
203 std::map<std::string, std::string> additionalAttributes = {},
204 size_t tid = threads::getThreadId(), int id = -1);
205
206 /// Check if event should be logged and then log pre-created TraceEvent
207 void logTraceEvent(TraceEvent &&ev);
208
209 /// Logs a new TraceEvent with the Complete event type, the start time is
210 /// provided and uses the current time to determine duration.
211 void logCompleteTraceEvent(
212 llvm::StringRef name, TraceLevel level, uint64_t startTimestamp,
213 std::map<std::string, std::string> additionalAttributes = {});
214 void logCompleteTraceEvent(
215 llvm::StringRef name, TraceLevel level, uint64_t startTimestamp,
216 std::map<std::string, std::string> additionalAttributes, size_t tid);
217
218 /// Sets the human readable \p name for thread \tid.
219 void setThreadName(int tid, llvm::StringRef name);
220
221 /// Sets the human readable \p name for the current thread (by
222 /// threads::getThreadId()).
223 void setThreadName(llvm::StringRef name);
224
225 /// \returns the list of human readable thread names.
226 std::map<int, std::string> &getThreadNames() { return threadNames_; }
227
228 /// Dumps all TraceEvents in json format to the given \p filename,
229 /// optionally with a provided \p processName.
230 void dump(llvm::StringRef filename, const std::string &processName = "");
231
232 /// Moves all TraceEvents and thread names in \p other into this context.
233 /// This will clear in the input TraceContext.
234 void merge(TraceContext *other);
235
236 /// Moves all TraceEvents and thread names in \p other into this context.
237 /// This will clear in the input TraceContext.
238 void merge(std::unique_ptr<TraceContext> other) { merge(other.get()); }
239
240 /// Copies all TraceEvents and thread names in \p other into this context.
241 void copy(TraceContext *other);
242};
243
244/// These macros predicate the logging of a TraceEvent on a validity of the
245/// given TraceContext.
246
247/// Logs a new "Begin" event, beginning an event with duration.
248#define TRACE_EVENT_BEGIN(ctx, level, name) \
249 if (ctx) { \
250 ctx->logTraceEvent(name, level, TraceEvent::BeginType); \
251 }
252
253/// Logs a new "Begin" event, beginning an event with duration.
254#define TRACE_EVENT_BEGIN_ATTR(ctx, level, name, attributes) \
255 if (ctx) { \
256 ctx->logTraceEvent(name, level, TraceEvent::BeginType, attributes); \
257 }
258
259/// Logs a new "End" event, ending an event with duration.
260#define TRACE_EVENT_END(ctx, level, name) \
261 if (ctx) { \
262 ctx->logTraceEvent(name, level, TraceEvent::EndType); \
263 }
264
265/// Logs a new "Instant" event, which has an associated time, but no duration.
266#define TRACE_EVENT_INSTANT(ctx, level, name) \
267 if (ctx) { \
268 ctx->logTraceEvent(name, level, TraceEvent::InstantType); \
269 }
270
271/// Logs a new TraceEvent with the provided type and timestamp.
272#define TRACE_EVENT_LOG(ctx, level, name, type, ts) \
273 if (ctx) { \
274 ctx->logTraceEvent(name, level, type, ts); \
275 }
276
277/// Logs a new TraceEvent with the provided type and timestamp.
278#define TRACE_EVENT_LOG_ID(ctx, level, name, type, ts, id) \
279 if (ctx) { \
280 ctx->logTraceEvent(name, level, type, ts, {}, threads::getThreadId(), id); \
281 }
282
283/// Create TraceEvent, don't log it
284#define TRACE_EVENT_CREATE(variable, level, name, type, id) \
285 TraceEvent variable(name, level, TraceEvent::now(), type, \
286 threads::getThreadId(), {}, id)
287
288/// Logs a pre-created TraceEvent
289#define TRACE_EVENT_LOG_PRE_CREATED(ctx, ev) \
290 if (ctx) { \
291 ev.tid = threads::getThreadId(); \
292 ctx->logTraceEvent(std::move(ev)); \
293 }
294
295/// Logs a new TraceEvent which begins and ends in the current scope block.
296#define TRACE_EVENT_SCOPE(ctx, level, name) \
297 ScopedTraceBlock __event__(ctx, level, name);
298
299/// Logs a new scoped TraceEvent with the provided name, allowing multiple
300/// within the same scope.
301#define TRACE_EVENT_SCOPE_NAMED(ctx, level, name, objName) \
302 ScopedTraceBlock objName(ctx, level, name);
303
304/// End a scoped TraceEvent before its scope exits.
305#define TRACE_EVENT_SCOPE_END() __event__.end();
306
307/// End a named scoped TraceEvent before its scope exits.
308#define TRACE_EVENT_SCOPE_END_NAMED(name) name.end();
309
310class ExecutionContext;
311
312/// Helper class which uses RAII for the start and end times of a TraceEvent.
313/// At creation will create a "begin" TraceEvent and at destuction (or end())
314/// will create an "end" TraceEvent.
315class ScopedTraceBlock {
316 /// The context to log to.
317 TraceContext *context_;
318
319 /// The TraceLevel of the associated TraceEvent.
320 TraceLevel level_;
321
322 /// The name of the event.
323 llvm::StringRef name_;
324
325 /// Timestamp of the beginning of this event.
326 uint64_t startTimestamp_;
327
328 /// Additional metadata associated with the event, which will be visible in
329 /// the properties display of the event in the tracing visualizer.
330 std::map<std::string, std::string> args_;
331
332 /// Whether this event has already logged the "end" event, to avoid logging
333 /// it twice.
334 bool end_{false};
335
336public:
337 ScopedTraceBlock(TraceContext *context, TraceLevel level,
338 llvm::StringRef name);
339
340 ScopedTraceBlock(ExecutionContext *context, TraceLevel level,
341 llvm::StringRef name);
342 ~ScopedTraceBlock();
343
344 /// Adds an argument to the metadata for this object.
345 ScopedTraceBlock &addArg(llvm::StringRef key, llvm::StringRef value);
346
347 /// Triggers the "end" event before destruction of the object.
348 void end();
349};
350
351} // namespace glow
352
353#endif // GLOW_BACKENDS_TRACEEVENTS_H
354