Negative duration in "Waiting for socket thread" on fenix

[mcomella]

I don't know if this would reproduce consistently but I created this profile by:

• Open fenix on an existing tab
• Click URL bar
• Type "am"
• Start profile
• Hit enter to autocomplete "amazon.com"
• Capture profile when page load completes

https://share.firefox.dev/3uWzZ96

┆Issue is synchronized with this Jira Task

[julienw]

Interesting!

I think this is because we assume this is a sequence of events, where in the real life some operations happen in parallel. I believe that in this case the DNS request was successful 4ms before the socket thread was ready. (TBH I didn't know that the DNS request happened before the socket thread was present, but this makes sense).

For now we consider that this tooltip is an approximation of what happens, but we should probably at least detect such cases...

[julienw]

if you have an example of a profile with this problem that you can share, that can help a lot!

[mstange]

We're probably doing speculative DNS pre-resolution here, that's why it begins before the request is initiated. I wouldn't put too much trust in the "waiting for socket thread" description here.

[mcomella]

Another thing that is happening is that the request is blocking on the Android UI thread to be free. This is because, for whatever reason, in GeckoView the request needs to use the UI thread and some requests need to be handled UI thread -> Gecko thread -> UI thread, which causes them to be blocked on a UI transition. Here's the bug to improve perf by handling it synchronously: https://bugzilla.mozilla.org/show_bug.cgi?id=1734916

In the mean time, this shows up in the profiler as a "Waiting for socket thread" duration.

if you have an example of a profile with this problem that you can share, that can help a lot!

There is one at the bottom of the first comment (I can see why it might be easy to miss).