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