Skip to content

Commit

Permalink
Refactor TraceEvent format (#48269)
Browse files Browse the repository at this point in the history
Summary:
Pull Request resolved: #48269

# Changelog: [Internal]

I've noticed that our definition of Trace Event is different from the one that is defined in Google's doc / V8 / Chrome. This has some flaws:
* It creates fragmentation, like with custom track ids or with mocked process ids.
* Current implementation is strict the relationship between `performance.mark()`, `performance.measure` APIs and Instant, Complete Trace Events. Basically only something recorded with `performance.mark` can be an instant trace event.

This should unblock recording custom trace events inside `PerformanceTracer`, such as when tracing started and others. Same could be said about events related to CPU profiling from Hermes, which will be based on these APIs.

This is the pre-requisite for next diff that will add emitting `TracingStartedInPage` event. With this event, the trace should look similar to the one recorded in the browser, and Timings / Main tracks no longer should be registered manually.

Reviewed By: huntie

Differential Revision: D67207107

fbshipit-source-id: fd7f55dd82167c14a63c2d93aaa649072c5a2a2c
  • Loading branch information
hoxyq authored and facebook-github-bot committed Dec 16, 2024
1 parent 4368368 commit 03a1246
Show file tree
Hide file tree
Showing 2 changed files with 149 additions and 58 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -49,12 +49,11 @@ bool PerformanceTracer::stopTracingAndCollectEvents(

tracing_ = false;
if (buffer_.empty()) {
customTrackIdMap_.clear();
return true;
}

auto traceEvents = folly::dynamic::array();
auto savedBuffer = std::move(buffer_);
buffer_.clear();

// Register "Main" process
traceEvents.push_back(folly::dynamic::object(
Expand All @@ -69,27 +68,29 @@ bool PerformanceTracer::stopTracingAndCollectEvents(
"cat", "__metadata")("name", "thread_name")("ph", "M")("pid", PID)(
"tid", USER_TIMINGS_DEFAULT_TRACK)("ts", 0));

auto customTrackIdMap = getCustomTracks(savedBuffer);
for (const auto& [trackName, trackId] : customTrackIdMap) {
for (const auto& [trackName, trackId] : customTrackIdMap_) {
// Register custom tracks
traceEvents.push_back(folly::dynamic::object(
"args", folly::dynamic::object("name", trackName))("cat", "__metadata")(
"name", "thread_name")("ph", "M")("pid", PID)("tid", trackId)("ts", 0));
}

for (auto& event : savedBuffer) {
for (auto event : buffer_) {
// Emit trace events
traceEvents.push_back(serializeTraceEvent(event, customTrackIdMap));
traceEvents.push_back(serializeTraceEvent(event));

if (traceEvents.size() >= 1000) {
resultCallback(traceEvents);
traceEvents = folly::dynamic::array();
}
}
customTrackIdMap_.clear();
buffer_.clear();

if (traceEvents.size() >= 1) {
resultCallback(traceEvents);
}

return true;
}

Expand All @@ -100,8 +101,15 @@ void PerformanceTracer::reportMark(
if (!tracing_) {
return;
}
buffer_.push_back(TraceEvent{
.type = TraceEventType::MARK, .name = std::string(name), .start = start});

TraceEventBase* event = new InstantTraceEvent{
std::string(name),
std::vector{TraceEventCategory::UserTiming},
start,
PID, // FIXME: This should be real process ID.
USER_TIMINGS_DEFAULT_TRACK, // FIXME: This should be real thread ID.
};
buffer_.push_back(event);
}

void PerformanceTracer::reportMeasure(
Expand All @@ -114,62 +122,85 @@ void PerformanceTracer::reportMeasure(
return;
}

std::optional<std::string> track;
uint64_t threadId =
USER_TIMINGS_DEFAULT_TRACK; // FIXME: This should be real thread ID.
if (trackMetadata.has_value()) {
track = trackMetadata.value().track;
std::string trackName = trackMetadata.value().track;

if (!customTrackIdMap_.contains(trackName)) {
uint64_t trackId =
USER_TIMINGS_DEFAULT_TRACK + customTrackIdMap_.size() + 1;
threadId = trackId;

customTrackIdMap_.emplace(trackName, trackId);
}
}

buffer_.push_back(TraceEvent{
.type = TraceEventType::MEASURE,
.name = std::string(name),
.start = start,
.duration = duration,
.track = track});
TraceEventBase* event = new CompleteTraceEvent{
std::string(name),
std::vector{TraceEventCategory::UserTiming},
start,
PID, // FIXME: This should be real process ID.
threadId, // FIXME: This should be real thread ID.
duration};
buffer_.push_back(event);
}

std::unordered_map<std::string, uint32_t> PerformanceTracer::getCustomTracks(
std::vector<TraceEvent>& events) {
std::unordered_map<std::string, uint32_t> trackIdMap;

uint32_t nextTrack = USER_TIMINGS_DEFAULT_TRACK + 1;
for (auto& event : events) {
// Custom tracks are only supported by User Timing "measure" events
if (event.type != TraceEventType::MEASURE) {
continue;
std::string PerformanceTracer::serializeTraceEventCategories(
TraceEventBase* event) const {
std::string result;

for (const auto& category : event->categories) {
switch (category) {
case TraceEventCategory::UserTiming:
result += "blink.user_timing";
break;
case TraceEventCategory::TimelineEvent:
result += "disabled-by-default-devtools.timeline";
break;

default:
throw std::runtime_error("Unknown trace event category");
}

if (event.track.has_value() && !trackIdMap.contains(event.track.value())) {
auto trackId = nextTrack++;
trackIdMap[event.track.value()] = trackId;
}
result += ",";
}

return trackIdMap;
if (result.length() > 0) {
result.pop_back();
}

return result;
}

folly::dynamic PerformanceTracer::serializeTraceEvent(
TraceEvent& event,
std::unordered_map<std::string, uint32_t>& customTrackIdMap) const {
TraceEventBase* event) const {
folly::dynamic result = folly::dynamic::object;

result["args"] = folly::dynamic::object();
result["cat"] = "blink.user_timing";
result["name"] = event.name;
result["pid"] = PID;
result["ts"] = event.start;
result["name"] = event->name;
result["cat"] = serializeTraceEventCategories(event);
result["args"] = event->args;
result["ts"] = event->timestamp;
result["pid"] = event->processId;
result["tid"] = event->threadId;

switch (event.type) {
case TraceEventType::MARK:
switch (event->type) {
case TraceEventType::Instant:
result["ph"] = "I";
result["tid"] = USER_TIMINGS_DEFAULT_TRACK;

break;
case TraceEventType::MEASURE:
result["dur"] = event.duration;

case TraceEventType::Complete: {
result["ph"] = "X";
result["tid"] = event.track.has_value()
? customTrackIdMap[event.track.value()]
: USER_TIMINGS_DEFAULT_TRACK;

auto completeEvent = static_cast<CompleteTraceEvent*>(event);
result["dur"] = completeEvent->duration;

break;
}

default:
throw std::runtime_error("Unknown trace event type");
}

return result;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -22,16 +22,78 @@ namespace facebook::react::jsinspector_modern {
// design is copied from earlier FuseboxTracer prototype).

enum class TraceEventType {
MARK = 1,
MEASURE = 2,
Instant,
Complete,
};

struct TraceEvent {
TraceEventType type;
enum class TraceEventCategory {
UserTiming,
TimelineEvent,
};

/*
* Based on the out-of-date "Trace Event Format" document from Google and our
* findings while reverse engineering the contract between Chrome and Chrome
* DevTools.
* https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?pli=1&tab=t.0#heading=h.yr4qxyxotyw
*/
struct TraceEventBase {
std::string name;
uint64_t start;
uint64_t duration = 0;
std::optional<std::string> track;
std::vector<TraceEventCategory> categories;
TraceEventType type;
uint64_t timestamp;
uint64_t processId;
uint64_t threadId;
folly::dynamic args = folly::dynamic::object();
};

template <TraceEventType T>
struct TraceEvent : public TraceEventBase {
TraceEvent(
std::string name,
std::vector<TraceEventCategory> categories,
uint64_t timestamp,
uint64_t processId,
uint64_t threadId)
: TraceEventBase{
std::move(name),
std::move(categories),
T,
timestamp,
processId,
threadId} {}
};

struct CompleteTraceEvent : public TraceEvent<TraceEventType::Complete> {
uint64_t duration;

CompleteTraceEvent(
std::string name,
std::vector<TraceEventCategory> categories,
uint64_t timestamp,
uint64_t processId,
uint64_t threadId,
uint64_t duration)
: TraceEvent<
TraceEventType::
Complete>{std::move(name), std::move(categories), timestamp, processId, threadId},
duration(duration) {}
};

struct InstantTraceEvent : public TraceEvent<TraceEventType::Instant> {
InstantTraceEvent(
std::string name,
std::vector<TraceEventCategory> categories,
uint64_t timestamp,
uint64_t processId,
uint64_t threadId)
: TraceEvent<TraceEventType::Instant>{
std::move(name),
std::move(categories),
timestamp,
processId,
threadId} {}
};

/**
Expand Down Expand Up @@ -83,14 +145,12 @@ class PerformanceTracer {
PerformanceTracer& operator=(const PerformanceTracer&) = delete;
~PerformanceTracer() = default;

std::unordered_map<std::string, uint32_t> getCustomTracks(
std::vector<TraceEvent>& events);
folly::dynamic serializeTraceEvent(
TraceEvent& event,
std::unordered_map<std::string, uint32_t>& customTrackIdMap) const;
std::string serializeTraceEventCategories(TraceEventBase* event) const;
folly::dynamic serializeTraceEvent(TraceEventBase* event) const;

bool tracing_{false};
std::vector<TraceEvent> buffer_;
std::unordered_map<std::string, uint64_t> customTrackIdMap_;
std::vector<TraceEventBase*> buffer_;
std::mutex mutex_;
};

Expand Down

0 comments on commit 03a1246

Please sign in to comment.