blob: 4c0af32e5641b02718bcd27ac51b18683bfdca73 [file] [log] [blame]
// Copyright 2014 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#include "net/log/trace_net_log_observer.h"
#include <stdio.h>
#include <memory>
#include <string>
#include <utility>
#include "base/check.h"
#include "base/json/json_writer.h"
#include "base/strings/stringprintf.h"
#include "base/trace_event/trace_event.h"
#include "base/values.h"
#include "net/log/net_log_entry.h"
#include "net/log/net_log_event_type.h"
#include "third_party/perfetto/include/perfetto/tracing/track_event.h"
namespace net {
namespace {
// TraceLog category for NetLog events.
constexpr const char kNetLogTracingCategory[] = "netlog";
constexpr const char kSensitiveNetLogTracingCategory[] =
TRACE_DISABLED_BY_DEFAULT("netlog.sensitive");
class TracedValue : public base::trace_event::ConvertableToTraceFormat {
public:
explicit TracedValue(base::Value::Dict value) : value_(std::move(value)) {}
~TracedValue() override = default;
private:
void AppendAsTraceFormat(std::string* out) const override {
if (!value_.empty()) {
std::string tmp;
base::JSONWriter::Write(value_, &tmp);
*out += tmp;
} else {
*out += "{}";
}
}
private:
base::Value::Dict value_;
};
// Inspired by http://crbug.com/418158806#comment2. This is more efficient than
// using TrackEvent::SetTrackDescriptor() because that would require us to keep
// extra state to ensure we only call it once.
class SourceTrack final : public perfetto::Track {
public:
SourceTrack(uint64_t uuid,
perfetto::Track parent_track,
perfetto::StaticString source_type_string)
: Track(uuid, parent_track), source_type_string_(source_type_string) {}
void Serialize(
perfetto::protos::pbzero::TrackDescriptor* track_descriptor) const {
const auto bytes = Serialize().SerializeAsString();
track_descriptor->AppendRawProtoBytes(bytes.data(), bytes.size());
}
perfetto::protos::gen::TrackDescriptor Serialize() const {
auto track_descriptor = Track::Serialize();
// We add a reasonably unique random string at the end of the track name
// to prevent the Perfetto UI from incorrectly merging identically-named
// tracks, which would be confusing in our case (e.g. separate independent
// URL requests being incorrectly stacked on top of each other). See
// https://crbug.com/417420482.
//
// Note this means the name is not really static, but it's fine to treat it
// as such as the dynamic part obviously doesn't carry any sensitive
// information.
track_descriptor.set_static_name(base::StringPrintf(
"%s %04x", source_type_string_.value, uuid % 0xFFFF));
return track_descriptor;
}
private:
perfetto::StaticString source_type_string_;
};
perfetto::StaticString SourceTypeToStaticString(NetLogSourceType source_type) {
return perfetto::StaticString(NetLog::SourceTypeToString(source_type));
}
} // namespace
TraceNetLogObserver::TraceNetLogObserver(Options options)
: capture_mode_(options.capture_mode),
use_sensitive_category_(options.use_sensitive_category),
verbose_(options.verbose),
root_track_name_(options.root_track_name) {}
TraceNetLogObserver::~TraceNetLogObserver() {
DCHECK(!net_log_to_watch_);
DCHECK(!net_log());
}
perfetto::Track TraceNetLogObserver::MaybeSetUpAndGetRootTrack() {
// -1 to prevent conflicts with source tracks (which use positive offsets).
perfetto::Track root_track(track_id_base_ - 1);
std::call_once(root_track_set_up_, [&] {
auto root_track_descriptor = root_track.Serialize();
root_track_descriptor.set_static_name(root_track_name_.value);
root_track_descriptor.set_child_ordering(
perfetto::protos::gen::TrackDescriptor::CHRONOLOGICAL);
base::TrackEvent::SetTrackDescriptor(root_track, root_track_descriptor);
});
return root_track;
}
void TraceNetLogObserver::OnAddEntry(const NetLogEntry& entry) {
base::Value::Dict params = entry.params.Clone();
// Add source's start time as a parameter. The net-log viewer requires it.
params.Set("source_start_time",
NetLog::TickCountToString(entry.source.start_time));
const perfetto::StaticString entry_type_string(
NetLogEventTypeToString(entry.type));
const auto source_type_string = SourceTypeToStaticString(entry.source.type);
if (verbose_) {
AddEntryVerbose(entry, entry_type_string, source_type_string,
std::move(params));
} else {
AddEntry(entry, entry_type_string, source_type_string, std::move(params));
}
}
void TraceNetLogObserver::AddEntry(const NetLogEntry& entry,
perfetto::StaticString entry_type_string,
perfetto::StaticString source_type_string,
base::Value::Dict params) {
const perfetto::Track track(track_id_base_ + entry.source.id,
MaybeSetUpAndGetRootTrack());
switch (entry.phase) {
case NetLogEventPhase::BEGIN:
TRACE_EVENT_BEGIN(kNetLogTracingCategory, entry_type_string, track,
"source_type", source_type_string, "params",
std::make_unique<TracedValue>(std::move(params)));
break;
case NetLogEventPhase::END:
TRACE_EVENT_END(kNetLogTracingCategory, track, "params",
std::make_unique<TracedValue>(std::move(params)));
break;
case NetLogEventPhase::NONE:
TRACE_EVENT_INSTANT(kNetLogTracingCategory, entry_type_string, track,
"source_type", source_type_string, "params",
std::make_unique<TracedValue>(std::move(params)));
break;
}
}
void TraceNetLogObserver::AddEntryVerbose(
const NetLogEntry& entry,
perfetto::StaticString entry_type_string,
perfetto::StaticString source_type_string,
base::Value::Dict params) {
const auto get_source_track = [&](uint32_t source_id,
perfetto::StaticString source_type_string) {
return SourceTrack(track_id_base_ + entry.source.id,
MaybeSetUpAndGetRootTrack(), source_type_string);
};
const auto track = get_source_track(entry.source.id, source_type_string);
// We use Perfetto Flows to relate the entry back to the thread that caused it
// be logged (typically, the network thread). This bridges the gap between
// thread call stacks and NetLog, allowing users to correlate them.
//
// To provide anchor points for the flow, we write instant events on the
// current thread stack.
//
// For "instant" events (NetLogEventPhase::NONE), we simply generate a random
// flow ID. The flow starts from the instant event we are writing to the
// current thread, and terminates on the NetLog event.
//
// For non-instant events, it's a bit trickier. For maximum readability, we
// want the flow to start from the instant event we are writing to the current
// thread for the BEGIN entry, go through the NetLog event, and then terminate
// on a separate thread event for the END entry. This means we need to use the
// same flow ID for BEGIN and END entries. There is no obvious ID we can use
// that would be identical between the two entries. The approach we use here
// is to generate the flow ID from the Track ID and the NetLog event type.
// This will work as long as a given Track doesn't have two NetLog events that
// are the same type *and* overlap in time. If this assumption breaks, we will
// need to revisit this approach; we may need to track additional state.
const auto thread_event_name_str = base::StringPrintf(
"%s: %s%s/%s", root_track_name_.value,
[&] {
switch (entry.phase) {
case NetLogEventPhase::BEGIN:
return "BEGIN ";
case NetLogEventPhase::END:
return "END ";
case NetLogEventPhase::NONE:
return "";
}
}(),
source_type_string.value, entry_type_string.value);
// Note: the separate variable is load-bearing, as DynamicString will not
// retain the std::string. See https://crbug.com/417982839.
const perfetto::DynamicString thread_event_name(thread_event_name_str);
const uint64_t thread_flow_id =
entry.phase == NetLogEventPhase::NONE
? base::RandUint64()
: track.uuid + std::hash<std::string_view>()(std::string_view(
reinterpret_cast<const char*>(&entry.type),
sizeof(entry.type)));
if (entry.phase != NetLogEventPhase::END) {
TRACE_EVENT_INSTANT(kNetLogTracingCategory, thread_event_name,
perfetto::Flow::ProcessScoped(thread_flow_id));
} else {
TRACE_EVENT_INSTANT(
kNetLogTracingCategory, thread_event_name,
perfetto::TerminatingFlow::ProcessScoped(thread_flow_id));
}
const auto add_thread_flow = [&](perfetto::EventContext& event_context) {
switch (entry.phase) {
case NetLogEventPhase::BEGIN:
perfetto::Flow::ProcessScoped(thread_flow_id)(event_context);
break;
case NetLogEventPhase::END:
// No need to add the flow: we already added it to this event while
// processing the BEGIN entry.
break;
case NetLogEventPhase::NONE:
perfetto::TerminatingFlow::ProcessScoped(thread_flow_id)(event_context);
break;
}
};
// The tracing category must be a compile-time constant, hence the macro to
// handle the sensitive vs non-sensitive categories.
#define CALL_TRACE_EVENT(TRACE_EVENT, ...) \
do { \
if (use_sensitive_category_) { \
TRACE_EVENT(kSensitiveNetLogTracingCategory, __VA_ARGS__); \
} else { \
TRACE_EVENT(kNetLogTracingCategory, __VA_ARGS__); \
} \
} while (false)
// We use Perfetto Flows to represent source dependencies; these will show up
// as arrows in the Perfetto UI. The dependency is on a source, i.e. a track,
// but Perfetto flows start from an event, not a track. To work around this we
// write a made-up instant event on the source dependency track to act as an
// anchor for the flow.
std::optional<uint64_t> source_dependency_flow_id;
const base::DictValue* const source_dependency =
params.FindDict("source_dependency");
if (source_dependency != nullptr) {
const std::optional<int> source_dependency_id =
source_dependency->FindInt("id");
const std::optional<int> source_dependency_type =
source_dependency->FindInt("type");
if (source_dependency_id.has_value() &&
source_dependency_type.has_value()) {
source_dependency_flow_id = base::RandUint64();
CALL_TRACE_EVENT(
TRACE_EVENT_INSTANT, entry_type_string,
get_source_track(
*source_dependency_id,
SourceTypeToStaticString(
static_cast<NetLogSourceType>(*source_dependency_type))),
perfetto::Flow::ProcessScoped(*source_dependency_flow_id));
}
}
const auto maybe_add_source_dependency_flow =
[&](perfetto::EventContext& event_context) {
if (source_dependency_flow_id.has_value()) {
perfetto::TerminatingFlow::ProcessScoped (*source_dependency_flow_id)(
event_context);
}
};
const auto set_event_fields = [&](perfetto::EventContext& event_context) {
add_thread_flow(event_context);
maybe_add_source_dependency_flow(event_context);
};
switch (entry.phase) {
case NetLogEventPhase::BEGIN:
CALL_TRACE_EVENT(TRACE_EVENT_BEGIN, entry_type_string, track,
set_event_fields, "source_type", source_type_string,
"params",
std::make_unique<TracedValue>(std::move(params)));
break;
case NetLogEventPhase::END:
CALL_TRACE_EVENT(TRACE_EVENT_END, track, set_event_fields, "params",
std::make_unique<TracedValue>(std::move(params)));
break;
case NetLogEventPhase::NONE:
CALL_TRACE_EVENT(TRACE_EVENT_INSTANT, entry_type_string, track,
set_event_fields, "source_type", source_type_string,
"params",
std::make_unique<TracedValue>(std::move(params)));
break;
}
#undef CALL_TRACE_EVENT
}
void TraceNetLogObserver::WatchForTraceStart(NetLog* netlog) {
DCHECK(!net_log_to_watch_);
DCHECK(!net_log());
net_log_to_watch_ = netlog;
// Tracing can start before the observer is even created, for instance for
// startup tracing.
if (base::trace_event::TraceLog::GetInstance()->IsEnabled())
OnTraceLogEnabled();
base::trace_event::TraceLog::GetInstance()->AddAsyncEnabledStateObserver(
weak_factory_.GetWeakPtr());
}
void TraceNetLogObserver::StopWatchForTraceStart() {
// Should only stop if is currently watching.
DCHECK(net_log_to_watch_);
base::trace_event::TraceLog::GetInstance()->RemoveAsyncEnabledStateObserver(
this);
// net_log() != nullptr iff NetLog::AddObserver() has been called.
// This implies that if the netlog category wasn't enabled, then
// NetLog::RemoveObserver() will not get called, and there won't be
// a crash in NetLog::RemoveObserver().
if (net_log())
net_log()->RemoveObserver(this);
net_log_to_watch_ = nullptr;
}
void TraceNetLogObserver::OnTraceLogEnabled() {
bool enabled;
TRACE_EVENT_CATEGORY_GROUP_ENABLED(kNetLogTracingCategory, &enabled);
if (!enabled)
return;
net_log_to_watch_->AddObserver(this, capture_mode_);
}
void TraceNetLogObserver::OnTraceLogDisabled() {
if (net_log())
net_log()->RemoveObserver(this);
}
} // namespace net