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 | |
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 | |
46 | Trace* Trace::get() { |
47 | static Trace trace; |
48 | return &trace; |
49 | } |
50 | |
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 | |
83 | Trace::~Trace() { |
84 | put(new Shutdown()); |
85 | thread.join(); |
86 | } |
87 | |
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 | |
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 | |
117 | void Trace::endEvent() { |
118 | if (stopped) { |
119 | return; |
120 | } |
121 | auto event = new EndEvent(); |
122 | event->timestamp = timestamp(); |
123 | put(event); |
124 | } |
125 | |
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 | |
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 | |
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 | |
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 | |
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 | |
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 | |
197 | 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 | |
227 | 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 | |
238 | 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 |