1723817 - The Socket Thread is blocked on net::nsHttpActivityDistributor::ObserveActivityWithArgs running quickly in the main thread

Status: NEW

(Core :: Networking: HTTP, defect, P2)

Description

[Florian Quèze [:florian]]

See this profile where the Socket Thread activity drops to 0 when the main thread is janky (due to opening the download dialog) : https://share.firefox.dev/3xkeiPx

In the main thread, there are lots of net::nsHttpActivityDistributor::ObserveActivityWithArgs runnables.

Note: on the Socket Thread, this profile includes markers from the patch up for review in bug 1723813.

Steps to reproduce this profile:

1. Open Nightly.
2. Load http://test-debit.free.fr/
3. Start the profiler (ensure the Socket Thread will be recorded)
4. Click on one of the large files.
5. After a few seconds, press Escape to cancel the download.
6. Capture the profile.

Comment 1

[Florian Quèze [:florian]]

Looking at the profile some more, we also have nsPipeInputStream::AsyncWait runnables on the main thread, so I'm not sure which of nsPipeInputStream::AsyncWait and net::nsHttpActivityDistributor::ObserveActivityWithArgs is blocking the socket thread.

Comment 2

[Florian Quèze [:florian]]

Looking at the profile even more, https://share.firefox.dev/3lozBxf the mozilla::net::nsHttpActivityDistributor::ObserveActivityWithArgs call path is calling mach_msg_trap, so I think my first guess was correct.

Comment 3

[Valentin Gosu [:valentin] (he/him)]

I wouldn't expect calling NS_DispatchToMainThread to actually block the thread - which is what I understand is hapening here.
The codepath was added in bug 1606706. I assume this is the reason why it caused some performance regressions (if MT is busier, it makes other threads slower too).
I don't know very well how the TaskController is supposed to work, so I'm moving this to Core:XPCOM

Comment 4

[Florian Quèze [:florian]]

(In reply to Valentin Gosu [:valentin] (he/him) from comment #3)

I wouldn't expect calling NS_DispatchToMainThread to actually block the thread - which is what I understand is hapening here.

The Socket Thread isn't blocked, it's still polling, but the "Poll count" in the markers is 8 instead of 9, https://share.firefox.dev/2VeUrog

Comment 5

[Bas Schouten (:bas.schouten)]

Yeah, I don't see any indication this is blocking in dispatching a task? Why do you believe this is the case?

Comment 6

[Valentin Gosu [:valentin] (he/him)]

(In reply to Bas Schouten (:bas.schouten) from comment #5)

Yeah, I don't see any indication this is blocking in dispatching a task? Why do you believe this is the case?

This was my interpretation of comment 2:

Looking at the profile even more, https://share.firefox.dev/3lozBxf the mozilla::net::nsHttpActivityDistributor::ObserveActivityWithArgs call path is calling mach_msg_trap, so I think my first guess was correct.

ObserveActivityWithArgs -> DispatchRunnable -> MaybeInterruptTask -> EnsureMainThreadTaskScheduled -> ScheduleNativeEventCallback -> mach_msg_trap

My reading of the comment This will invoke ProcessGeckoEvents on the main thread. was to mean that it would wait for the invocation to happen.

Florian, did I misunderstand the issue here?

Comment 7

[Florian Quèze [:florian]]

(In reply to Valentin Gosu [:valentin] (he/him) from comment #6)

Florian, did I misunderstand the issue here?

Maybe the word "block" in the bug summary was confusing.

What I saw in the profile is:

• we use a lot of (almost 100%) CPU in the Socket Thread, except when the main thread is busy.
• during the time when the main thread is busy and when the Socket Thread is using 0% CPU (there's a longer Poll marker), the Poll count (in the marker tooltip) is 1 less than when the Poll markers are short and frequent.

So based on this I was under the impression that the download doesn't make progress while the main thread is unresponsive. Is this a correct guess?

Comment 8

[Kershaw Chang [:kershaw]]

FWIW, I think nsIHttpActivityObserver should only be used for devtools.
In our current code, an observer is always added at startup here, so there are a lot of activity events need to be dispatched from socket thread to main thread. I'll file another bug and see if we can somehow mitigate this.

Comment 9

[Nika Layzell [:nika] (ni? for response)]

Moving this back to networking, as this isn't an xpcom problem.

Comment 10

[Sunil Mayya]

Hello Florian,

I tried to reproduce this issue on the latest nightly.
I did not see the main thread becoming janky

Were you able to reproduce this on the latest nightly?

Thanks

Comment 11

[Florian Quèze [:florian]]

(In reply to Sunil Mayya from comment #10)

Hello Florian,

I tried to reproduce this issue on the latest nightly.
I did not see the main thread becoming janky

The popup asking me to save the file or cancel the download no longer seems to exist, now we start downloading to the downloads folder, so that jank isn't there anymore.

Were you able to reproduce this on the latest nightly?

Yes, I just created artificial jank from the devtools console (running var start = Date.now(); while (Date.now() < start + 1000);) on a page loaded in the parent process (eg. about:about). Here is a profile on a recent mozilla-central build: https://share.firefox.dev/3YkWpPC

Comment 12

[Florian Quèze [:florian]]

(In reply to Florian Quèze [:florian] from comment #11)

Here is a profile on a recent mozilla-central build: https://share.firefox.dev/3YkWpPC

Note: the CPU use on the Socket thread is less visible in this new profile, I think that's because I profiled today on an M1 Macbook Pro, and bug 1709175 seems to affect mostly Intel macs. The bug is still visible when looking at the SocketTransportService::Poll markers on the Socket thread.

Comment 13

[Florian Quèze [:florian]]

(In reply to Florian Quèze [:florian] from comment #7)

So based on this I was under the impression that the download doesn't make progress while the main thread is unresponsive. Is this a correct guess?

I verified this impression: when I generate artificial 10s jank on the parent process main thread, the network traffic drops to almost zero in the OS X Activity Monitor.