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 | |
28 | namespace glow { |
29 | |
30 | class 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 |
35 | struct 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 | |
109 | using 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(). |
115 | struct 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). |
162 | class 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 | |
175 | public: |
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 | |
310 | class 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. |
315 | class 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 | |
336 | public: |
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 | |