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 "glow/ExecutionContext/TraceEvents.h" |
18 | #include "glow/ExecutionContext/ExecutionContext.h" |
19 | #include "glow/Support/ThreadPool.h" |
20 | |
21 | #include "llvm/Support/FormatVariadic.h" |
22 | #include "llvm/Support/raw_ostream.h" |
23 | |
24 | #include <atomic> |
25 | #include <fstream> |
26 | #include <glog/logging.h> |
27 | |
28 | namespace glow { |
29 | |
30 | void writeMetadataHelper(llvm::raw_fd_ostream &file, llvm::StringRef type, |
31 | int id, llvm::StringRef name) { |
32 | file << "{\"cat\": \"__metadata\", \"ph\":\"" << TraceEvent::MetadataType |
33 | << "\", \"ts\":0, \"pid\":0, \"tid\":" << id << ", \"name\":\"" |
34 | << type.str() << "\", \"args\": {\"name\":\"" << name.str() |
35 | << "\"} },\n" ; |
36 | } |
37 | |
38 | void TraceEvent::dumpTraceEvents( |
39 | std::list<TraceEvent> &events, llvm::StringRef filename, |
40 | const std::string &processName, |
41 | const std::map<int, std::string> &threadNames) { |
42 | LOG(INFO) << "dumping " << events.size() << " trace events to " |
43 | << filename.str(); |
44 | |
45 | auto process = processName.empty() ? "glow" : processName; |
46 | std::error_code EC; |
47 | llvm::raw_fd_ostream file(filename, EC); |
48 | |
49 | // Print an error message if the output stream can't be created. |
50 | if (EC) { |
51 | LOG(ERROR) << "Unable to open file " << filename.str(); |
52 | return; |
53 | } |
54 | |
55 | file << "[\n" ; |
56 | /// Set up process name metadata. |
57 | writeMetadataHelper(file, "process_name" , 0, |
58 | processName.empty() ? "glow" : processName); |
59 | |
60 | /// And thread name metadata. |
61 | for (const auto &nameMap : threadNames) { |
62 | // Put thread name ahead of thread ID so chrome will group thread with the |
63 | // same prefix together. |
64 | writeMetadataHelper( |
65 | file, "thread_name" , nameMap.first, |
66 | llvm::formatv("{1}: {0}" , nameMap.first, nameMap.second).str()); |
67 | } |
68 | |
69 | bool first{true}; |
70 | for (const auto &event : events) { |
71 | file << (first ? "" : ",\n" ); |
72 | first = false; |
73 | |
74 | file << "{\"name\": \"" << event.name; |
75 | file << "\", \"cat\": \"" << traceLevelToString(event.level) << "\"," ; |
76 | file << "\"ph\": \"" << event.type; |
77 | file << "\", \"ts\": " << event.timestamp; |
78 | file << ", \"pid\": 0" ; |
79 | file << ", \"tid\": " << event.tid; |
80 | |
81 | if (event.type == CompleteType) { |
82 | file << ", \"dur\": " << event.duration; |
83 | } |
84 | |
85 | if (event.id != -1) { |
86 | file << ", \"id\": \"" << event.id << "\"" ; |
87 | } |
88 | |
89 | if (!event.args.empty()) { |
90 | file << ", \"args\": {" ; |
91 | bool firstArg{true}; |
92 | for (auto &pair : event.args) { |
93 | // Start with a comma unless it's the first item in the list. |
94 | file << (firstArg ? "" : ", " ); |
95 | firstArg = false; |
96 | file << "\"" << pair.first << "\" : \"" << pair.second << "\"" ; |
97 | } |
98 | file << "}" ; |
99 | } |
100 | file << "}" ; |
101 | } |
102 | file << "\n]" ; |
103 | file.close(); |
104 | } |
105 | |
106 | uint64_t TraceEvent::now() { |
107 | return std::chrono::duration_cast<std::chrono::microseconds>( |
108 | std::chrono::steady_clock::now().time_since_epoch()) |
109 | .count(); |
110 | } |
111 | |
112 | llvm::StringRef TraceEvent::traceLevelToString(TraceLevel level) { |
113 | switch (level) { |
114 | case NONE: |
115 | return "None" ; |
116 | case REQUEST: |
117 | return "Request" ; |
118 | case RUNTIME: |
119 | return "Runtime" ; |
120 | case COPY: |
121 | return "Copy" ; |
122 | case OPERATOR: |
123 | return "Operator" ; |
124 | case DEBUG: |
125 | return "Debug" ; |
126 | case STANDARD: |
127 | return "Standard" ; |
128 | } |
129 | |
130 | return "Unknown" ; |
131 | } |
132 | |
133 | void TraceContext::logTraceEvent( |
134 | llvm::StringRef name, TraceLevel level, char type, |
135 | std::map<std::string, std::string> additionalAttributes, size_t tid, |
136 | int id) { |
137 | logTraceEvent(name, level, type, TraceEvent::now(), |
138 | std::move(additionalAttributes), tid, id); |
139 | } |
140 | |
141 | void TraceContext::logTraceEvent( |
142 | llvm::StringRef name, TraceLevel level, char type, uint64_t timestamp, |
143 | std::map<std::string, std::string> additionalAttributes, size_t tid, |
144 | int id) { |
145 | if (!shouldLog(level)) { |
146 | return; |
147 | } |
148 | |
149 | TraceEvent ev(name, level, timestamp, type, tid, |
150 | std::move(additionalAttributes), id); |
151 | { |
152 | std::lock_guard<std::mutex> l(lock_); |
153 | traceEvents_.push_back(std::move(ev)); |
154 | } |
155 | } |
156 | |
157 | void TraceContext::logTraceEvent(TraceEvent &&ev) { |
158 | if (!shouldLog(ev.level)) { |
159 | return; |
160 | } |
161 | std::lock_guard<std::mutex> l(lock_); |
162 | traceEvents_.push_back(std::move(ev)); |
163 | } |
164 | |
165 | void TraceContext::logCompleteTraceEvent( |
166 | llvm::StringRef name, TraceLevel level, uint64_t startTimestamp, |
167 | std::map<std::string, std::string> additionalAttributes) { |
168 | this->logCompleteTraceEvent(name, level, startTimestamp, |
169 | std::move(additionalAttributes), |
170 | threads::getThreadId()); |
171 | } |
172 | |
173 | void TraceContext::logCompleteTraceEvent( |
174 | llvm::StringRef name, TraceLevel level, uint64_t startTimestamp, |
175 | std::map<std::string, std::string> additionalAttributes, size_t tid) { |
176 | if (!shouldLog(level)) { |
177 | return; |
178 | } |
179 | |
180 | TraceEvent ev(name, level, startTimestamp, TraceEvent::now() - startTimestamp, |
181 | tid, std::move(additionalAttributes)); |
182 | { |
183 | std::lock_guard<std::mutex> l(lock_); |
184 | traceEvents_.push_back(std::move(ev)); |
185 | } |
186 | } |
187 | |
188 | void TraceContext::setThreadName(int tid, llvm::StringRef name) { |
189 | std::lock_guard<std::mutex> l(lock_); |
190 | threadNames_[tid] = name.str(); |
191 | } |
192 | |
193 | void TraceContext::setThreadName(llvm::StringRef name) { |
194 | setThreadName(threads::getThreadId(), name); |
195 | } |
196 | |
197 | void TraceContext::dump(llvm::StringRef filename, |
198 | const std::string &processName) { |
199 | TraceEvent::dumpTraceEvents(getTraceEvents(), filename, |
200 | std::move(processName), getThreadNames()); |
201 | } |
202 | |
203 | void TraceContext::merge(TraceContext *other) { |
204 | std::lock_guard<std::mutex> l(lock_); |
205 | auto &newEvents = other->getTraceEvents(); |
206 | std::move(newEvents.begin(), newEvents.end(), |
207 | std::back_inserter(getTraceEvents())); |
208 | newEvents.clear(); |
209 | auto &names = other->getThreadNames(); |
210 | threadNames_.insert(names.begin(), names.end()); |
211 | names.clear(); |
212 | } |
213 | |
214 | void TraceContext::copy(TraceContext *other) { |
215 | std::lock_guard<std::mutex> l(lock_); |
216 | auto &newEvents = other->getTraceEvents(); |
217 | std::copy(newEvents.begin(), newEvents.end(), |
218 | std::back_inserter(getTraceEvents())); |
219 | auto &names = other->getThreadNames(); |
220 | threadNames_.insert(names.begin(), names.end()); |
221 | } |
222 | |
223 | ScopedTraceBlock::ScopedTraceBlock(TraceContext *context, TraceLevel level, |
224 | llvm::StringRef name) |
225 | : context_(context), level_(level), name_(name) { |
226 | startTimestamp_ = TraceEvent::now(); |
227 | |
228 | // A local memory fence to prevent the compiler reordering instructions to |
229 | // before taking the start timestamp. |
230 | std::atomic_signal_fence(std::memory_order_seq_cst); |
231 | } |
232 | |
233 | ScopedTraceBlock::ScopedTraceBlock(ExecutionContext *context, TraceLevel level, |
234 | llvm::StringRef name) |
235 | : ScopedTraceBlock(context ? context->getTraceContext() : nullptr, level, |
236 | name) {} |
237 | |
238 | ScopedTraceBlock::~ScopedTraceBlock() { end(); } |
239 | |
240 | ScopedTraceBlock &ScopedTraceBlock::addArg(llvm::StringRef key, |
241 | llvm::StringRef value) { |
242 | args_[key.str()] = value.str(); |
243 | return *this; |
244 | } |
245 | |
246 | void ScopedTraceBlock::end() { |
247 | /// A local memory fence to prevent the compiler reordering intructions to |
248 | /// after the end timestamp. |
249 | std::atomic_signal_fence(std::memory_order_seq_cst); |
250 | |
251 | if (!end_ && context_) { |
252 | context_->logCompleteTraceEvent(name_, level_, startTimestamp_, |
253 | std::move(args_)); |
254 | } |
255 | end_ = true; |
256 | } |
257 | } // namespace glow |
258 | |