1814990 - Structured clone reading spending too much time in telemetry code in this instance

Status: NEW

(Core :: JavaScript Engine, defect, P2)

Description

[Markus Stange [:mstange]]

Profile: https://share.firefox.dev/3jt66vA

I had a background tab with Google Maps which somehow got stuck in a loop of DOM message events. In the profile, I noticed that a large part of JS_ReadStructuredClone was spent inside telemetry code and capturing timestamps. There's not much time in this function overall, so it might not be a problem; it's just the ratio of useful work in this particular function that stood out to me.

Comment 1

[Steve Fink [:sfink] [:s:]]

Ouch, that does look kind of awful. Ted, you looked at the Telemetry stuff when streamlining the API from SM. (Which is not the problem here; all the time is in the underlying telemetry code.) How high overhead is it expected to be? I assumed it was cheap. If it's as expensive as this example makes it look like, then I'm inclined to just drop this telemetry. It hasn't produced any actionable insights, and there are performance problems associated with structured clone that have been showing up. If telemetry is not showing them, then it's probably the wrong mechanism.

(It might be fixable—the 95th percentile of DESERIALIZE_US is 72µs, which is nothing. The 99.9th percentile is 5ms, which is significant. So maybe I should be ignoring all of the small ones or something? Or maybe I should just have more respect for the current setup, and work on reducing the 99.9th percentile?)

Comment 2

[Steve Fink [:sfink] [:s:]]

Oh and Markus, any idea why mach_absolute_time is so slow? It's claiming 49ms there, which seems... excessive.

Comment 3

[Jan de Mooij [:jandem]]

(In reply to Steve Fink [:sfink] [:s:] from comment #1)

If it's as expensive as this example makes it look like, then I'm inclined to just drop this telemetry. It hasn't produced any actionable insights, and there are performance problems associated with structured clone that have been showing up. If telemetry is not showing them, then it's probably the wrong mechanism.

For what it's worth, bug 1812055 improved the deserialize_us 95th percentile from 72 to 60, so I found it useful to confirm an improvement. If it's hurting performance we shouldn't keep it just for that though.

Comment 4

[Markus Stange [:mstange]]

(In reply to Steve Fink [:sfink] [:s:] from comment #2)

Oh and Markus, any idea why mach_absolute_time is so slow? It's claiming 49ms there, which seems... excessive.

It's a bit misleading. It's 48 samples over many different calls to mach_absolute_time across a timespan of 7.4 seconds.