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
32namespace {
33
34// Chrome traces can choke or error on very large trace files.
35// Limit the number of events created to this number.
36static constexpr int MaxEvents = 100000;
37
38uint64_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
44namespace marl {
45
46Trace* Trace::get() {
47 static Trace trace;
48 return &trace;
49}
50
51Trace::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
83Trace::~Trace() {
84 put(new Shutdown());
85 thread.join();
86}
87
88void 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
102void 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
117void Trace::endEvent() {
118 if (stopped) {
119 return;
120 }
121 auto event = new EndEvent();
122 event->timestamp = timestamp();
123 put(event);
124}
125
126void 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
142void 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
158uint64_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
165void 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
177std::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
190Trace::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
197void 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
227void 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
238void 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