Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Support the chrome JSON trace format (allows viewing of hermes traces) #453

Merged
merged 25 commits into from
Dec 26, 2023

Conversation

zacharyfmarion
Copy link
Contributor

@zacharyfmarion zacharyfmarion commented Dec 21, 2023

Add support for the chrome JSON object trace format. I have tested this with hermes profiles, which spit out a version of the spec with additional information in the stack frame. Mainly inspiration was taken from two sources:

Example profiles

Specifically I pulled some code from this file. While this works great for raw profiles, the hermes-profile-transformer package also applies sourcemaps, which is something that I would like to by applied for hermes profiles as well. It's a little awkward because in the hermes profile file format, there isn't actually a field from the file path where a given function in a frame originated - instead it is in parentheses after the function name. Also I will need to update the implementations in three places:

  1. https://github.com/react-native-community/hermes-profile-transformer
  2. https://github.com/react-native-community/cli
  3. Bump version in react

Which is a little overwhelming. Given time constraints I might not get a chance to land all of this for a while. I think in the shorter term it would be nice to just add some specific support for hermes-generated trace profiles in the trace-event file. Discussion on this is here

Example

Trace event format Trace event object format
Screenshot 2023-12-20 at 10 21 29 PM Screenshot 2023-12-20 at 10 21 55 PM

@@ -189,8 +194,8 @@ async function _importProfileGroup(dataSource: ProfileDataSource): Promise<Profi
return toGroup(importFromInstrumentsDeepCopy(contents))
}

if (/^(Stack_|Script_|Obj_)\S+ log opened \(PC\)\n/.exec(contents.firstChunk())){
console.log("Importing as Papyrus profile")
if (/^(Stack_|Script_|Obj_)\S+ log opened \(PC\)\n/.exec(contents.firstChunk())) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All changes unrelated to hermes are from running npm run prettier. Might be worth adding npm run prettier --check to the ci.yml so PRs fail if committers have not run the formatter

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was already part of the repo (though using an eslint plugin instead of prettier --check for reasons I don't remember)

But I broke it 3 years ago! PR to fix that is here: #454

I'm going to wait until this merges though to avoid you dealing with annoying merge conflicts

@coveralls
Copy link

coveralls commented Dec 21, 2023

Coverage Status

coverage: 43.427% (+0.4%) from 43.041%
when pulling c8c1e7f on zacharyfmarion:zac/hermes-format
into dfd3a0d on jlfwong:main.

@zacharyfmarion
Copy link
Contributor Author

zacharyfmarion commented Dec 21, 2023

Actually after looking at this some more it looks like spec is actually part of the chrome trace event spec? But it doesn't currently seem to be implemented...at least hermes profiles did not work before. @jlfwong should I name this something more generic?

@jlfwong
Copy link
Owner

jlfwong commented Dec 21, 2023

Going to continue discussion of both #451 (comment) and this PR here, since they're intertwined.

Given that this is an extension of the chrome trace event spec, this should IMO live inside of import/trace-event.ts. That file already contains handling of both a TraceEvent[] format and a {traceEvents: TraceEvent[]} format, so this seems like a fairly natural extension. And that unfortunately means it similarly should be generic w.r.t. handling of args.

That said, if there are highly reliable ways to see from analysis of a profile that it was specifically generated by Hermes, whether it be a {traceEvents, stackFrames, samples} profile as in this PR, or one of the existing supported trace event formats, I'm open to accepting a patch to trace-event.ts which ignores args in that case because they're known to be useless when coming from Hermes.

This could be through structural analysis of the JSON, or it could be from filename matching if Hermes spits out files with a specific naming convention.

Does that sound tenable?

@zacharyfmarion
Copy link
Contributor Author

@jlfwong Okay sounds good - I will refactor trace-event to support the json object format - are you okay with me keeping the main json import code in a separate file? The trace-event file is already pretty large. Not sure if you're opposed to me creating a folder in the imports directory called traceEvent that has a types file and then two files, one for each import type. I can put it all in one file if you prefer.

Re. the hermes format - I should be able to reliably detect if the args match what hermes exports - thanks for understanding. I will do that after this lands and we can iterate. I definitely don't want to merge anything you're not comfortable with.

@@ -122,3 +122,7 @@ test('importTraceEvents invalid x nesting', async () => {
test('importTraceEvents event reordering name match', async () => {
await checkProfileSnapshot('./sample/profiles/trace-event/event-reordering-name-match.json')
})

test('importTraceEvents simple json profile', async () => {
Copy link
Contributor Author

@zacharyfmarion zacharyfmarion Dec 21, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can add a test for supporting multiple threads but I don't know where to get it - @jlfwong do you know where to get one in the wild? Hermes only has one thread

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added test here

@zacharyfmarion
Copy link
Contributor Author

Went ahead and pushed it up, can clean up a bit later

* next thing to leave (top of the stack). If this is not the case we warn, and then leave
* the frame at the top of the stack
*/
function tryToLeaveFrame(frame: StackFrame, timestamp: number) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is some duplication here but I'm not sure if the juice is worth the squeeze...happy to refactor if you think otherwise

@zacharyfmarion zacharyfmarion changed the title Support the hermes profile format Support the chrome JSON trace format (allows viewing of hermes traces) Dec 22, 2023
@jlfwong
Copy link
Owner

jlfwong commented Dec 22, 2023

@zacharyfmarion thanks for being so responsive to feedback! is this ready to review now, or should I hold off for further changes?

@zacharyfmarion
Copy link
Contributor Author

@jlfwong ready for review!

Copy link
Owner

@jlfwong jlfwong left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, digging in! Thanks for getting this working, and I hope you'll bear with me for a fairly thorough review since this is changing control flow for codepaths I update semi-frequently.

First, and probably most importantly, I think you want to use StackListProfileBuilder instead of CallTreeProfileBuilder for this. I think that will obviate the need for more than half the code in trace-event-json.ts.

Second, I have some really high-level feedback on control flow and type structuring. There are two principles that I try to uphold in the codebase that this is deviating from:

  1. Whenever it isn't performance prohibitive, default to pure functions. The clearest deviation from that in this PR is the buildFunction which mutates a ProfileBuilder in place.

  2. Whenever possible, I try to keep types semantically meaningful, rather than just balls of fields that are incidentally related because of the particular control flow of the code. One indication of when this is happening is that some of the fields are only accessed in a single function somewhere because it was a convenient way of threading them through the control logic. The clearest deviation of this is the existence of ProfileBuilderInfo, where, for example, pid and tid are only accessed in jsonObjectTraceBuilder, and importableEvents is only accessed in constructProfileFromTraceEvents. Once you remove those fields which are only accessed in one place, the only thing left is the ProfileBuilder. Usually this kind of code smell can be resolved by deleting the type and just threading the relevant variables where they actually need to be.

I think in this particular case, both of these problems can be resolved by the extraction of a few helper functions (e.g. a getNameForProfile(pid, tid, processNamesByPid, threadNamesByTid): string) function, and then dropping the buildFunction callback altogether.

Instead, similar to the pattern that pre-dates this PR of having an eventListToProfileGroup function which returns a ProfileGroup, you could have an sampleListToProfileGroup which is still a pure function. It will create slightly more code duplication, but I think the clarity of control flow is worth it.

@@ -65,16 +66,47 @@ interface XTraceEvent extends TraceEvent {
// The trace format supports a number of event types that we ignore.
type ImportableTraceEvent = BTraceEvent | ETraceEvent | XTraceEvent

export interface StackFrame {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As much as possible, I try to keep my exported type-names globally unique and only generic if they are intended to be used generically over the entire codebase. In this case, this is specific to trace events, so TraceEventStackFrame would IMO be better here.

parent?: number
}

export interface Sample {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same here -- TraceEventSample please

stackFrameData?: StackFrame
}

export interface TraceEventJsonObject {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is IMO pretty undescriptive of a name, especially given that {traceEvent: TraceEvent[]} is also conceptually a trace event json object.

What do you think about TraceEventWithSamples?

It's probably worth making {traceEvents: TraceEvent[]} it's own type, and having TraceEventWithSamples explicitly extend the interface

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TraceEventWithSamples to me sounds like it s a single TraceEvent with additional fields, instead of an object that contains an array of traceEvents, along with samples. How about ChromeTraceWithSamples?

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, naming things is hard. ChromeTraceWithSamples sounds to me like it's specific to Chrome, and there's a whole separate importer in speedscope for Chrome profiles specifically (since they have their own format for CPU profiles that's totally unrelated to trace event -- the JavaScript profiler and the full-browser profiler are totally separate.

But I hear you that TraceEventWithSamples is also not a good name. TraceEventsObjectWithSamples?

function pidTidKey(pid: number, tid: number): string {
// We zero-pad the PID and TID to make sorting them by pid/tid pair later easier.
return `${zeroPad('' + pid, 10)}:${zeroPad('' + tid, 10)}`
}

function partitionByPidTid(events: ImportableTraceEvent[]): Map<string, ImportableTraceEvent[]> {
const map = new Map<string, ImportableTraceEvent[]>()
function partitionByPidTid<T extends {tid: number | string; pid: number | string}>(
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice 👌

Comment on lines 146 to 148
* @param activeNodeIds - The ids of the functions that are active at this timestamp
* @param lastActiveNodeIds - The ids of the functions active at the previous timestamp
* @param timestamp - The current timestamp (microseconds)
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't use jsdoc anywhere else in the codebase, please remove

Comment on lines 114 to 137
if (lastActiveFrame == null) {
console.warn(
`Tried to end frame "${
frameInfoForEvent(frame).key
}", but the stack was empty. Doing nothing instead.`,
)
return
}

const frameInfo = frameInfoForEvent(frame)
const lastActiveFrameInfo = frameInfoForEvent(lastActiveFrame)

if (frame.name !== lastActiveFrame.name) {
console.warn(
`ts=${timestamp}: Tried to end "${frameInfo.key}" when "${lastActiveFrameInfo.key}" was on the top of the stack. Doing nothing instead.`,
)
return
}

if (frameInfo.key !== lastActiveFrameInfo.key) {
console.warn(
`ts=${timestamp}: Tried to end "${frameInfo.key}" when "${lastActiveFrameInfo.key}" was on the top of the stack. Ending ${lastActiveFrameInfo.key} instead.`,
)
}
Copy link
Owner

@jlfwong jlfwong Dec 24, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Was this just here for debugging? CallTreeProfileBuilder.leaveFrame (or more specifically CallTreeProfileBuilder._leaveFrame) should handle this warnings of this class of error already.

(This is probably irrelevant if you switch to StackListProfileBuilder)

* key is the frame id and the value is the stack frame object.
*/
function getFrameById(frameId: string | number): StackFrame {
return contents.stackFrames[String(frameId)]
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would it be wise to throw here if the key is missing? The return type here isn't nullable, but it's certainly possible to have corrupt data that's missing entries in the stackFrames mapping

* Initialization function to enable O(1) access to the set of active nodes in the stack by node ID.
*/
function getActiveNodeArrays(profile: TraceEventJsonObject): Map<number, number[]> {
const map: Map<number, number[]> = new Map<number, number[]>()
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This could just be const map = new Map<number, number[]>() with no loss of type information

* @param lastActiveNodeIds - The ids of the functions active at the previous timestamp
* @param timestamp - The current timestamp (microseconds)
*/
function handleSample(activeNodeIds: number[], lastActiveNodeIds: number[], timestamp: number) {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I haven't looked closely at the profile format, but it occurs to me that StackListProfileBuilder may be much better suited to dealing with this kind of profile than CallTreeProfileBuilder is.

const node = profile.stackFrames[id]
if (!node) throw new Error(`No such node ${id}`)
if (node.parent) {
const array = getActiveNodes(node.parent).concat([id])
Copy link
Owner

@jlfwong jlfwong Dec 24, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This gives me mild pause. This is cloning the array for every child, which seems like it could end up being a ton of memory. If you have a call-stack that's N frames deep, this will allocate O(N^2) memory because the root node will be in N arrays, the one below it in N-1 arrays, etc.

I think this is irrelevant, however, if you switch to using StackListProfileBuilder instead though. If you use that, then you can just do a single traversal on-demand to construct the list of samples the only time you need them (to pass to StackListProfileBuilder.appendSample), rather than building a map for repeated O(1) lookups.

@zacharyfmarion
Copy link
Contributor Author

zacharyfmarion commented Dec 24, 2023

@jlfwong Thank you for the thorough review - I will likely take a look at this after Christmas - I totally missed StackListProfileBuilder 🤦 . Will read through that code and update!

Comment on lines 561 to 611
function eventListToProfileGroup(events: TraceEvent[]): ProfileGroup {
const importableEvents = filterIgnoredEventTypes(events)
const partitionedTraceEvents = partitionByPidTid(importableEvents)
const profileNamesByPidTid = getProfileNameByPidTid(events, partitionedTraceEvents)

const profilePairs: [string, Profile][] = []

profileNamesByPidTid.forEach((name, pidTidKey) => {
const importableEventsForPidTid = partitionedTraceEvents.get(pidTidKey)

if (!importableEventsForPidTid) {
throw new Error(`Could not find events for key: ${importableEventsForPidTid}`)
}

profilePairs.push([pidTidKey, constructProfileFromTraceEvents(importableEventsForPidTid, name)])
})

// For now, we just sort processes by pid & tid.
// TODO: The standard specifies that metadata events with the name
// "process_sort_index" and "thread_sort_index" can be used to influence the
// order, but for simplicity we'll ignore that until someone complains :)
sortBy(profilePairs, p => p[0])

return {
name: '',
indexToView: 0,
profiles: profilePairs.map(p => p[1]),
}
}

function sampleListToProfileGroup(contents: TraceWithSamples): ProfileGroup {
const importableEvents = filterIgnoredEventTypes(contents.traceEvents)
const partitionedTraceEvents = partitionByPidTid(importableEvents)
const partitionedSamples = partitionByPidTid(contents.samples)
const profileNamesByPidTid = getProfileNameByPidTid(contents.traceEvents, partitionedTraceEvents)

const profilePairs: [string, Profile][] = []

profileNamesByPidTid.forEach((name, pidTidKey) => {
const samplesForPidTid = partitionedSamples.get(pidTidKey)

if (!samplesForPidTid) {
throw new Error(`Could not find samples for key: ${samplesForPidTid}`)
}

if (samplesForPidTid.length === 0) {
return
}

profilePairs.push([pidTidKey, constructProfileFromSampleList(contents, samplesForPidTid, name)])
})
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jlfwong not sure how you feel about this duplication...I can abstract some stuff away or just keep it like this depending on what you think

@jlfwong
Copy link
Owner

jlfwong commented Dec 25, 2023

@zacharyfmarion looks like you couldn't wait until after Christmas 😄

High level this looks great! Thanks for taking all the feedback in stride. It looks like there are tests failing now, so it seems like the refactor changed the output. Let me know when that's resolved and this is ready for another look

@zacharyfmarion
Copy link
Contributor Author

zacharyfmarion commented Dec 25, 2023

@jlfwong hahaha yep got antsy! Tests were correctly failing as I thought "weight" represented the time diff between the previous sample and current sample, instead of the current sample and the next one. Updated and it looks like the profiles look the same as before the refactor. Should be ready for another round of feedback whenever you get a chance!

Copy link
Owner

@jlfwong jlfwong left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is looking great! Thanks for following through with all the feedback. We're down to small nits. After those are addressed, this will be good to merge

Comment on lines 290 to 295
export type ProfileBuilderInfo = {
profileBuilder: CallTreeProfileBuilder
importableEvents: ImportableTraceEvent[]
pid: number
tid: number
}
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is unused now, so please remove

* Returns an array containing the time difference in microseconds between the current
* sample and the next sample
*/
function getTimeDeltasForSamples(samples: Sample[]) {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Add a return type annotation here please:

function getTimeDeltasForSamples(samples: Sample[]): number[] {

}

function getActiveFramesForSample(
stackFrames: TraceWithSamples['stackFrames'],
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tend to avoid using this kind of type indexing because it adds an unnecessary level of indirection in trying to understand type signatures.

There are occasionally good reasons to do this in the case of generics, but this IMO isn't one of them. If you changed the type of TraceWithSamples['stackFrames'] above you'd still need to update the code below because you have frame: StackFrame directly, so this also doesn't buy you anything in terms of flexibility (which would be irrelevant anyway, since these types are based on a static external spec)

So, TL;DR: I think this should just be {[key: string]: StackFrame} instead.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks there are no references to Record which is a nice ts helper I use a lot - I will use {[key: string]: StackFrame} to keep consistency with the codebase.

interface TraceWithSamples {
traceEvents: TraceEvent[]
samples: Sample[]
stackFrames: {[key in string]: StackFrame}
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've never seen [key in string] used here -- this is the same as [key: string]: StackFrame, right?

The in syntax is just for mapped types AFAIK?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, this is unnecessary

Comment on lines +525 to +534
while (parent) {
const frame: StackFrame = stackFrames[parent]

if (!frame) {
throw new Error(`Could not find frame for id ${parent}`)
}

frames.push(frameInfoForSampleFrame(frame))
parent = frame.parent
}
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Technically there could be a cycle here that would cause the browser to hang, but I guess we'll worry about that if someone finds a real profile in the wild that does that. It wouldn't be a valid profile, but it's certainly possible to construct a file that would do this

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point - I can just keep a counter and if the number of parents > total number of frames I can throw an error. Will hold off for now since it will make the code less readable but if you'd prefer I'm happy to make the change.

Comment on lines +551 to +556
samples.forEach((sample, index) => {
const timeDelta = timeDeltas[index]
const activeFrames = getActiveFramesForSample(contents.stackFrames, sample.sf)

profileBuilder.appendSampleWithWeight(activeFrames, timeDelta)
})
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Haha yeah that looks a lot simpler

contents: TraceWithSamples,
samples: Sample[],
name: string,
) {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Add a return type to the function signature please

I have the eslint rule dispabled to always enforce return types being required because sometimes it's absurdly obvious or annoying to do, but here not's not trivially obvious.

Also for consistency, please rename to sampleListToProfile

Copy link
Contributor Author

@zacharyfmarion zacharyfmarion Dec 26, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will add a type - there are four functions:

  • eventListToProfileGroup which calls constructProfileFromTraceEvents for each thread
  • sampleListToProfileGroup which calls constructProfileFromSampleList for each thread

Would you like me to rename to eventListToProfile and sampleListToProfile - that sound good?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated here, seems sensible

@zacharyfmarion
Copy link
Contributor Author

zacharyfmarion commented Dec 26, 2023

@jlfwong awesome - attempted to address feedback, should be ready for another look. No rush though 😄

@jlfwong jlfwong merged commit b214804 into jlfwong:main Dec 26, 2023
8 checks passed
@jlfwong
Copy link
Owner

jlfwong commented Dec 26, 2023

@zacharyfmarion Okay! This is deployed now on https://www.speedscope.app/

Are you still planning on following up with some hermes-specific changes? After that, would love to signal boost this since I'm sure there are other react native devs that could take advantage of these changes

@zacharyfmarion
Copy link
Contributor Author

@jfwong thank you so much! I will open a PR for the Hermes-specific changes today. I agree, once I'm back at work in the new year I can get my coworkers to help get the message out.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants