Perfetto UI: Chrome async events not shown about perfetto HOT 25 CLOSED

Hi! Thanks for the bug report 👍

It looks like the issue is these events are reported with phase b:

{"args":{"state":"silent"},"cat":"toplevel","id2":{"local":"0x7fbbc001b138"},"name":"RendererAudioState","ph":"b","pid":31089,"scope":"toplevel","tid":775,"ts":16760681614},
{"args":{"state":"renderer_backgrounded"},"cat":"toplevel","id2":{"local":"0x7fbbc001af78"},"name":"RendererPriority","ph":"b","pid":31089,"scope":"toplevel","tid":775,"ts":16760681617},
{"args":{"state":"hidden"},"cat":"toplevel","id2":{"local":"0x7fbbc001af20"},"name":"RendererVisibility","ph":"b","pid":31089,"scope":"toplevel","tid":775,"ts":16760681619},
{"args":{"state":"extension"},"cat":"toplevel","id2":{"local":"0x7fcec30194b8"},"name":"RendererProcessType","ph":"b","pid":31044,"scope":"toplevel","tid":775,"ts":16760681710},
{"args":{"state":"silent"},"cat":"toplevel","id2":{"local":"0x7fcec3019138"},"name":"RendererAudioState","ph":"b","pid":31044,"scope":"toplevel","tid":775,"ts":16760681714},
{"args":{"state":"renderer_foregrounded"},"cat":"toplevel","id2":{"local":"0x7fcec3018f78"},"name":"RendererPriority","ph":"b","pid":31044,"scope":"toplevel","tid":775,"ts":16760681717},

(so nestable begin and friends: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.puwqg050lyuy)

And we don't currently parse that at all for json traces:
https://github.com/google/perfetto/blob/master/src/trace_processor/importers/json/json_trace_parser.cc#L124

@betasheet Did I get that right and do you know if anyone is interested in adding support for that on the Chrome side? I think it should be reasonably easy to plumb in similar way to Android async events (e.g. https://github.com/google/perfetto/blob/master/src/trace_processor/importers/systrace/systrace_parser.cc#L163).

from perfetto.

Where is the proto format documented? We currently generate JSON files in our application, that we used to use the old Catapult viewer to display, but apparently that is deprecated and broken now, and from what you're saying Perfetto is never going to fully support the JSON format. I'm completely new to Perfetto, so I might be missing something very obvious, but so far I've been unable to find any documentation of what file format we should generate if we want Perfetto to be able to display it. Is there any kind of migration guide for the many applications that used to generate JSON expecting to use the Catapult viewer to display them?

from perfetto.

I wonder if this is a bug/missing feature in the Perfetto UI. It's possible this doesn't yet work for children of thread tracks. Does it work with children of process tracks? That is:

packet {
  timestamp: 0
  track_descriptor {
    uuid: 1000
    process {
      pid: 81351
      process_name: "example0"
    }
  }
}
packet {
  timestamp: 0
  track_descriptor {
    uuid: 1001
    parent_uuid: 1000
    name: "example0_async"
  }
}
packet {
  timestamp: 0
  track_descriptor {
    uuid: 1002
    parent_uuid: 1000
    name: "example0_async"
  }
}

from perfetto.

Thanks for narrowing this down @chromy 😄 I can confirm that my trace measurements (which were created with performance.measure()) are also described by events that have lowercase b and e phases.

If needed, I'm also happy to provide an example trace that reproduces this fairly minimally.

from perfetto.

We don't currently have plans to add support for importing JSON async trace events. It would probably be good but its pretty low level of priority for us currently.

If you are manually recording these traces you can get around this by either recording the trace through the perfetto UI (using the chrome extension select platform 'chrome') or through catapult by clicking the 'use protobuf' option (record -> edit categories -> use protobuf checkbox) in catapult UI.

This will generate a protobuf trace file (which the catapult UI can not directly load). But the NESTABLE_ASYNC slices will be visible in the Perfetto UI, and will also be exported when clicking Legacy UI and will then show up in the catapult UI as well.

If these are coming from benchmark runs then obviously can't do that and the only workaround would be adding json import support or directly using catapult. Importing is a bit tricky since you have to handle creating new tracks which nothing else in the json importer really needs to do since everything is thread tracks.

from perfetto.

Thanks @StephenNu. We record these traces using Chrome RDP through puppeteer. Unfortunately it does seem that the catapult trace viewer is the best option for this case right now. Is the intention that perfetto replace the catapult viewer?

from perfetto.

Yes the intention is for the perfetto UI to replace catapult viewer. However JSON support is sort of best effort and isn't a huge priority.

However if you could use proto format then I think these trace events would appear. I believe the remote DevTools protocal that puppeteer uses supports this. Could you try using StreamFormat and set it equal to 'proto'?

Then if you view this in the Perfetto UI the events should be visible, and if you go to the "legacy UI" to get a JSON trace again the events should also be there.

StreamFormat Reference: https://chromedevtools.github.io/devtools-protocol/tot/Tracing/#type-StreamFormat

from perfetto.

Where is the proto format documented?

https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit

But as said above, not all features are implemented. Chrome stopped used some of them and as such there is not support for them in the new UI, at least for now.

but apparently that is deprecated and broken now,

One thing that you need to understand is that the JSON format had a huge set of features. The spec doc itself is 19 pages and that doesn't even get close to cover all the various dialects and interpretations that people came up in the years (e.g. tid being a string rather than a number, tid being 0, "args" being a string rather than a dict and so on). People came up with all sort of variants which just happened to work because Catapult TraceViewer was written in Javascript (10y ago, without strict mode or TS) and JavaScript is the language where null == undefined but null !== undefined, ("" || 42) === 42 but ({} || 42) === {}, [1, 2, 3] + [4, 5, 6] === "1,2,34,5,6"

Saying "it's broken, what's expected to work?" it's a bit like saying "I have an HTML page which uses some HTML feature. Now it doesn't work anymore (Without ever saying what). What's expected to work?". Depends on what you are using and how, on a case by case basis.

The state of JSON parsing in Perfetto is the following:

• If something is obviously broken, it's very likely we'll fix it, depending on the impact and extent of the breakage (e.g. it was the case with some whitespace parsing or displayTimeUnit recently). A good bug with a trace which loads properly in chrome://tracing and doesn't in perfetto, with a clear description is the best way.
• For features (like object snapshots for instance), only the ones used by chrome are prioritized. The rest are done in a best-effort form. Like any other project out there, we must have priorities as well.

chrome://tracing has always been a tool for visualizing chrome traces and was never meant to be some universal reader for arbitrary JSON formats. Neither is Perfetto.

My suggestions here is:

• If you think something is broken, file a bug. we might or might not fix it depending on the actual bug.
• If you feel the TraceViewer in Catapult is what you really need, TraceViewer is open source. you are more than welcome to fork and maintain it.

Is there any kind of migration guide for the many applications that used to generate JSON expecting to use the Catapult viewer to display them?

There isn't and, as I explained above, the space is too wide.

from perfetto.

The proto format is documented in source code comments here: https://cs.android.com/android/platform/superproject/+/master:external/perfetto/protos/perfetto/trace/trace_packet.proto

There's also a source-code-generated reference here: https://perfetto.dev/docs/reference/trace-packet-proto

from perfetto.

I see, thanks for explaining.

A good bug with a trace which loads properly in chrome://tracing and doesn't in perfetto, with a clear description is the best way.

Sure. The thing that threw me off here is that the project seems a little bit schizophrenic. Both the old trace viewer and Perfetto seem to present themselves as open viewers that third parties are encouraged to use.
If I visit the Perfetto website It claims to be interoperable and it claims to support the JSON trace format (without any qualifications or conditions), so you can't really blame me for being surprised that apparently "we only support the parts of the file format that are needed by our own company".
As an outsider, I would have thought that "we don't render async events" would qualify as "something obviously broken", but of course if the JSON format is only kept around for Chrome it doesn't make sense to implement those. That caveat just isn't apparent unless you ask a question here and have to have a project developer spell it out.

Saying "it's broken, what's expected to work?" it's a bit like saying "I have an HTML page which uses some HTML feature. Now it doesn't work anymore (Without ever saying what)

True, but HTML has a specification, and browsers document if they choose not to implement parts of that specification.
That said, in a thread about async events not showing up, I thought the feature in question was implied. I'm sorry if that came across as me being unclear :))

Anyway, thanks for the explanation

from perfetto.

Both the old trace viewer and Perfetto seem to present themselves as open viewers that third parties are encouraged to use

Not sure where you got that. That is for sure a nice to have byproduct but has never been the goal of any of the two projects. The name itself (chrome://tracing) should give a strong strong hint.

If I visit the Perfetto website It claims to be interoperable and it claims to support the JSON trace format (without any qualifications or conditions)

Fair. Again this is not about "never going to support them". The real point is on the "when" and priorities. And as I explained we do prioritize features being used by the projects (Chrome/Android) that put efforts and resources in developing the tool (seems reasonable, no?).

so you can't really blame me for being surprised

I am not blaming anybody. i am just explaining the state of the affairs and how we realistically take decisions here.

"we only support the parts of the file format that are needed by our own company".

This is not about "our own company" or about vetoing features. A more fair and accurate statement is: "we (Perfetto) prioritize the parts of the file format and the features to view the traces written by project (Chrome and Android) that came up with the tracing tool in the first place and contributes to that".

Also remember, this is an open source project. If you find something that is very important for you and not a priority for the project the reasonable thing to do is:

• Start a quick discussion (either on GH or ML) and go "hey I care about this, I am planning to write a patch to do roughly X,Y,Z. Any objection / suggestion before I spend time?"
• Send a patch once the shape is agreed.

Most open source projects I came across work this way.

We don't have a team of people sitting down and waiting for feature request to arrive an implement them. It's a quite small set of people that is dealing with UI, trace ingestion, tracing libraries and general performance optimizations of Chrome and Android, which are quite large codebases with their own never-ending sets of surprises.

That caveat just isn't apparent unless you ask a question here and have to have a project developer spell it out.

I agree that docs could have pointed out better. But hey this is what mailing list / bugs are for.

As a final note, things are never clear cut. There has been a number of cases where we spend our personal time out of work hours (or weekends) to implement features that seemed nice-to-have for others, beyond any business goals.

But then, if I have to be fully honest, when I have some extra hours the very last thing I will think about is dealing with is requests of the form "I am new to this project, I was using the previous one (which is still around), it doesn't work for me, this project seems a little bit schizophrenic".

from perfetto.

Could you provide more guidance on how to implement this?

We have async events that are not nested. However, putting each slice (is that the right term? I mean a begin+end) into a separate track won't work for us. The current behavior of the legacy viewer is to stack slices as needed (generating tracks) but to sequence them into the same track where possible.

Are you willing to review and merge a patch if we write one?

from perfetto.

Happy to review patches adding support for JSON nestable async (phases b/e/n) slice ingestion. Please see perfetto.dev docs for contribution guidelines :)

With regards to merging non-nested slices into the same track: Perfetto UI already supports this for TrackEvents -- if there are multiple tracks (with different track IDs but) with the same name in the same scope (e.g. within the same process), these tracks are displayed in a merged visual track in the UI, very similar to what the catapult viewer does.

from perfetto.

Is it acceptable to generate one track per slice or is that going to be a performance problem? Would it be acceptable to start with support for non-nested async slices and add nesting support subsequently?

(Google CLA is signed, and I've already submitted some patches to AOSP.)

from perfetto.

@chromy ^

from perfetto.

With regards to merging non-nested slices into the same track: Perfetto UI already supports this for TrackEvents -- if there are multiple tracks (with different track IDs but) with the same name in the same scope (e.g. within the same process), these tracks are displayed in a merged visual track in the UI, very similar to what the catapult viewer does.

Sorry to do some necromancy on this thread but I tried to do so without any success. They are not merged in the same visual track:

Do you mind giving more information on how to achieve this merging? In this examples each slice (begin/end) have their own packed_sequence_id / sequence_flag. Please find below my trace_to_text output, and the c++ source code to generate it

Sorry if this is a dumb question, we are starting with perfecto. It's a really nice tool, thanks to you for making this Open Source!

packet {ng trace:        0 KB
  timestamp: 0
  sequence_flags: 1
  trace_packet_defaults {
    timestamp_clock_id: 6
    track_event_defaults {
      track_uuid: 17508407868897082924
    }
  }
  trusted_uid: 0
  trusted_packet_sequence_id: 2
  trusted_pid: 0
  previous_packet_dropped: true
}
packet {
  timestamp: 0
  sequence_flags: 2
  track_descriptor {
    uuid: 17508407868897082924
    thread {
      pid: 81351
      tid: 81351
      thread_name: "example0"
    }
  }
  trusted_uid: 0
  trusted_packet_sequence_id: 2
  trusted_pid: 0
}
packet {
  timestamp: 0
  sequence_flags: 3
  track_descriptor {
    uuid: 17508407868897082925
    thread {
      pid: 81351
      tid: 81351
      thread_name: "example0"
    }
  }
  trusted_uid: 0
  trusted_packet_sequence_id: 3
  trusted_pid: 0
}
packet {
  timestamp: 0
  sequence_flags: 2
  track_event {
    type: TYPE_SLICE_BEGIN
    name: "0:40"
  }
  trusted_uid: 0
  trusted_packet_sequence_id: 2
  trusted_pid: 0
}
packet {
  timestamp: 15
  sequence_flags: 3
  track_event {
    type: TYPE_SLICE_BEGIN
    name: "15:60"
  }
  trusted_uid: 0
  trusted_packet_sequence_id: 3
  trusted_pid: 0
}
packet {
  timestamp: 40
  sequence_flags: 2
  track_event {
    type: TYPE_SLICE_END
  }
  trusted_uid: 0
  trusted_packet_sequence_id: 2
  trusted_pid: 0
}
packet {
  timestamp: 60
  sequence_flags: 3
  track_event {
    type: TYPE_SLICE_END
  }
  trusted_uid: 0
  trusted_packet_sequence_id: 3
  trusted_pid: 0
}

#include <iostream>
#include <string>

#include "perfetto/ext/base/file_utils.h"
#include "perfetto/protozero/scattered_heap_buffer.h"
#include "protos/perfetto/common/builtin_clock.pbzero.h"
#include "protos/perfetto/trace/clock_snapshot.pbzero.h"
#include "protos/perfetto/trace/trace.pbzero.h"
#include "protos/perfetto/trace/trace_packet.pbzero.h"
#include "protos/perfetto/trace/trace_packet_defaults.pbzero.h"
#include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h"
#include "protos/perfetto/trace/track_event/thread_descriptor.pbzero.h"
#include "protos/perfetto/trace/track_event/track_descriptor.pbzero.h"
#include "protos/perfetto/trace/track_event/track_event.pbzero.h"

static void add_events(protozero::HeapBuffered<perfetto::protos::pbzero::Trace> &trace) {
  {
    auto *packet = trace->add_packet();
    packet->set_timestamp(0);
    packet->set_sequence_flags(1);
    auto *trace_packet_defaults = packet->set_trace_packet_defaults();
    // This change a lot of stuff
    trace_packet_defaults->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
    auto *track_event_defaults = trace_packet_defaults->set_track_event_defaults();
    track_event_defaults->set_track_uuid(17508407868897082924u);

    packet->set_trusted_uid(0);
    packet->set_trusted_packet_sequence_id(2);
    packet->set_trusted_pid(0);

    packet->set_previous_packet_dropped(true);
  }

  {
    auto *packet = trace->add_packet();
    packet->set_timestamp(0);
    packet->set_sequence_flags(2);
    auto *track_descriptor = packet->set_track_descriptor();
    track_descriptor->set_uuid(17508407868897082924u);
    auto *thread = track_descriptor->set_thread();
    thread->set_pid(81351);
    thread->set_tid(81351);
    thread->set_thread_name("example0");

    packet->set_trusted_uid(0);
    packet->set_trusted_packet_sequence_id(2);
    packet->set_trusted_pid(0);
  }

  {
    auto *packet = trace->add_packet();
    packet->set_timestamp(0);
    packet->set_sequence_flags(3);
    auto *track_descriptor = packet->set_track_descriptor();
    track_descriptor->set_uuid(17508407868897082925u);
    auto *thread = track_descriptor->set_thread();
    thread->set_pid(81351);
    thread->set_tid(81351);
    thread->set_thread_name("example0");

    packet->set_trusted_uid(0);
    packet->set_trusted_packet_sequence_id(3);
    packet->set_trusted_pid(0);
  }

  {
    auto *packet = trace->add_packet();
    packet->set_timestamp(0);
    packet->set_sequence_flags(2);
    auto *track_event = packet->set_track_event();
    track_event->set_type(perfetto::protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
    track_event->set_name("0:40");

    packet->set_trusted_uid(0);
    packet->set_trusted_packet_sequence_id(2);
    packet->set_trusted_pid(0);
  }

  {
    auto *packet = trace->add_packet();
    packet->set_timestamp(15);
    packet->set_sequence_flags(3);
    auto *track_event = packet->set_track_event();
    track_event->set_type(perfetto::protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
    track_event->set_name("15:60");

    packet->set_trusted_uid(0);
    packet->set_trusted_packet_sequence_id(3);
    packet->set_trusted_pid(0);
  }

  {
    auto *packet = trace->add_packet();
    packet->set_timestamp(40);
    packet->set_sequence_flags(2);
    auto *track_event = packet->set_track_event();
    track_event->set_type(perfetto::protos::pbzero::TrackEvent::TYPE_SLICE_END);

    packet->set_trusted_uid(0);
    packet->set_trusted_packet_sequence_id(2);
    packet->set_trusted_pid(0);
  }

  {
    auto *packet = trace->add_packet();
    packet->set_timestamp(60);
    packet->set_sequence_flags(3);
    auto *track_event = packet->set_track_event();
    track_event->set_type(perfetto::protos::pbzero::TrackEvent::TYPE_SLICE_END);

    packet->set_trusted_uid(0);
    packet->set_trusted_packet_sequence_id(3);
    packet->set_trusted_pid(0);
  }
}

static void WriteToFile(const std::string &out, const char *path) {
  PERFETTO_CHECK(!remove(path) || errno == ENOENT);
  auto out_fd = perfetto::base::OpenFile(path, O_RDWR | O_CREAT, 0666);
  if (!out_fd || perfetto::base::WriteAll(out_fd.get(), out.data(), out.size()) !=
                     static_cast<ssize_t>(out.size())) {
    PERFETTO_FATAL("WriteToFile");
  }
}

int main(int argc, const char **argv) {
  (void)argc;
  const char *out_path = argv[1];
  protozero::HeapBuffered<perfetto::protos::pbzero::Trace> trace;
  add_events(trace);
  std::string raw_out = trace.SerializeAsString();
  WriteToFile(raw_out, out_path);
  return 0;
}

Thanks!

from perfetto.

IIRC this merging only happens for child tracks of process or thread tracks (a thread track itself is always assumed to contain synchronous events and thus we don't attempt to merge the track) - if you want to achieve this for tracks that have a thread association as in your example, try track descriptors similar to this:

packet {
  timestamp: 0
  track_descriptor {
    uuid: 1000
    thread {
      pid: 81351
      tid: 81351
      thread_name: "example0"
    }
  }
}
packet {
  timestamp: 0
  track_descriptor {
    uuid: 1001
    parent_uuid: 1000
    name: "example0_async"
  }
}
packet {
  timestamp: 0
  track_descriptor {
    uuid: 1002
    parent_uuid: 1000
    name: "example0_async"
  }
}

from perfetto.

Thanks a lot for the quick reply, Highly appreciated!

We tried using child tracks, without any luck. The display is the same as before.

Please find the trace to text bellow:

packet {ng trace:        0 KB
  timestamp: 0
  trace_packet_defaults {
    timestamp_clock_id: 6
    track_event_defaults {
      track_uuid: 1000
    }
  }
  trusted_packet_sequence_id: 10
  previous_packet_dropped: true
}
packet {
  timestamp: 0
  track_descriptor {
    uuid: 1000
    thread {
      pid: 81351
      tid: 81351
      thread_name: "example0"
    }
  }
  trusted_packet_sequence_id: 10
}
packet {
  timestamp: 0
  track_descriptor {
    uuid: 1001
    parent_uuid: 1000
    name: "example0_async"
  }
  trusted_packet_sequence_id: 10
}
packet {
  timestamp: 0
  track_descriptor {
    uuid: 1002
    parent_uuid: 1000
    name: "example0_async"
  }
  trusted_packet_sequence_id: 10
}
packet {
  timestamp: 0
  track_event {
    type: TYPE_SLICE_BEGIN
    name: "0:40"
    track_uuid: 1001
  }
  trusted_packet_sequence_id: 10
}
packet {
  timestamp: 15
  track_event {
    type: TYPE_SLICE_BEGIN
    name: "15:60"
    track_uuid: 1002
  }
  trusted_packet_sequence_id: 10
}
packet {
  timestamp: 40
  track_event {
    type: TYPE_SLICE_END
    track_uuid: 1001
  }
  trusted_packet_sequence_id: 10
}
packet {
  timestamp: 60
  track_event {
    type: TYPE_SLICE_END
    track_uuid: 1002
  }
  trusted_packet_sequence_id: 10
}

We used set_track_uuid and set_trusted_packet_sequence_id to map track events to their tracks, but we are not sure if it's the way to do it. Maybe this is the issue?

Thanks a lot!

from perfetto.

Not quite sure how one is supposed to report non-nested tracks like our gpu timings. We have a start and end time, but they are not nested. The async events at least provided a begin/end that could then be shown in a list. These seem to show up as individual tracks in Catapult, but would like to know a workaround for Perfetto. We won't be going back to Catapult, and nested tracks don't work for this. The gpu returns these timings with differing overlaps depending on parallel units. AGI seems to be able to show these tracks and uses Perfetto, so we'd like to know how that works.

Will look into moving off a thread track to a process track in hopes that it consolidates these. Catapult shows these as expected. Tried this, but still nothing shows up.

from perfetto.

Does it work with children of process tracks?

That's worked!

It's a little "sad" that I will not be able to merge multiple threads in the same process, but I can live with that. I will use many "virtual" processes (1 per GPU queue, and -at most- one child track per kernel. We are also using Perfetto to plot GPU activity as @alecazam :) ) and call it a day.

Do you want me to open a new issue for the non-tested threads tracks ?

Thanks again for your help!

PS: On a side note, look like the "color algorithm" doesn't distinguish between numeric names, but this is maybe a feature :)

from perfetto.

I'm trying to just write to the Catapult Json spec. I assume that you need to use some Perfetto specific json to achieve what you did. I tried defining a process name and referencing that from the async events. But they only show up in Catapult. I assume the packet notation and parent/child uuid mentioned above?

from perfetto.

Perfetto specific json

My understanding is that the JSON format doesn't support non-nested event. I now generate directly the protobuf format. See the source code bullet point in my previous comment for an example of how to generate the protobuf.

from perfetto.

The Catapult format totally supports and displays non-nested async events. These show up just how the gpu executed them, but a track per line. It's just that Perfetto doesn't import it.

I tried fabricating a Catapult process per gpu timeline, but that doesn't display a name, and looks like low-res ascii art. So I'll just have to fake Catapult threads per gpu timeline (correlate them by name, so they all appear on the same lines), and use that for now. So process 0 is cpu, and process 1 is gpu.

Vertical space using Perfetto is severely limiting. No split panes, and eventually starring tracks just exhausts the vertical real-estate. It's like the devs are using portrait monitors with this.

from perfetto.

That's worked!

Thanks for verifying!

Do you want me to open a new issue for the non-tested threads tracks ?

This is definitely something we should address, yes. Traces written by the SDK (e.g. Chrome traces) will encounter the same issue, although I think few people currently use thread-associated async tracks. Filed #321.

from perfetto.

This has been fixed now.

from perfetto.