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 #include <unordered_set>
32
33 namespace {
34
35 // Chrome traces can choke or error on very large trace files.
36 // Limit the number of events created to this number.
37 static constexpr int MaxEvents = 100000;
38
threadFiberID(uint32_t threadID,uint32_t fiberID)39 uint64_t threadFiberID(uint32_t threadID, uint32_t fiberID) {
40 return static_cast<uint64_t>(threadID) * 31 + static_cast<uint64_t>(fiberID);
41 }
42
43 } // anonymous namespace
44
45 namespace marl {
46
get()47 Trace* Trace::get() {
48 static Trace trace;
49 return &trace;
50 }
51
Trace()52 Trace::Trace() {
53 nameThread("main");
54 thread = std::thread([&] {
55 Thread::setName("Trace worker");
56
57 auto out = std::fstream("chrome.trace", std::ios_base::out);
58
59 out << "[" << std::endl;
60 defer(out << std::endl << "]" << std::endl);
61
62 auto first = true;
63 for (int i = 0; i < MaxEvents; i++) {
64 auto event = take();
65 if (event->type() == Event::Type::Shutdown) {
66 return;
67 }
68 if (!first) {
69 out << "," << std::endl;
70 };
71 first = false;
72 out << "{" << std::endl;
73 event->write(out);
74 out << "}";
75 }
76
77 stopped = true;
78
79 while (take()->type() != Event::Type::Shutdown) {
80 }
81 });
82 }
83
~Trace()84 Trace::~Trace() {
85 put(new Shutdown());
86 thread.join();
87 }
88
nameThread(const char * fmt,...)89 void Trace::nameThread(const char* fmt, ...) {
90 if (stopped) {
91 return;
92 }
93 auto event = new NameThreadEvent();
94
95 va_list vararg;
96 va_start(vararg, fmt);
97 vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
98 va_end(vararg);
99
100 put(event);
101 }
102
beginEvent(const char * fmt,...)103 void Trace::beginEvent(const char* fmt, ...) {
104 if (stopped) {
105 return;
106 }
107 auto event = new BeginEvent();
108
109 va_list vararg;
110 va_start(vararg, fmt);
111 vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
112 va_end(vararg);
113
114 event->timestamp = timestamp();
115 put(event);
116 }
117
endEvent()118 void Trace::endEvent() {
119 if (stopped) {
120 return;
121 }
122 auto event = new EndEvent();
123 event->timestamp = timestamp();
124 put(event);
125 }
126
beginAsyncEvent(uint32_t id,const char * fmt,...)127 void Trace::beginAsyncEvent(uint32_t id, const char* fmt, ...) {
128 if (stopped) {
129 return;
130 }
131 auto event = new AsyncStartEvent();
132
133 va_list vararg;
134 va_start(vararg, fmt);
135 vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
136 va_end(vararg);
137
138 event->timestamp = timestamp();
139 event->id = id;
140 put(event);
141 }
142
endAsyncEvent(uint32_t id,const char * fmt,...)143 void Trace::endAsyncEvent(uint32_t id, const char* fmt, ...) {
144 if (stopped) {
145 return;
146 }
147 auto event = new AsyncEndEvent();
148
149 va_list vararg;
150 va_start(vararg, fmt);
151 vsnprintf(event->name, Trace::MaxEventNameLength, fmt, vararg);
152 va_end(vararg);
153
154 event->timestamp = timestamp();
155 event->id = id;
156 put(event);
157 }
158
timestamp()159 uint64_t Trace::timestamp() {
160 auto now = std::chrono::high_resolution_clock::now();
161 auto diff =
162 std::chrono::duration_cast<std::chrono::microseconds>(now - createdAt);
163 return static_cast<uint64_t>(diff.count());
164 }
165
put(Event * event)166 void Trace::put(Event* event) {
167 auto idx = eventQueueWriteIdx++ % eventQueues.size();
168 auto& queue = eventQueues[idx];
169 std::unique_lock<std::mutex> lock(queue.mutex);
170 auto notify = queue.data.size() == 0;
171 queue.data.push(std::unique_ptr<Event>(event));
172 lock.unlock();
173 if (notify) {
174 queue.condition.notify_one();
175 }
176 }
177
take()178 std::unique_ptr<Trace::Event> Trace::take() {
179 auto idx = eventQueueReadIdx++ % eventQueues.size();
180 auto& queue = eventQueues[idx];
181 std::unique_lock<std::mutex> lock(queue.mutex);
182 queue.condition.wait(lock, [&queue] { return queue.data.size() > 0; });
183 auto event = std::move(queue.data.front());
184 queue.data.pop();
185 return event;
186 }
187
188 #define QUOTE(x) "\"" << x << "\""
189 #define INDENT " "
190
Event()191 Trace::Event::Event()
192 : threadID(std::hash<std::thread::id>()(std::this_thread::get_id())) {
193 if (auto fiber = Scheduler::Fiber::current()) {
194 fiberID = fiber->id;
195 }
196 }
197
write(std::ostream & out) const198 void Trace::Event::write(std::ostream& out) const {
199 out << INDENT << QUOTE("name") << ": " << QUOTE(name) << "," << std::endl;
200 if (categories != nullptr) {
201 out << INDENT << QUOTE("cat") << ": "
202 << "\"";
203 auto first = true;
204 for (auto category = *categories; category != nullptr; category++) {
205 if (!first) {
206 out << ",";
207 }
208 out << category;
209 }
210 out << "\"," << std::endl;
211 }
212 if (fiberID != 0) {
213 out << INDENT << QUOTE("args") << ": "
214 << "{" << std::endl
215 << INDENT << INDENT << QUOTE("fiber") << ": " << fiberID << std::endl
216 << INDENT << "}," << std::endl;
217 }
218 if (threadID != 0) {
219 out << INDENT << QUOTE("tid") << ": " << threadFiberID(threadID, fiberID)
220 << "," << std::endl;
221 }
222 out << INDENT << QUOTE("ph") << ": " << QUOTE(static_cast<char>(type()))
223 << "," << std::endl
224 << INDENT << QUOTE("pid") << ": " << processID << "," << std::endl
225 << INDENT << QUOTE("ts") << ": " << timestamp << std::endl;
226 }
227
write(std::ostream & out) const228 void Trace::NameThreadEvent::write(std::ostream& out) const {
229 out << INDENT << QUOTE("name") << ": " << QUOTE("thread_name") << ","
230 << std::endl
231 << INDENT << QUOTE("ph") << ": " << QUOTE("M") << "," << std::endl
232 << INDENT << QUOTE("pid") << ": " << processID << "," << std::endl
233 << INDENT << QUOTE("tid") << ": " << threadFiberID(threadID, fiberID)
234 << "," << std::endl
235 << INDENT << QUOTE("args") << ": {" << QUOTE("name") << ": "
236 << QUOTE(name) << "}" << std::endl;
237 }
238
write(std::ostream & out) const239 void Trace::AsyncEvent::write(std::ostream& out) const {
240 out << INDENT << QUOTE("id") << ": " << QUOTE(id) << "," << std::endl
241 << INDENT << QUOTE("cat") << ": " << QUOTE("async") << "," << std::endl;
242 Event::write(out);
243 }
244
245 } // namespace marl
246
247 #endif // MARL_TRACE_ENABLED