1 /*
2 * Copyright (C) 2020 The Android Open Source Project
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 "perfetto/tracing/console_interceptor.h"
18
19 #include "perfetto/ext/base/file_utils.h"
20 #include "perfetto/ext/base/hash.h"
21 #include "perfetto/ext/base/optional.h"
22 #include "perfetto/ext/base/scoped_file.h"
23 #include "perfetto/ext/base/utils.h"
24 #include "perfetto/tracing/internal/track_event_internal.h"
25
26 #include "protos/perfetto/common/interceptor_descriptor.gen.h"
27 #include "protos/perfetto/config/data_source_config.gen.h"
28 #include "protos/perfetto/config/interceptor_config.gen.h"
29 #include "protos/perfetto/config/interceptors/console_config.pbzero.h"
30 #include "protos/perfetto/trace/interned_data/interned_data.pbzero.h"
31 #include "protos/perfetto/trace/trace_packet.pbzero.h"
32 #include "protos/perfetto/trace/trace_packet_defaults.pbzero.h"
33 #include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h"
34 #include "protos/perfetto/trace/track_event/thread_descriptor.pbzero.h"
35 #include "protos/perfetto/trace/track_event/track_descriptor.pbzero.h"
36 #include "protos/perfetto/trace/track_event/track_event.pbzero.h"
37
38 #include <algorithm>
39 #include <cmath>
40 #include <tuple>
41
42 namespace perfetto {
43
44 // sRGB color.
45 struct ConsoleColor {
46 uint8_t r;
47 uint8_t g;
48 uint8_t b;
49 };
50
51 namespace {
52
53 int g_output_fd_for_testing;
54
55 // Google Turbo colormap.
56 constexpr std::array<ConsoleColor, 16> kTurboColors = {{
57 ConsoleColor{0x30, 0x12, 0x3b},
58 ConsoleColor{0x40, 0x40, 0xa1},
59 ConsoleColor{0x46, 0x6b, 0xe3},
60 ConsoleColor{0x41, 0x93, 0xfe},
61 ConsoleColor{0x28, 0xbb, 0xeb},
62 ConsoleColor{0x17, 0xdc, 0xc2},
63 ConsoleColor{0x32, 0xf1, 0x97},
64 ConsoleColor{0x6d, 0xfd, 0x62},
65 ConsoleColor{0xa4, 0xfc, 0x3b},
66 ConsoleColor{0xcd, 0xeb, 0x34},
67 ConsoleColor{0xed, 0xcf, 0x39},
68 ConsoleColor{0xfd, 0xab, 0x33},
69 ConsoleColor{0xfa, 0x7d, 0x20},
70 ConsoleColor{0xea, 0x50, 0x0d},
71 ConsoleColor{0xd0, 0x2f, 0x04},
72 ConsoleColor{0xa9, 0x15, 0x01},
73 }};
74
75 constexpr size_t kHueBits = 4;
76 constexpr uint32_t kMaxHue = kTurboColors.size() << kHueBits;
77 constexpr uint8_t kLightness = 128u;
78 constexpr ConsoleColor kWhiteColor{0xff, 0xff, 0xff};
79
80 const char kDim[] = "\x1b[90m";
81 const char kDefault[] = "\x1b[39m";
82 const char kReset[] = "\x1b[0m";
83
84 #define FMT_RGB_SET "\x1b[38;2;%d;%d;%dm"
85 #define FMT_RGB_SET_BG "\x1b[48;2;%d;%d;%dm"
86
Mix(ConsoleColor a,ConsoleColor b,uint8_t ratio)87 ConsoleColor Mix(ConsoleColor a, ConsoleColor b, uint8_t ratio) {
88 return {
89 static_cast<uint8_t>(a.r + (((b.r - a.r) * ratio) >> 8)),
90 static_cast<uint8_t>(a.g + (((b.g - a.g) * ratio) >> 8)),
91 static_cast<uint8_t>(a.b + (((b.b - a.b) * ratio) >> 8)),
92 };
93 }
94
HueToRGB(uint32_t hue)95 ConsoleColor HueToRGB(uint32_t hue) {
96 PERFETTO_DCHECK(hue < kMaxHue);
97 uint32_t c1 = hue >> kHueBits;
98 uint32_t c2 =
99 std::min(static_cast<uint32_t>(kTurboColors.size() - 1), c1 + 1u);
100 uint32_t ratio = hue & ((1 << kHueBits) - 1);
101 return Mix(kTurboColors[c1], kTurboColors[c2],
102 static_cast<uint8_t>(ratio | (ratio << kHueBits)));
103 }
104
CounterToHue(uint32_t counter)105 uint32_t CounterToHue(uint32_t counter) {
106 // We split the hue space into 8 segments, reversing the order of bits so
107 // successive counter values will be far from each other.
108 uint32_t reversed =
109 ((counter & 0x7) >> 2) | ((counter & 0x3)) | ((counter & 0x1) << 2);
110 return reversed * kMaxHue / 8;
111 }
112
113 } // namespace
114
115 class ConsoleInterceptor::Delegate : public TrackEventStateTracker::Delegate {
116 public:
117 explicit Delegate(InterceptorContext&);
118 ~Delegate() override;
119
120 TrackEventStateTracker::SessionState* GetSessionState() override;
121 void OnTrackUpdated(TrackEventStateTracker::Track&) override;
122 void OnTrackEvent(const TrackEventStateTracker::Track&,
123 const TrackEventStateTracker::ParsedTrackEvent&) override;
124
125 private:
126 using SelfHandle = LockedHandle<ConsoleInterceptor>;
127
128 InterceptorContext& context_;
129 base::Optional<SelfHandle> locked_self_;
130 };
131
132 ConsoleInterceptor::~ConsoleInterceptor() = default;
133
ThreadLocalState(ThreadLocalStateArgs & args)134 ConsoleInterceptor::ThreadLocalState::ThreadLocalState(
135 ThreadLocalStateArgs& args) {
136 if (auto self = args.GetInterceptorLocked()) {
137 start_time_ns = self->start_time_ns_;
138 use_colors = self->use_colors_;
139 fd = self->fd_;
140 }
141 }
142
143 ConsoleInterceptor::ThreadLocalState::~ThreadLocalState() = default;
144
Delegate(InterceptorContext & context)145 ConsoleInterceptor::Delegate::Delegate(InterceptorContext& context)
146 : context_(context) {}
147 ConsoleInterceptor::Delegate::~Delegate() = default;
148
149 TrackEventStateTracker::SessionState*
GetSessionState()150 ConsoleInterceptor::Delegate::GetSessionState() {
151 // When the session state is retrieved for the first time, it is cached (and
152 // kept locked) until we return from OnTracePacket. This avoids having to lock
153 // and unlock the instance multiple times per invocation.
154 if (locked_self_.has_value())
155 return &locked_self_.value()->session_state_;
156 locked_self_ =
157 base::make_optional<SelfHandle>(context_.GetInterceptorLocked());
158 return &locked_self_.value()->session_state_;
159 }
160
OnTrackUpdated(TrackEventStateTracker::Track & track)161 void ConsoleInterceptor::Delegate::OnTrackUpdated(
162 TrackEventStateTracker::Track& track) {
163 auto track_color = HueToRGB(CounterToHue(track.index));
164 std::array<char, 16> title;
165 if (!track.name.empty()) {
166 snprintf(title.data(), title.size(), "%s", track.name.c_str());
167 } else if (track.pid && track.tid) {
168 snprintf(title.data(), title.size(), "%u:%u",
169 static_cast<uint32_t>(track.pid),
170 static_cast<uint32_t>(track.tid));
171 } else if (track.pid) {
172 snprintf(title.data(), title.size(), "%" PRId64, track.pid);
173 } else {
174 snprintf(title.data(), title.size(), "%" PRIu64, track.uuid);
175 }
176 int title_width = static_cast<int>(title.size());
177
178 auto& tls = context_.GetThreadLocalState();
179 std::array<char, 128> message_prefix{};
180 ssize_t written = 0;
181 if (tls.use_colors) {
182 written = snprintf(message_prefix.data(), message_prefix.size(),
183 FMT_RGB_SET_BG " %s%s %-*.*s", track_color.r,
184 track_color.g, track_color.b, kReset, kDim, title_width,
185 title_width, title.data());
186 } else {
187 written = snprintf(message_prefix.data(), message_prefix.size(), "%-*.*s",
188 title_width + 2, title_width, title.data());
189 }
190 if (written < 0)
191 written = message_prefix.size();
192 track.user_data.assign(message_prefix.begin(),
193 message_prefix.begin() + written);
194 }
195
OnTrackEvent(const TrackEventStateTracker::Track & track,const TrackEventStateTracker::ParsedTrackEvent & event)196 void ConsoleInterceptor::Delegate::OnTrackEvent(
197 const TrackEventStateTracker::Track& track,
198 const TrackEventStateTracker::ParsedTrackEvent& event) {
199 // Start printing.
200 auto& tls = context_.GetThreadLocalState();
201 tls.buffer_pos = 0;
202
203 // Print timestamp and track identifier.
204 SetColor(context_, kDim);
205 Printf(context_, "[%7.3lf] %.*s",
206 static_cast<double>(event.timestamp_ns - tls.start_time_ns) / 1e9,
207 static_cast<int>(track.user_data.size()), track.user_data.data());
208
209 // Print category.
210 Printf(context_, "%-5.*s ",
211 std::min(5, static_cast<int>(event.category.size)),
212 event.category.data);
213
214 // Print stack depth.
215 for (size_t i = 0; i < event.stack_depth; i++) {
216 Printf(context_, "- ");
217 }
218
219 // Print slice name.
220 auto slice_color = HueToRGB(event.name_hash % kMaxHue);
221 auto highlight_color = Mix(slice_color, kWhiteColor, kLightness);
222 if (event.track_event.type() == protos::pbzero::TrackEvent::TYPE_SLICE_END) {
223 SetColor(context_, kDefault);
224 Printf(context_, "} ");
225 }
226 SetColor(context_, highlight_color);
227 Printf(context_, "%.*s", static_cast<int>(event.name.size), event.name.data);
228 SetColor(context_, kReset);
229 if (event.track_event.type() ==
230 protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN) {
231 SetColor(context_, kDefault);
232 Printf(context_, " {");
233 }
234
235 // Print annotations.
236 if (event.track_event.has_debug_annotations()) {
237 PrintDebugAnnotations(context_, event.track_event, slice_color,
238 highlight_color);
239 }
240
241 // TODO(skyostil): Print typed arguments.
242
243 // Print duration for longer events.
244 constexpr uint64_t kNsPerMillisecond = 1000000u;
245 if (event.duration_ns >= 10 * kNsPerMillisecond) {
246 SetColor(context_, kDim);
247 Printf(context_, " +%" PRIu64 "ms", event.duration_ns / kNsPerMillisecond);
248 }
249 SetColor(context_, kReset);
250 Printf(context_, "\n");
251 }
252
253 // static
Register()254 void ConsoleInterceptor::Register() {
255 perfetto::protos::gen::InterceptorDescriptor desc;
256 desc.set_name("console");
257 Interceptor<ConsoleInterceptor>::Register(desc);
258 }
259
260 // static
SetOutputFdForTesting(int fd)261 void ConsoleInterceptor::SetOutputFdForTesting(int fd) {
262 g_output_fd_for_testing = fd;
263 }
264
OnSetup(const SetupArgs & args)265 void ConsoleInterceptor::OnSetup(const SetupArgs& args) {
266 int fd = STDOUT_FILENO;
267 if (g_output_fd_for_testing)
268 fd = g_output_fd_for_testing;
269 #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN) && \
270 !PERFETTO_BUILDFLAG(PERFETTO_OS_WASM)
271 bool use_colors = isatty(fd);
272 #else
273 bool use_colors = false;
274 #endif
275 protos::pbzero::ConsoleConfig::Decoder config(
276 args.config.interceptor_config().console_config_raw());
277 if (config.has_enable_colors())
278 use_colors = config.enable_colors();
279 if (config.output() == protos::pbzero::ConsoleConfig::OUTPUT_STDOUT) {
280 fd = STDOUT_FILENO;
281 } else if (config.output() == protos::pbzero::ConsoleConfig::OUTPUT_STDERR) {
282 fd = STDERR_FILENO;
283 }
284 fd_ = fd;
285 use_colors_ = use_colors;
286 }
287
OnStart(const StartArgs &)288 void ConsoleInterceptor::OnStart(const StartArgs&) {
289 start_time_ns_ = internal::TrackEventInternal::GetTimeNs();
290 }
291
OnStop(const StopArgs &)292 void ConsoleInterceptor::OnStop(const StopArgs&) {}
293
294 // static
OnTracePacket(InterceptorContext context)295 void ConsoleInterceptor::OnTracePacket(InterceptorContext context) {
296 {
297 auto& tls = context.GetThreadLocalState();
298 Delegate delegate(context);
299 perfetto::protos::pbzero::TracePacket::Decoder packet(
300 context.packet_data.data, context.packet_data.size);
301 TrackEventStateTracker::ProcessTracePacket(delegate, tls.sequence_state,
302 packet);
303 } // (Potential) lock scope for session state.
304 Flush(context);
305 }
306
307 // static
Printf(InterceptorContext & context,const char * format,...)308 void ConsoleInterceptor::Printf(InterceptorContext& context,
309 const char* format,
310 ...) {
311 auto& tls = context.GetThreadLocalState();
312 ssize_t remaining = static_cast<ssize_t>(tls.message_buffer.size()) -
313 static_cast<ssize_t>(tls.buffer_pos);
314 int written = 0;
315 if (remaining > 0) {
316 va_list args;
317 va_start(args, format);
318 written = vsnprintf(&tls.message_buffer[tls.buffer_pos],
319 static_cast<size_t>(remaining), format, args);
320 PERFETTO_DCHECK(written >= 0);
321 va_end(args);
322 }
323
324 // In case of buffer overflow, flush to the fd and write the latest message to
325 // it directly instead.
326 if (remaining <= 0 || written > remaining) {
327 FILE* output = (tls.fd == STDOUT_FILENO) ? stdout : stderr;
328 if (g_output_fd_for_testing) {
329 output = fdopen(dup(g_output_fd_for_testing), "w");
330 }
331 Flush(context);
332 va_list args;
333 va_start(args, format);
334 vfprintf(output, format, args);
335 va_end(args);
336 if (g_output_fd_for_testing) {
337 fclose(output);
338 }
339 } else if (written > 0) {
340 tls.buffer_pos += static_cast<size_t>(written);
341 }
342 }
343
344 // static
Flush(InterceptorContext & context)345 void ConsoleInterceptor::Flush(InterceptorContext& context) {
346 auto& tls = context.GetThreadLocalState();
347 ssize_t res = base::WriteAll(tls.fd, &tls.message_buffer[0], tls.buffer_pos);
348 PERFETTO_DCHECK(res == static_cast<ssize_t>(tls.buffer_pos));
349 tls.buffer_pos = 0;
350 }
351
352 // static
SetColor(InterceptorContext & context,const ConsoleColor & color)353 void ConsoleInterceptor::SetColor(InterceptorContext& context,
354 const ConsoleColor& color) {
355 auto& tls = context.GetThreadLocalState();
356 if (!tls.use_colors)
357 return;
358 Printf(context, FMT_RGB_SET, color.r, color.g, color.b);
359 }
360
361 // static
SetColor(InterceptorContext & context,const char * color)362 void ConsoleInterceptor::SetColor(InterceptorContext& context,
363 const char* color) {
364 auto& tls = context.GetThreadLocalState();
365 if (!tls.use_colors)
366 return;
367 Printf(context, "%s", color);
368 }
369
370 // static
PrintDebugAnnotations(InterceptorContext & context,const protos::pbzero::TrackEvent_Decoder & track_event,const ConsoleColor & slice_color,const ConsoleColor & highlight_color)371 void ConsoleInterceptor::PrintDebugAnnotations(
372 InterceptorContext& context,
373 const protos::pbzero::TrackEvent_Decoder& track_event,
374 const ConsoleColor& slice_color,
375 const ConsoleColor& highlight_color) {
376 SetColor(context, slice_color);
377 Printf(context, "(");
378
379 bool is_first = true;
380 for (auto it = track_event.debug_annotations(); it; it++) {
381 perfetto::protos::pbzero::DebugAnnotation::Decoder annotation(*it);
382 SetColor(context, slice_color);
383 if (!is_first)
384 Printf(context, ", ");
385
386 PrintDebugAnnotationName(context, annotation);
387 Printf(context, ":");
388
389 SetColor(context, highlight_color);
390 PrintDebugAnnotationValue(context, annotation);
391
392 is_first = false;
393 }
394 SetColor(context, slice_color);
395 Printf(context, ")");
396 }
397
398 // static
PrintDebugAnnotationName(InterceptorContext & context,const perfetto::protos::pbzero::DebugAnnotation::Decoder & annotation)399 void ConsoleInterceptor::PrintDebugAnnotationName(
400 InterceptorContext& context,
401 const perfetto::protos::pbzero::DebugAnnotation::Decoder& annotation) {
402 auto& tls = context.GetThreadLocalState();
403 protozero::ConstChars name{};
404 if (annotation.name_iid()) {
405 name.data =
406 tls.sequence_state.debug_annotation_names[annotation.name_iid()].data();
407 name.size =
408 tls.sequence_state.debug_annotation_names[annotation.name_iid()].size();
409 } else if (annotation.has_name()) {
410 name.data = annotation.name().data;
411 name.size = annotation.name().size;
412 }
413 Printf(context, "%.*s", static_cast<int>(name.size), name.data);
414 }
415
416 // static
PrintDebugAnnotationValue(InterceptorContext & context,const perfetto::protos::pbzero::DebugAnnotation::Decoder & annotation)417 void ConsoleInterceptor::PrintDebugAnnotationValue(
418 InterceptorContext& context,
419 const perfetto::protos::pbzero::DebugAnnotation::Decoder& annotation) {
420 if (annotation.has_bool_value()) {
421 Printf(context, "%s", annotation.bool_value() ? "true" : "false");
422 } else if (annotation.has_uint_value()) {
423 Printf(context, "%" PRIu64, annotation.uint_value());
424 } else if (annotation.has_int_value()) {
425 Printf(context, "%" PRId64, annotation.int_value());
426 } else if (annotation.has_double_value()) {
427 Printf(context, "%f", annotation.double_value());
428 } else if (annotation.has_string_value()) {
429 Printf(context, "%.*s", static_cast<int>(annotation.string_value().size),
430 annotation.string_value().data);
431 } else if (annotation.has_pointer_value()) {
432 Printf(context, "%p", reinterpret_cast<void*>(annotation.pointer_value()));
433 } else if (annotation.has_legacy_json_value()) {
434 Printf(context, "%.*s",
435 static_cast<int>(annotation.legacy_json_value().size),
436 annotation.legacy_json_value().data);
437 } else if (annotation.has_dict_entries()) {
438 Printf(context, "{");
439 bool is_first = true;
440 for (auto it = annotation.dict_entries(); it; ++it) {
441 if (!is_first)
442 Printf(context, ", ");
443 perfetto::protos::pbzero::DebugAnnotation::Decoder key_value(*it);
444 PrintDebugAnnotationName(context, key_value);
445 Printf(context, ":");
446 PrintDebugAnnotationValue(context, key_value);
447 is_first = false;
448 }
449 Printf(context, "}");
450 } else if (annotation.has_array_values()) {
451 Printf(context, "[");
452 bool is_first = true;
453 for (auto it = annotation.array_values(); it; ++it) {
454 if (!is_first)
455 Printf(context, ", ");
456 perfetto::protos::pbzero::DebugAnnotation::Decoder key_value(*it);
457 PrintDebugAnnotationValue(context, key_value);
458 is_first = false;
459 }
460 Printf(context, "]");
461 } else {
462 Printf(context, "{}");
463 }
464 }
465
466 } // namespace perfetto
467