910e62b5创建于 1月15日历史提交
// 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