1 // Copyright 2019 The Marl Authors.
2 //
3 // Licensed under the Apache License, Version 2.0 (the "License");
4 // you may not use this file except in compliance with the License.
5 // You may obtain a copy of the License at
6 //
7 // https://www.apache.org/licenses/LICENSE-2.0
8 //
9 // Unless required by applicable law or agreed to in writing, software
10 // distributed under the License is distributed on an "AS IS" BASIS,
11 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 // See the License for the specific language governing permissions and
13 // limitations under the License.
14
15 // The Trace API produces a trace event file that can be consumed with Chrome's
16 // about:tracing viewer.
17 // Documentation can be found at:
18 // https://www.chromium.org/developers/how-tos/trace-event-profiling-tool
19 // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit
20
21 #include "marl/trace.h"
22
23 #include "marl/defer.h"
24 #include "marl/scheduler.h"
25 #include "marl/thread.h"
26
27 #if MARL_TRACE_ENABLED
28
29 #include <atomic>
30 #include <fstream>
31
32 namespace {
33
34 // Chrome traces can choke or error on very large trace files.
35 // Limit the number of events created to this number.
36 static constexpr int MaxEvents = 100000;
37
threadFiberID(uint32_t threadID,uint32_t fiberID)38 uint64_t threadFiberID(uint32_t threadID, uint32_t fiberID) {
39 return static_cast<uint64_t>(threadID) * 31 + static_cast<uint64_t>(fiberID);
40 }
41
42 } // anonymous namespace
43
44 namespace marl {
45
get()46 Trace* Trace::get() {
47 static Trace trace;
48 return &trace;
49 }
50
Trace()51 Trace::Trace() {
52 nameThread("main");
53 thread = std::thread([&] {
54 Thread::setName("Trace worker");
55
56 auto out = std::fstream("chrome.trace", std::ios_base::out);
57
58 out << "[" << std::endl;
59 defer(out << std::endl << "]" << std::endl);
60
61 auto first = true;
62 for (int i = 0; i < MaxEvents; i++) {
63 auto event = take();
64 if (event->type() == Event::Type::Shutdown) {
65 return;
66 }
67 if (!first) {
68 out << "," << std::endl;
69 };
70 first = false;
71 out << "{" << std::endl;
72 event->write(out);
73 out << "}";
74 }
75
76 stopped = true;
77
78 while (take()->type() != Event::Type::Shutdown) {
79 }
80 });
81 }
82
~Trace()83 Trace::~Trace() {
84 put(new Shutdown());
85 thread.join();
86 }
87
nameThread(const char * fmt,...)88 void Trace::nameThread(const char* fmt, ...) {
89 if (stopped) {
90 return;
91 }
92 auto event = new NameThreadEvent();
93
94 va_list vararg;
95 va_start(vararg, fmt);
96 vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
97 va_end(vararg);
98
99 put(event);
100 }
101
beginEvent(const char * fmt,...)102 void Trace::beginEvent(const char* fmt, ...) {
103 if (stopped) {
104 return;
105 }
106 auto event = new BeginEvent();
107
108 va_list vararg;
109 va_start(vararg, fmt);
110 vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
111 va_end(vararg);
112
113 event->timestamp = timestamp();
114 put(event);
115 }
116
endEvent()117 void Trace::endEvent() {
118 if (stopped) {
119 return;
120 }
121 auto event = new EndEvent();
122 event->timestamp = timestamp();
123 put(event);
124 }
125
beginAsyncEvent(uint32_t id,const char * fmt,...)126 void Trace::beginAsyncEvent(uint32_t id, const char* fmt, ...) {
127 if (stopped) {
128 return;
129 }
130 auto event = new AsyncStartEvent();
131
132 va_list vararg;
133 va_start(vararg, fmt);
134 vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
135 va_end(vararg);
136
137 event->timestamp = timestamp();
138 event->id = id;
139 put(event);
140 }
141
endAsyncEvent(uint32_t id,const char * fmt,...)142 void Trace::endAsyncEvent(uint32_t id, const char* fmt, ...) {
143 if (stopped) {
144 return;
145 }
146 auto event = new AsyncEndEvent();
147
148 va_list vararg;
149 va_start(vararg, fmt);
150 vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
151 va_end(vararg);
152
153 event->timestamp = timestamp();
154 event->id = id;
155 put(event);
156 }
157
timestamp()158 uint64_t Trace::timestamp() {
159 auto now = std::chrono::high_resolution_clock::now();
160 auto diff =
161 std::chrono::duration_cast<std::chrono::microseconds>(now - createdAt);
162 return static_cast<uint64_t>(diff.count());
163 }
164
put(Event * event)165 void Trace::put(Event* event) {
166 auto idx = eventQueueWriteIdx++ % eventQueues.size();
167 auto& queue = eventQueues[idx];
168 std::unique_lock<std::mutex> lock(queue.mutex);
169 auto notify = queue.data.size() == 0;
170 queue.data.push(std::unique_ptr<Event>(event));
171 lock.unlock();
172 if (notify) {
173 queue.condition.notify_one();
174 }
175 }
176
take()177 std::unique_ptr<Trace::Event> Trace::take() {
178 auto idx = eventQueueReadIdx++ % eventQueues.size();
179 auto& queue = eventQueues[idx];
180 std::unique_lock<std::mutex> lock(queue.mutex);
181 queue.condition.wait(lock, [&queue] { return queue.data.size() > 0; });
182 auto event = std::move(queue.data.front());
183 queue.data.pop();
184 return event;
185 }
186
187 #define QUOTE(x) "\"" << x << "\""
188 #define INDENT " "
189
Event()190 Trace::Event::Event()
191 : threadID(std::hash<std::thread::id>()(std::this_thread::get_id())) {
192 if (auto fiber = Scheduler::Fiber::current()) {
193 fiberID = fiber->id;
194 }
195 }
196
write(std::ostream & out) const197 void Trace::Event::write(std::ostream& out) const {
198 out << INDENT << QUOTE("name") << ": " << QUOTE(name) << "," << std::endl;
199 if (categories != nullptr) {
200 out << INDENT << QUOTE("cat") << ": "
201 << "\"";
202 auto first = true;
203 for (auto category = *categories; category != nullptr; category++) {
204 if (!first) {
205 out << ",";
206 }
207 out << category;
208 }
209 out << "\"," << std::endl;
210 }
211 if (fiberID != 0) {
212 out << INDENT << QUOTE("args") << ": "
213 << "{" << std::endl
214 << INDENT << INDENT << QUOTE("fiber") << ": " << fiberID << std::endl
215 << INDENT << "}," << std::endl;
216 }
217 if (threadID != 0) {
218 out << INDENT << QUOTE("tid") << ": " << threadFiberID(threadID, fiberID)
219 << "," << std::endl;
220 }
221 out << INDENT << QUOTE("ph") << ": " << QUOTE(static_cast<char>(type()))
222 << "," << std::endl
223 << INDENT << QUOTE("pid") << ": " << processID << "," << std::endl
224 << INDENT << QUOTE("ts") << ": " << timestamp << std::endl;
225 }
226
write(std::ostream & out) const227 void Trace::NameThreadEvent::write(std::ostream& out) const {
228 out << INDENT << QUOTE("name") << ": " << QUOTE("thread_name") << ","
229 << std::endl
230 << INDENT << QUOTE("ph") << ": " << QUOTE("M") << "," << std::endl
231 << INDENT << QUOTE("pid") << ": " << processID << "," << std::endl
232 << INDENT << QUOTE("tid") << ": " << threadFiberID(threadID, fiberID)
233 << "," << std::endl
234 << INDENT << QUOTE("args") << ": {" << QUOTE("name") << ": "
235 << QUOTE(name) << "}" << std::endl;
236 }
237
write(std::ostream & out) const238 void Trace::AsyncEvent::write(std::ostream& out) const {
239 out << INDENT << QUOTE("id") << ": " << QUOTE(id) << "," << std::endl
240 << INDENT << QUOTE("cat") << ": " << QUOTE("async") << "," << std::endl;
241 Event::write(out);
242 }
243
244 } // namespace marl
245
246 #endif // MARL_TRACE_ENABLED