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 <tuple>
24
25 #include "perfetto/ext/base/file_utils.h"
26 #include "perfetto/ext/base/hash.h"
27 #include "perfetto/ext/base/optional.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.pbzero.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 base::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 base::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(message_prefix.begin(),
195 message_prefix.begin() + written);
196 }
197
OnTrackEvent(const TrackEventStateTracker::Track & track,const TrackEventStateTracker::ParsedTrackEvent & event)198 void ConsoleInterceptor::Delegate::OnTrackEvent(
199 const TrackEventStateTracker::Track& track,
200 const TrackEventStateTracker::ParsedTrackEvent& event) {
201 // Start printing.
202 auto& tls = context_.GetThreadLocalState();
203 tls.buffer_pos = 0;
204
205 // Print timestamp and track identifier.
206 SetColor(context_, kDim);
207 Printf(context_, "[%7.3lf] %.*s",
208 static_cast<double>(event.timestamp_ns - tls.start_time_ns) / 1e9,
209 static_cast<int>(track.user_data.size()), track.user_data.data());
210
211 // Print category.
212 Printf(context_, "%-5.*s ",
213 std::min(5, static_cast<int>(event.category.size)),
214 event.category.data);
215
216 // Print stack depth.
217 for (size_t i = 0; i < event.stack_depth; i++) {
218 Printf(context_, "- ");
219 }
220
221 // Print slice name.
222 auto slice_color = HueToRGB(event.name_hash % kMaxHue);
223 auto highlight_color = Mix(slice_color, kWhiteColor, kLightness);
224 if (event.track_event.type() == protos::pbzero::TrackEvent::TYPE_SLICE_END) {
225 SetColor(context_, kDefault);
226 Printf(context_, "} ");
227 }
228 SetColor(context_, highlight_color);
229 Printf(context_, "%.*s", static_cast<int>(event.name.size), event.name.data);
230 SetColor(context_, kReset);
231 if (event.track_event.type() ==
232 protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN) {
233 SetColor(context_, kDefault);
234 Printf(context_, " {");
235 }
236
237 // Print annotations.
238 if (event.track_event.has_debug_annotations()) {
239 PrintDebugAnnotations(context_, event.track_event, slice_color,
240 highlight_color);
241 }
242
243 // TODO(skyostil): Print typed arguments.
244
245 // Print duration for longer events.
246 constexpr uint64_t kNsPerMillisecond = 1000000u;
247 if (event.duration_ns >= 10 * kNsPerMillisecond) {
248 SetColor(context_, kDim);
249 Printf(context_, " +%" PRIu64 "ms", event.duration_ns / kNsPerMillisecond);
250 }
251 SetColor(context_, kReset);
252 Printf(context_, "\n");
253 }
254
255 // static
Register()256 void ConsoleInterceptor::Register() {
257 perfetto::protos::gen::InterceptorDescriptor desc;
258 desc.set_name("console");
259 Interceptor<ConsoleInterceptor>::Register(desc);
260 }
261
262 // static
SetOutputFdForTesting(int fd)263 void ConsoleInterceptor::SetOutputFdForTesting(int fd) {
264 g_output_fd_for_testing = fd;
265 }
266
OnSetup(const SetupArgs & args)267 void ConsoleInterceptor::OnSetup(const SetupArgs& args) {
268 int fd = STDOUT_FILENO;
269 if (g_output_fd_for_testing)
270 fd = g_output_fd_for_testing;
271 #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN) && \
272 !PERFETTO_BUILDFLAG(PERFETTO_OS_WASM)
273 bool use_colors = isatty(fd);
274 #else
275 bool use_colors = false;
276 #endif
277 protos::pbzero::ConsoleConfig::Decoder config(
278 args.config.interceptor_config().console_config_raw());
279 if (config.has_enable_colors())
280 use_colors = config.enable_colors();
281 if (config.output() == protos::pbzero::ConsoleConfig::OUTPUT_STDOUT) {
282 fd = STDOUT_FILENO;
283 } else if (config.output() == protos::pbzero::ConsoleConfig::OUTPUT_STDERR) {
284 fd = STDERR_FILENO;
285 }
286 fd_ = fd;
287 use_colors_ = use_colors;
288 }
289
OnStart(const StartArgs &)290 void ConsoleInterceptor::OnStart(const StartArgs&) {
291 start_time_ns_ = internal::TrackEventInternal::GetTimeNs();
292 }
293
OnStop(const StopArgs &)294 void ConsoleInterceptor::OnStop(const StopArgs&) {}
295
296 // static
OnTracePacket(InterceptorContext context)297 void ConsoleInterceptor::OnTracePacket(InterceptorContext context) {
298 {
299 auto& tls = context.GetThreadLocalState();
300 Delegate delegate(context);
301 perfetto::protos::pbzero::TracePacket::Decoder packet(
302 context.packet_data.data, context.packet_data.size);
303 TrackEventStateTracker::ProcessTracePacket(delegate, tls.sequence_state,
304 packet);
305 } // (Potential) lock scope for session state.
306 Flush(context);
307 }
308
309 // static
Printf(InterceptorContext & context,const char * format,...)310 void ConsoleInterceptor::Printf(InterceptorContext& context,
311 const char* format,
312 ...) {
313 auto& tls = context.GetThreadLocalState();
314 ssize_t remaining = static_cast<ssize_t>(tls.message_buffer.size()) -
315 static_cast<ssize_t>(tls.buffer_pos);
316 int written = 0;
317 if (remaining > 0) {
318 va_list args;
319 va_start(args, format);
320 written = vsnprintf(&tls.message_buffer[tls.buffer_pos],
321 static_cast<size_t>(remaining), format, args);
322 PERFETTO_DCHECK(written >= 0);
323 va_end(args);
324 }
325
326 // In case of buffer overflow, flush to the fd and write the latest message to
327 // it directly instead.
328 if (remaining <= 0 || written > remaining) {
329 FILE* output = (tls.fd == STDOUT_FILENO) ? stdout : stderr;
330 if (g_output_fd_for_testing) {
331 output = fdopen(dup(g_output_fd_for_testing), "w");
332 }
333 Flush(context);
334 va_list args;
335 va_start(args, format);
336 vfprintf(output, format, args);
337 va_end(args);
338 if (g_output_fd_for_testing) {
339 fclose(output);
340 }
341 } else if (written > 0) {
342 tls.buffer_pos += static_cast<size_t>(written);
343 }
344 }
345
346 // static
Flush(InterceptorContext & context)347 void ConsoleInterceptor::Flush(InterceptorContext& context) {
348 auto& tls = context.GetThreadLocalState();
349 ssize_t res = base::WriteAll(tls.fd, &tls.message_buffer[0], tls.buffer_pos);
350 PERFETTO_DCHECK(res == static_cast<ssize_t>(tls.buffer_pos));
351 tls.buffer_pos = 0;
352 }
353
354 // static
SetColor(InterceptorContext & context,const ConsoleColor & color)355 void ConsoleInterceptor::SetColor(InterceptorContext& context,
356 const ConsoleColor& color) {
357 auto& tls = context.GetThreadLocalState();
358 if (!tls.use_colors)
359 return;
360 Printf(context, FMT_RGB_SET, color.r, color.g, color.b);
361 }
362
363 // static
SetColor(InterceptorContext & context,const char * color)364 void ConsoleInterceptor::SetColor(InterceptorContext& context,
365 const char* color) {
366 auto& tls = context.GetThreadLocalState();
367 if (!tls.use_colors)
368 return;
369 Printf(context, "%s", color);
370 }
371
372 // static
PrintDebugAnnotations(InterceptorContext & context,const protos::pbzero::TrackEvent_Decoder & track_event,const ConsoleColor & slice_color,const ConsoleColor & highlight_color)373 void ConsoleInterceptor::PrintDebugAnnotations(
374 InterceptorContext& context,
375 const protos::pbzero::TrackEvent_Decoder& track_event,
376 const ConsoleColor& slice_color,
377 const ConsoleColor& highlight_color) {
378 SetColor(context, slice_color);
379 Printf(context, "(");
380
381 bool is_first = true;
382 for (auto it = track_event.debug_annotations(); it; it++) {
383 perfetto::protos::pbzero::DebugAnnotation::Decoder annotation(*it);
384 SetColor(context, slice_color);
385 if (!is_first)
386 Printf(context, ", ");
387
388 PrintDebugAnnotationName(context, annotation);
389 Printf(context, ":");
390
391 SetColor(context, highlight_color);
392 PrintDebugAnnotationValue(context, annotation);
393
394 is_first = false;
395 }
396 SetColor(context, slice_color);
397 Printf(context, ")");
398 }
399
400 // static
PrintDebugAnnotationName(InterceptorContext & context,const perfetto::protos::pbzero::DebugAnnotation::Decoder & annotation)401 void ConsoleInterceptor::PrintDebugAnnotationName(
402 InterceptorContext& context,
403 const perfetto::protos::pbzero::DebugAnnotation::Decoder& annotation) {
404 auto& tls = context.GetThreadLocalState();
405 protozero::ConstChars name{};
406 if (annotation.name_iid()) {
407 name.data =
408 tls.sequence_state.debug_annotation_names[annotation.name_iid()].data();
409 name.size =
410 tls.sequence_state.debug_annotation_names[annotation.name_iid()].size();
411 } else if (annotation.has_name()) {
412 name.data = annotation.name().data;
413 name.size = annotation.name().size;
414 }
415 Printf(context, "%.*s", static_cast<int>(name.size), name.data);
416 }
417
418 // static
PrintDebugAnnotationValue(InterceptorContext & context,const perfetto::protos::pbzero::DebugAnnotation::Decoder & annotation)419 void ConsoleInterceptor::PrintDebugAnnotationValue(
420 InterceptorContext& context,
421 const perfetto::protos::pbzero::DebugAnnotation::Decoder& annotation) {
422 if (annotation.has_bool_value()) {
423 Printf(context, "%s", annotation.bool_value() ? "true" : "false");
424 } else if (annotation.has_uint_value()) {
425 Printf(context, "%" PRIu64, annotation.uint_value());
426 } else if (annotation.has_int_value()) {
427 Printf(context, "%" PRId64, annotation.int_value());
428 } else if (annotation.has_double_value()) {
429 Printf(context, "%f", annotation.double_value());
430 } else if (annotation.has_string_value()) {
431 Printf(context, "%.*s", static_cast<int>(annotation.string_value().size),
432 annotation.string_value().data);
433 } else if (annotation.has_pointer_value()) {
434 Printf(context, "%p", reinterpret_cast<void*>(annotation.pointer_value()));
435 } else if (annotation.has_legacy_json_value()) {
436 Printf(context, "%.*s",
437 static_cast<int>(annotation.legacy_json_value().size),
438 annotation.legacy_json_value().data);
439 } else if (annotation.has_dict_entries()) {
440 Printf(context, "{");
441 bool is_first = true;
442 for (auto it = annotation.dict_entries(); it; ++it) {
443 if (!is_first)
444 Printf(context, ", ");
445 perfetto::protos::pbzero::DebugAnnotation::Decoder key_value(*it);
446 PrintDebugAnnotationName(context, key_value);
447 Printf(context, ":");
448 PrintDebugAnnotationValue(context, key_value);
449 is_first = false;
450 }
451 Printf(context, "}");
452 } else if (annotation.has_array_values()) {
453 Printf(context, "[");
454 bool is_first = true;
455 for (auto it = annotation.array_values(); it; ++it) {
456 if (!is_first)
457 Printf(context, ", ");
458 perfetto::protos::pbzero::DebugAnnotation::Decoder key_value(*it);
459 PrintDebugAnnotationValue(context, key_value);
460 is_first = false;
461 }
462 Printf(context, "]");
463 } else {
464 Printf(context, "{}");
465 }
466 }
467
468 } // namespace perfetto
469