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
28namespace glow {
29
30void 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
38void 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
106uint64_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
112llvm::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
133void 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
141void 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
157void 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
165void 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
173void 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
188void TraceContext::setThreadName(int tid, llvm::StringRef name) {
189 std::lock_guard<std::mutex> l(lock_);
190 threadNames_[tid] = name.str();
191}
192
193void TraceContext::setThreadName(llvm::StringRef name) {
194 setThreadName(threads::getThreadId(), name);
195}
196
197void TraceContext::dump(llvm::StringRef filename,
198 const std::string &processName) {
199 TraceEvent::dumpTraceEvents(getTraceEvents(), filename,
200 std::move(processName), getThreadNames());
201}
202
203void 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
214void 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
223ScopedTraceBlock::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
233ScopedTraceBlock::ScopedTraceBlock(ExecutionContext *context, TraceLevel level,
234 llvm::StringRef name)
235 : ScopedTraceBlock(context ? context->getTraceContext() : nullptr, level,
236 name) {}
237
238ScopedTraceBlock::~ScopedTraceBlock() { end(); }
239
240ScopedTraceBlock &ScopedTraceBlock::addArg(llvm::StringRef key,
241 llvm::StringRef value) {
242 args_[key.str()] = value.str();
243 return *this;
244}
245
246void 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