/* * Copyright (C) 2020 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include "perfetto/tracing/console_interceptor.h" #include "perfetto/ext/base/file_utils.h" #include "perfetto/ext/base/hash.h" #include "perfetto/ext/base/optional.h" #include "perfetto/ext/base/scoped_file.h" #include "perfetto/ext/base/utils.h" #include "perfetto/tracing/internal/track_event_internal.h" #include "protos/perfetto/common/interceptor_descriptor.gen.h" #include "protos/perfetto/config/data_source_config.gen.h" #include "protos/perfetto/config/interceptor_config.gen.h" #include "protos/perfetto/config/interceptors/console_config.pbzero.h" #include "protos/perfetto/trace/interned_data/interned_data.pbzero.h" #include "protos/perfetto/trace/trace_packet.pbzero.h" #include "protos/perfetto/trace/trace_packet_defaults.pbzero.h" #include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h" #include "protos/perfetto/trace/track_event/thread_descriptor.pbzero.h" #include "protos/perfetto/trace/track_event/track_descriptor.pbzero.h" #include "protos/perfetto/trace/track_event/track_event.pbzero.h" #include #include #include namespace perfetto { // sRGB color. struct ConsoleColor { uint8_t r; uint8_t g; uint8_t b; }; namespace { int g_output_fd_for_testing; // Google Turbo colormap. constexpr std::array kTurboColors = {{ ConsoleColor{0x30, 0x12, 0x3b}, ConsoleColor{0x40, 0x40, 0xa1}, ConsoleColor{0x46, 0x6b, 0xe3}, ConsoleColor{0x41, 0x93, 0xfe}, ConsoleColor{0x28, 0xbb, 0xeb}, ConsoleColor{0x17, 0xdc, 0xc2}, ConsoleColor{0x32, 0xf1, 0x97}, ConsoleColor{0x6d, 0xfd, 0x62}, ConsoleColor{0xa4, 0xfc, 0x3b}, ConsoleColor{0xcd, 0xeb, 0x34}, ConsoleColor{0xed, 0xcf, 0x39}, ConsoleColor{0xfd, 0xab, 0x33}, ConsoleColor{0xfa, 0x7d, 0x20}, ConsoleColor{0xea, 0x50, 0x0d}, ConsoleColor{0xd0, 0x2f, 0x04}, ConsoleColor{0xa9, 0x15, 0x01}, }}; constexpr size_t kHueBits = 4; constexpr uint32_t kMaxHue = kTurboColors.size() << kHueBits; constexpr uint8_t kLightness = 128u; constexpr ConsoleColor kWhiteColor{0xff, 0xff, 0xff}; const char kDim[] = "\x1b[90m"; const char kDefault[] = "\x1b[39m"; const char kReset[] = "\x1b[0m"; #define FMT_RGB_SET "\x1b[38;2;%d;%d;%dm" #define FMT_RGB_SET_BG "\x1b[48;2;%d;%d;%dm" ConsoleColor Mix(ConsoleColor a, ConsoleColor b, uint8_t ratio) { return { static_cast(a.r + (((b.r - a.r) * ratio) >> 8)), static_cast(a.g + (((b.g - a.g) * ratio) >> 8)), static_cast(a.b + (((b.b - a.b) * ratio) >> 8)), }; } ConsoleColor HueToRGB(uint32_t hue) { PERFETTO_DCHECK(hue < kMaxHue); uint32_t c1 = hue >> kHueBits; uint32_t c2 = std::min(static_cast(kTurboColors.size() - 1), c1 + 1u); uint32_t ratio = hue & ((1 << kHueBits) - 1); return Mix(kTurboColors[c1], kTurboColors[c2], static_cast(ratio | (ratio << kHueBits))); } uint32_t CounterToHue(uint32_t counter) { // We split the hue space into 8 segments, reversing the order of bits so // successive counter values will be far from each other. uint32_t reversed = ((counter & 0x7) >> 2) | ((counter & 0x3)) | ((counter & 0x1) << 2); return reversed * kMaxHue / 8; } } // namespace class ConsoleInterceptor::Delegate : public TrackEventStateTracker::Delegate { public: explicit Delegate(InterceptorContext&); ~Delegate() override; TrackEventStateTracker::SessionState* GetSessionState() override; void OnTrackUpdated(TrackEventStateTracker::Track&) override; void OnTrackEvent(const TrackEventStateTracker::Track&, const TrackEventStateTracker::ParsedTrackEvent&) override; private: using SelfHandle = LockedHandle; InterceptorContext& context_; base::Optional locked_self_; }; ConsoleInterceptor::~ConsoleInterceptor() = default; ConsoleInterceptor::ThreadLocalState::ThreadLocalState( ThreadLocalStateArgs& args) { if (auto self = args.GetInterceptorLocked()) { start_time_ns = self->start_time_ns_; use_colors = self->use_colors_; fd = self->fd_; } } ConsoleInterceptor::ThreadLocalState::~ThreadLocalState() = default; ConsoleInterceptor::Delegate::Delegate(InterceptorContext& context) : context_(context) {} ConsoleInterceptor::Delegate::~Delegate() = default; TrackEventStateTracker::SessionState* ConsoleInterceptor::Delegate::GetSessionState() { // When the session state is retrieved for the first time, it is cached (and // kept locked) until we return from OnTracePacket. This avoids having to lock // and unlock the instance multiple times per invocation. if (locked_self_.has_value()) return &locked_self_.value()->session_state_; locked_self_ = base::make_optional(context_.GetInterceptorLocked()); return &locked_self_.value()->session_state_; } void ConsoleInterceptor::Delegate::OnTrackUpdated( TrackEventStateTracker::Track& track) { auto track_color = HueToRGB(CounterToHue(track.index)); std::array title; if (!track.name.empty()) { snprintf(title.data(), title.size(), "%s", track.name.c_str()); } else if (track.pid && track.tid) { snprintf(title.data(), title.size(), "%u:%u", static_cast(track.pid), static_cast(track.tid)); } else if (track.pid) { snprintf(title.data(), title.size(), "%" PRId64, track.pid); } else { snprintf(title.data(), title.size(), "%" PRIu64, track.uuid); } int title_width = static_cast(title.size()); auto& tls = context_.GetThreadLocalState(); std::array message_prefix{}; ssize_t written = 0; if (tls.use_colors) { written = snprintf(message_prefix.data(), message_prefix.size(), FMT_RGB_SET_BG " %s%s %-*.*s", track_color.r, track_color.g, track_color.b, kReset, kDim, title_width, title_width, title.data()); } else { written = snprintf(message_prefix.data(), message_prefix.size(), "%-*.*s", title_width + 2, title_width, title.data()); } if (written < 0) written = message_prefix.size(); track.user_data.assign(message_prefix.begin(), message_prefix.begin() + written); } void ConsoleInterceptor::Delegate::OnTrackEvent( const TrackEventStateTracker::Track& track, const TrackEventStateTracker::ParsedTrackEvent& event) { // Start printing. auto& tls = context_.GetThreadLocalState(); tls.buffer_pos = 0; // Print timestamp and track identifier. SetColor(context_, kDim); Printf(context_, "[%7.3lf] %.*s", static_cast(event.timestamp_ns - tls.start_time_ns) / 1e9, static_cast(track.user_data.size()), track.user_data.data()); // Print category. Printf(context_, "%-5.*s ", std::min(5, static_cast(event.category.size)), event.category.data); // Print stack depth. for (size_t i = 0; i < event.stack_depth; i++) { Printf(context_, "- "); } // Print slice name. auto slice_color = HueToRGB(event.name_hash % kMaxHue); auto highlight_color = Mix(slice_color, kWhiteColor, kLightness); if (event.track_event.type() == protos::pbzero::TrackEvent::TYPE_SLICE_END) { SetColor(context_, kDefault); Printf(context_, "} "); } SetColor(context_, highlight_color); Printf(context_, "%.*s", static_cast(event.name.size), event.name.data); SetColor(context_, kReset); if (event.track_event.type() == protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN) { SetColor(context_, kDefault); Printf(context_, " {"); } // Print annotations. if (event.track_event.has_debug_annotations()) { PrintDebugAnnotations(context_, event.track_event, slice_color, highlight_color); } // TODO(skyostil): Print typed arguments. // Print duration for longer events. constexpr uint64_t kNsPerMillisecond = 1000000u; if (event.duration_ns >= 10 * kNsPerMillisecond) { SetColor(context_, kDim); Printf(context_, " +%" PRIu64 "ms", event.duration_ns / kNsPerMillisecond); } SetColor(context_, kReset); Printf(context_, "\n"); } // static void ConsoleInterceptor::Register() { perfetto::protos::gen::InterceptorDescriptor desc; desc.set_name("console"); Interceptor::Register(desc); } // static void ConsoleInterceptor::SetOutputFdForTesting(int fd) { g_output_fd_for_testing = fd; } void ConsoleInterceptor::OnSetup(const SetupArgs& args) { int fd = STDOUT_FILENO; if (g_output_fd_for_testing) fd = g_output_fd_for_testing; #if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN) && \ !PERFETTO_BUILDFLAG(PERFETTO_OS_WASM) bool use_colors = isatty(fd); #else bool use_colors = false; #endif protos::pbzero::ConsoleConfig::Decoder config( args.config.interceptor_config().console_config_raw()); if (config.has_enable_colors()) use_colors = config.enable_colors(); if (config.output() == protos::pbzero::ConsoleConfig::OUTPUT_STDOUT) { fd = STDOUT_FILENO; } else if (config.output() == protos::pbzero::ConsoleConfig::OUTPUT_STDERR) { fd = STDERR_FILENO; } fd_ = fd; use_colors_ = use_colors; } void ConsoleInterceptor::OnStart(const StartArgs&) { start_time_ns_ = internal::TrackEventInternal::GetTimeNs(); } void ConsoleInterceptor::OnStop(const StopArgs&) {} // static void ConsoleInterceptor::OnTracePacket(InterceptorContext context) { { auto& tls = context.GetThreadLocalState(); Delegate delegate(context); perfetto::protos::pbzero::TracePacket::Decoder packet( context.packet_data.data, context.packet_data.size); TrackEventStateTracker::ProcessTracePacket(delegate, tls.sequence_state, packet); } // (Potential) lock scope for session state. Flush(context); } // static void ConsoleInterceptor::Printf(InterceptorContext& context, const char* format, ...) { auto& tls = context.GetThreadLocalState(); ssize_t remaining = static_cast(tls.message_buffer.size()) - static_cast(tls.buffer_pos); int written = 0; if (remaining > 0) { va_list args; va_start(args, format); written = vsnprintf(&tls.message_buffer[tls.buffer_pos], static_cast(remaining), format, args); PERFETTO_DCHECK(written >= 0); va_end(args); } // In case of buffer overflow, flush to the fd and write the latest message to // it directly instead. if (remaining <= 0 || written > remaining) { FILE* output = (tls.fd == STDOUT_FILENO) ? stdout : stderr; if (g_output_fd_for_testing) { output = fdopen(dup(g_output_fd_for_testing), "w"); } Flush(context); va_list args; va_start(args, format); vfprintf(output, format, args); va_end(args); if (g_output_fd_for_testing) { fclose(output); } } else if (written > 0) { tls.buffer_pos += static_cast(written); } } // static void ConsoleInterceptor::Flush(InterceptorContext& context) { auto& tls = context.GetThreadLocalState(); ssize_t res = base::WriteAll(tls.fd, &tls.message_buffer[0], tls.buffer_pos); PERFETTO_DCHECK(res == static_cast(tls.buffer_pos)); tls.buffer_pos = 0; } // static void ConsoleInterceptor::SetColor(InterceptorContext& context, const ConsoleColor& color) { auto& tls = context.GetThreadLocalState(); if (!tls.use_colors) return; Printf(context, FMT_RGB_SET, color.r, color.g, color.b); } // static void ConsoleInterceptor::SetColor(InterceptorContext& context, const char* color) { auto& tls = context.GetThreadLocalState(); if (!tls.use_colors) return; Printf(context, "%s", color); } // static void ConsoleInterceptor::PrintDebugAnnotations( InterceptorContext& context, const protos::pbzero::TrackEvent_Decoder& track_event, const ConsoleColor& slice_color, const ConsoleColor& highlight_color) { SetColor(context, slice_color); Printf(context, "("); bool is_first = true; for (auto it = track_event.debug_annotations(); it; it++) { perfetto::protos::pbzero::DebugAnnotation::Decoder annotation(*it); SetColor(context, slice_color); if (!is_first) Printf(context, ", "); PrintDebugAnnotationName(context, annotation); Printf(context, ":"); SetColor(context, highlight_color); PrintDebugAnnotationValue(context, annotation); is_first = false; } SetColor(context, slice_color); Printf(context, ")"); } // static void ConsoleInterceptor::PrintDebugAnnotationName( InterceptorContext& context, const perfetto::protos::pbzero::DebugAnnotation::Decoder& annotation) { auto& tls = context.GetThreadLocalState(); protozero::ConstChars name{}; if (annotation.name_iid()) { name.data = tls.sequence_state.debug_annotation_names[annotation.name_iid()].data(); name.size = tls.sequence_state.debug_annotation_names[annotation.name_iid()].size(); } else if (annotation.has_name()) { name.data = annotation.name().data; name.size = annotation.name().size; } Printf(context, "%.*s", static_cast(name.size), name.data); } // static void ConsoleInterceptor::PrintDebugAnnotationValue( InterceptorContext& context, const perfetto::protos::pbzero::DebugAnnotation::Decoder& annotation) { if (annotation.has_bool_value()) { Printf(context, "%s", annotation.bool_value() ? "true" : "false"); } else if (annotation.has_uint_value()) { Printf(context, "%" PRIu64, annotation.uint_value()); } else if (annotation.has_int_value()) { Printf(context, "%" PRId64, annotation.int_value()); } else if (annotation.has_double_value()) { Printf(context, "%f", annotation.double_value()); } else if (annotation.has_string_value()) { Printf(context, "%.*s", static_cast(annotation.string_value().size), annotation.string_value().data); } else if (annotation.has_pointer_value()) { Printf(context, "%p", reinterpret_cast(annotation.pointer_value())); } else if (annotation.has_legacy_json_value()) { Printf(context, "%.*s", static_cast(annotation.legacy_json_value().size), annotation.legacy_json_value().data); } else if (annotation.has_dict_entries()) { Printf(context, "{"); bool is_first = true; for (auto it = annotation.dict_entries(); it; ++it) { if (!is_first) Printf(context, ", "); perfetto::protos::pbzero::DebugAnnotation::Decoder key_value(*it); PrintDebugAnnotationName(context, key_value); Printf(context, ":"); PrintDebugAnnotationValue(context, key_value); is_first = false; } Printf(context, "}"); } else if (annotation.has_array_values()) { Printf(context, "["); bool is_first = true; for (auto it = annotation.array_values(); it; ++it) { if (!is_first) Printf(context, ", "); perfetto::protos::pbzero::DebugAnnotation::Decoder key_value(*it); PrintDebugAnnotationValue(context, key_value); is_first = false; } Printf(context, "]"); } else { Printf(context, "{}"); } } } // namespace perfetto