1903975 - Waiting for socket thread takes 3 s

Status: UNCONFIRMED

(Core :: Networking, defect, P2)

Description

[Paul Menzel]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:129.0) Gecko/20100101 Firefox/129.0

Steps to reproduce:

Maybe related to bug 1891431 1

Load https://init-events.molgen.mpg.de

Actual results:

It took a long time.

Expected results:

The network transfers should be faster.

Profile: https://share.firefox.dev/45xJ2zi

Comment 1

[Paul Menzel]

Attachment: Output of `about:support`

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

The Bugbug bot thinks this bug should belong to the 'Core::Networking' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Comment 3

[Randell Jesup [:jesup] (needinfo me)]

Can you tell us more about the connection you experienced this on? Speed, latency? VPN? The loads of resources seem to take a really long time; a local test with a 50Mbps link showed all the resources before the woff files loaded in parallel, and took only ~300ms. Do you see similar behavior in Chrome?

Note that "Waiting for socket thread" in a profile is a bit misleading, in that the reasons for the delay may have nothing to do with the socket thread being busy.

Can you use about:logging to take a networking trace?

Thanks!

Comment 4

[Wayne Mery (:wsmwk)]

Paul?

Comment 5

[Paul Menzel]

Attachment: HAR file from Firefox Nightly 131.0a1~20240809095159

Can you tell us more about the connection you experienced this on? Speed, latency? VPN? The loads of resources seem to take a really long time; a local test with a 50Mbps link showed all the resources before the woff files loaded in parallel, and took only ~300ms.

It’s a 100 MBit/s Vodafone cable connection, and on the terminal it’s really quick:

$ date; curl -s -w '\nLookup time:\t%{time_namelookup}\nConnect time:\t%{time_connect}\nAppCon time:\t%{time_appconnect}\nRedirect time:\t%{time_redirect}\nPreXfer time:\t%{time_pretransfer}\nStartXfer time:\t%{time_starttransfer}\n\nTotal time:\t%{time_total}\n' -o /dev/null https://init-events.molgen.mpg.de/
Fr 9. Aug 19:57:24 CEST 2024

Lookup time:        0.021047
Connect time:       0.032747
AppCon time:        0.122442
Redirect time:      0.000000
PreXfer time:       0.122602
StartXfer time:     0.237425

Total time: 0.250506

Latency is quite low as the internet exchange BCIX is used (ICMP blocked for init-events, but bigbluebutton is connected the same way):

$ ping -c10 bigbluebutton.molgen.mpg.de
[…]
--- bigbluebutton.molgen.mpg.de ping statistics ---
10 packets transmitted, 10 received, 0% packet loss, time 9013ms
rtt min/avg/max/mdev = 12.797/14.379/17.105/1.420 ms

Without profiling it takes around three seconds. The HAR is attached.

Do you see similar behavior in Chrome?

It also takes around three seconds. I am going to attach the HAR.

Can you use about:logging to take a networking trace?

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

This time it was really, really slow when profiling. Any ideas?

Comment 6

[Paul Menzel]

Attachment: HAR file from *chromium* 127.0.6533.99-1 with `--temp-profile`

Compressed with:

7z a -t7z -m0=lzma -mx=9 -mfb=64 -md=32m -ms=on 20240809--chromium-127.0.6533.99-1--init-events.molgen.mpg.de.har.7z 20240809--chromium-127.0.6533.99-1--init-events.molgen.mpg.de.har

Comment 7

[edgul]

Kind of looks like a privileged content process is blocking the connection. Kershaw, any thoughts?

Comment 8

[Kershaw Chang [:kershaw]]

The profiler shows that the socket thread is busy with dumping raw data.
I think we should fix this first before investigating the real performance issue.

Comment 9

[Wayne Mery (:wsmwk)]

Paul do you still see this?

I don't see a delay with 135.0 (aarch64) on Mac