Perfetto displays existing .trace timings as seconds instead of milliseconds

[alecazam]

Jumping to the "Legacy UI" displays our trace files correctly as millseconds. This is a showstopper bug for us trying to switch off the old tracing API. I didn't see any preference to set this in the app, but maybe there's a config file.

[primiano]

This bug is extremely unactionable.
Can you attach a trace and explain what's the different behavior you see and what's unexpected.

Saying "the legacy UI displays correctly, this is a showstopper for us" doesn't help neither us to fix the bug, if there is one, nor any future person that stumbles on this bug.

[alecazam]

Here's part of a trace. I didn't add this profiler, but it's currently based on TraceViewer. But I've dropped this same trace file onto Speedscope, TraceViewer, and Catapult, and they all interpret this properly. The "Legacy UI" of Perfetto appears to be Catapult, so when I switch to that, the data is displayed correct.

Perfetto seems to interpret the micoroseconds of this trace "dur": 3183.3149 as milliseconds. But I don't think that's how these trace files are supposed to be intrepreted. I'm only looking into this json for the first time, and thought the file would be some unreadable and packed binary file. I think these values are always saved to a .trace file as microseconds, and then specify to display them as milliseconds as per the "displayTimeUnit": "ms".

This is 3183 microseconds. Which is 3.183ms. Seeing this displayed in seconds at the top fo the Perfetto timline is just wrong and hence a showstopper for us using this tool on our trace files. The other profilers interpret the trace correctly.

{
    "traceEvents":
    [
{
            "name": "FrameStart",
            "ph": "i",
            "pid": 0,
            "tid": 0,
            "ts": 0,
            "s": "g"
        },
        {
            "name": "ModuleBarn::Update",
            "ph": "X",
            "pid": 0,
            "tid": 0,
            "ts": 7.9970341,
            "dur": 3183.3149
        },
        {
            "name": "FrameEnd",
            "ph": "i",
            "pid": 0,
            "tid": 0,
            "ts": 39651.195,
            "s": "g"
        }
],
    "displayTimeUnit": "ms"
}

[chromy]

Same root cause as item 2 in #106 (comment) specifically:

trace_processor uses displayTimeUnit: UNIT to mean "ts is recorded in UNITs" which is not what catapult implements or what the specification says.

We initially landed support for displayTimeUnit for an internal client, based on how they thought it worked and at the time I didn't spend enough time looking at the spec and checking what catapult actually did before implementing this. As you mentioned in catapult displayTimeUnit doesn't affect the parsing of the file.

We should ask the internal client to switch away from using displayTimeUnit and then (after some time for old traces to expire) fix displayTimeUnit parsing in trace_processor.

alecazam@ as a work around it is possible to strip displayTimeUnit from the .json file, this should cause the timestamps to be correct in all tools (although they will be formatted as us not ms in catapult).

You also mentioned you did not implement the profiler that emitted this trace. If it is not an internal tool would you mind sharing which profiler it was? I would be interested in reaching out to the maintainers.

Cheers!

[alecazam]

I have no idea just how old our copy is, but we seem to be using https://pypi.org/project/trace2html/. I think there might be a newer one or similar one incoporated into Catapult? And we don't want to look at these in microseconds since they're from our game, so I can't share the full capture. We work in milliseconds exclusively.

I'm just looking for a better profiling tool than the old TraceViewer that we currently use. A colleague from Figma wrote speedscope and I really like it's analysis, but we need to look across threads and across many frames. And it's fast using WebGL. So in profiles, the bars are often too short for names (hence the hover request), and I need to see a lot of timings going up/down the flamechart.

[alecazam]

It looks like our engine is adding that displayTimeUnit, so it could be removed. But this gets back to needing to view the content in milliseconds, and not having any preference or control for that in Perfetto that I found. It sounds like Perfetto is unique in it's intepretation of displayTimeUnit, so it would be good to make that consistent with all the other perf tools.

[alecazam]

As I'd reported, we really just need to look at timings everywhere in milliseconds. That means about 2-3 digits of precision after the milliseconds. But I don't want to read timings in seconds or nanonseconds throughout the profiler. I need to see them all formatted the same, so I don't misread 21.234 s or 21.234 ns as 21.234 ms. I followed the issue link that you sent, but there didn't seem to be an alternative that I can write out to replace displayTimeUnit if only going to Perfetto, but that's quite limiting. I wanted our devs to have a choice of profiler, so having Perfetto inconsistent is problematic for adoption.

Can't this be a preference or argument (f.e. honor displayTimeUnit)? Or allow me to put whatever setting Perfetto needs in the Json, and when it finds that it ignores displayTimeUnit. I'm assuming the old tracers can handle the new Perfetto setting without complaint and ignore it.

[sam-mccall]

Clangd's traces are affected by this too. Display unit is ns and ts/dur are in us per the spec.

These displayed correctly in catapult but are sped up by a factor of 1000 in perfetto.

FWIW the main reason we set displayTimeUnit is that it increases the granularity of internal arithmetic in catapult, avoiding glitches.

Our generator is https://github.com/llvm/llvm-project/blob/7e92b759ed69ef3732b4341e8588ae07085d5f90/clang-tools-extra/clangd/support/Trace.cpp#L38

I can provide a sample trace if it's useful, it sounds like you understand the issue perfectly though.

[primiano]

@chromy

[DDoSolitary]

Is it possible add switch to disable this behavior if you want to keep the old behavior for that internal client?

[chromy]

The internal client has moved to generating the proto format so we can now fix this 😊 I have sent a change here: https://android-review.googlesource.com/c/platform/external/perfetto/+/1888768 I hope that keeping the a switch for the incorrect behavior will not be necessary.

Once that change lands and has been released I will update the issue.

[studgeek]

@alecazam, I filed #206 for the request to show duration in a single unit like catapult did. I also would really like to see that option.