VSync markers are present twice in the marker list

padenot commented 4 years ago

This profile https://perfht.ml/3afJtQF has all VsyncTimestamp markers twice in the marker table on the compositor threads.

This is on macOS if that matters, from a Nightly build

┆Issue is synchronized with this Jira Task

padenot commented 4 years ago

Adding a printf like so: https://gist.github.com/padenot/d1fea85852a89f12aa37f9c340cf325c shows that the event is inserted once on the Gecko side.

julienw commented 4 years ago

The 2 markers are present in the profile. So I believe there's a problem somewhere in the serialization...

squelart commented 4 years ago

I could reproduce the issue on Nightly/Windows, by doing a "regular" profiling session (start&stop through the popup). In fact it was worse, with each VsyncTimestamps present up to 5 times! https://perfht.ml/3eAIQVf

Doing a MOZ_PROFILER_SHUTDOWN profile, the output seemed fine (no duplicates), confirming what @padenot saw with his printfs. And that's all the serialization that happens in Firefox. From here, the json is transferred to profiler.firefox.com for processing and beautiful display...

A clue maybe: Shutdown profiling only saves data from the main process (we've got bugz about this), and when I drop that file into profiler.firefox.com, there are no duplicates. But a "real" profiling session would gather profiles from all processes, and send the lot to profiler.firefox.com... So my guess would be that either the gathering work in Firefox creates the duplication (though I doubt it, as sub-profiles are pretty much just pasted as text into json placeholders), or the processing on the website may grab VsyncTimestamps from all processes?

@julienw , would you be able to intercept the Gecko profile json sent to the website, and see what's in there before and after processing?

firefox-devtools / profiler

VSync markers are present twice in the marker list #2502