Format Support: Trace Event Format

[uber-mahyar2]

Chrome has a simplified trace format which is a json list of trace dictionaries. This is the main format we generate internally at our company, so it would be nice if speedscope could render them.

This test trace file loads in chrome://tracing while it gives an error in speedscope.

test.json.zip

[jlfwong]

Hey!

This isn't a supported file format at all right now, so this is a feature request.

As far as I can tell from inspecting the test.json file, this doesn't contain a flamechart at all:

[
{"name":"_dyld_start","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7269,"dur":1216203},
{"name":"dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7269,"dur":105},
{"name":"dyldbootstrap::start(macho_header const*, int, char const**, long, macho_header const*, unsigned long*)","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7269,"dur":105},
{"name":"dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*)","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7375,"dur":1216097},
{"name":"csops","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7375,"dur":115},
{"name":"dyld3::loadDyldCache(dyld3::SharedCacheOptions const&, dyld3::SharedCacheLoadInfo*)","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7491,"dur":209},
{"name":"dyld3::reuseExistingCache(dyld3::SharedCacheOptions const&, dyld3::SharedCacheLoadInfo*)","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7491,"dur":209},
{"name":"dyld3::getCachePath(dyld3::SharedCacheOptions const&, unsigned long, char*)","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7491,"dur":209},
{"name":"dyld::my_stat(char const*, stat*)","cat":"Auto","ph":"X","pid":1,"tid":1,"ts":7491,"dur":209}
]

So I'm not actually sure what I would display for this. Speedscope may later evolve to display arbitrary network-view like waterfall graphs, but that isn't the intent of the tool at the moment. As far as I can tell from looking at this file, there are no guarantees about this forming a call tree of any kind. Is that right?

I believe this is a file in the format described here, right? https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview

[uber-mahyar2]

Yeah it's the trace format in that doc.

It looks very similar to this format that currently works: Profile-20180628T170616.json.zip

I cut a much larger trace into that smaller one, since it worked in the chrome trace and it would be simpler to understand. The bigger trace has a similar problem. It comes from stack snapshots that we globbed together into spans for the chrome tracer, much like this item in the attached Profile.json:

  {
    "pid": 1996,
    "tid": 27395,
    "ts": 11937507063,
    "ph": "X",
    "cat": "toplevel",
    "name": "MessagePumpLibevent::OnLibeventNotification",
    "args": {
      "src_file": "../../mojo/edk/system/channel_posix.cc",
      "src_func": "StartOnIOThread"
    },
    "dur": 61,
    "tdur": 62,
    "tts": 178590489
  },

So the original data source it comes from are call trees. When you give the chrome tracer the "ph": "X" type spans, chrome seems to expect they are call trees too, because the rendering goes pretty wonky if it isn't. What chrome is rendering looks like it's a call tree to me:

But yes, it doesn't guarantee they are call trees.

[jlfwong]

Okay, I've read most of the spec for the .trace file format, and basic support for traces with just "X", "B", and "E" events given a single process and a single thread shouldn't be too difficult.

To support multiple processes/threads, speedscope will need to support display of multiple processes/threads (or more generally of multiple profiles, which now tracked in #82.

Trace files also seem like they can support a much richer set of data than just flamecharts (counters, instantaneous events, async events, object events, etc.), some of which won't have reasonable representations in speedscope without additional visualization primitives (which I would like to add eventually, but isn't a priority for me).

[jlfwong]

I’ll commit to implementing this feature myself if a total of $200 of donations is made to any combination of these specific charities:

• American Civil Liberties Union
• /dev/color: /dev/color is a non-profit organization whose mission is to empower Black software engineers to help one another grow into industry leaders.
• Girls Who Code: Girls Who Code was founded with a single mission: to close the gender gap in technology

In this particular case, the $200 would go towards basic import of "B", "E", and "X" events across multiple processes/threads, but would not include visualization of asynchronous events or instantaneous events.

If you’d like to contribute to that total, please post a screenshot of your donation receipt in this thread*.

Independent of that, I would accept a PR to implement this, regardless of donation amounts.

*: I'm planning on trying this policy on a number of issues. Donations will apply to the total of exactly one issue, so please don't post the same receipt in multiple issue threads.

[aras-p]

Would love this too! We have various internal tools that generate profiling data in Chrome Tracing format (mostly just using "X" events really - start time and duration); I've blogged about our usage of it here and here and here.

I see that you have the "will implement if donations there happen" above, how would I go about doing that? :)

[jlfwong]

@aras-p Thanks for the interest! Basically just donate to one of the 3 listed charities and post a receipt. I'm trusting people not to forge receipts :)

You can see an example of work that was successfully funded here: https://github.com/jlfwong/speedscope/issues/60

EDIT: I updated the above description to say that an initial implementation would include support for "X" events too, since it sounds like it shouldn't really be any harder than just "B" and "E" events.

[aras-p]

Ok done!

[jlfwong]

@aras-p Thank you so much! I'll try to get start on this on the weekend :)

[jlfwong]

I merged #197 which implements basic support, but I haven't published or deployed the change yet because my internet is in a just barely working state at home right now. I'll try to get the deploy running tomorrow.

[jlfwong]

@aras-p This is now live on https://www.speedscope.app/ and published as speedscope on npm. Can you please give this a try and see if this meets your needs? There's a bunch of ambiguity about the right way of implementing some of this stuff, so I'd be grateful for feedback.

[aras-p]

@jlfwong some of the trace profiles I had work beautifully now, thanks!

Some others fail to load, seemingly as soon as the trace has "thread/process metadata" (like thread name) event of ph:M type. If they were just ignored, that would be better than not supporting the trace at all.

Attached a couple files that don't load right now. The others (produced by other tools that we have that don't emit M events) load fine and look great! I'd like a way to see multiple thread timelines at once, but that sounds like a wholly separate feature request :)

FailingToLoadExamples.zip

[jlfwong]

I'd like a way to see multiple thread timelines at once, but that sounds like a wholly separate feature request :)

Indeed :) This is unfortunately a lot of work. That's tracked in #117. I don't have a bounty set on that because I'm not actually sure how much work it would be in practice.

Attached a couple files that don't load right now.

Thanks for taking the time to do this! I'll try to take a look sometime this week or next at the profiles that don't load.

[jlfwong]

@aras-p Okay! The issue that was preventing MacPlayer_frontend.json and bugreporter_frontend.json from importing should now be fixed in speedscope@1.4.1. That build is also live on https://www.speedscope.app/. Please let me know if you run into other issues!

[aras-p]

Works beautifully now, thanks!