1652083 - Slower than expected load of cnn.com

Status: RESOLVED DUPLICATE of bug 1392272

(Core :: Networking, defect, P3)

Description

[Asif Youssuff]

From https://www.reddit.com/r/firefox/comments/hhnbe3/firefox_started_behaving_much_slower_ever_after_a/

Basic information

Steps to Reproduce:

1. Go to cnn.com

Expected Results:

Firefox takes 2x as long as Chrome.

Actual Results:

At least as quick as Chrome on the same hardware.

---

More information

Profile URL: https://share.firefox.dev/3iOfeWs

Basic systems configuration:

OS version: Microsoft Windows 10 Pro 10.0.18363 N/A Build 18363

GPU model: NVIDIA GeForce GTX 970

Number of cores: 4

Amount of memory (RAM): 16GB

Thanks so much for your help.

Comment 1

[Asif Youssuff]

Attachment: about:support

Comment 2

[Markus Stange [:mstange]]

Tons of time spent in "waiting for socket thread", like 3 to 18 seconds. (See also bug 1618687.)

We'll probably need an HTTP log to track down the cause of this. Instructions are here: https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging

Asif, could you ask the reporter to attach an HTTP log here?

Comment 3

[Pasha]

Attachment: firefox logs.7z

Comment 4

[Pasha]

Reporter here. The generated log file is 213MB. I zipped it up and attached it here. Hopefully the 7z format is OK.

Comment 5

[Markus Stange [:mstange]]

Perfect, thanks!

Honza, could you take a look, or find somebody who can?

Comment 6

[Honza Bambas (:mayhemer)]

I don't think I'll be able to read anything out of the log on its own, but I'll take a look; cnn is a very complex website. I'll ask something else, tho.

Pasha: can you please flip network.preload to false in about:config and check if cnn then loads significantly faster?

If so, then I'll ask you to capture two consecutive logs reloading the same cnn page, one with preload off, and one with preload on. Thank you.

Comment 7

[Honza Bambas (:mayhemer)]

Hmm... if I understand correctly, this is on Firefox Release, 78, right? If so, then this has nothing to do with preload (it's disabled by default). Disregard previous comment if so.

Comment 8

[Markus Stange [:mstange]]

I see 6 seconds of proxy resolution for the request to https://cdn.cnn.com/cnnnext/dam/assets/200710153908-hp-only-20200710-ca-tx-fl-covid-cases-hp-large-tease.png, I think.

Comment 9

[Markus Stange [:mstange]]

Are you using a proxy server? Do you need to? Is it possible that the proxy server is slow?

I'm not experienced at reading HTTP logs but proxy resolution seems to be implicated as a slow factor.

Comment 10

[Honza Bambas (:mayhemer)]

There is no proxy involved. Those are scripts (addons) or something else long-blocking the main thread of the parent process. That blocks everything.
MOZ_LOG=events has not reached the release channel yet (is on beta now). Only option I see now is to enable logging in the profiler and upload a new profile. But it will be some digging to figure out what is the source of blocking anyway. I personally bet on some addon. Pasha, can you try disabling one by one and isolate the one that may be causing it?

Comment 11

[Pasha]

I did a full browser refresh, so I don't have any addons installed anymore. Still have the same problems.
It's happening on every single site for me, so is there a better place I can generate the logs from?

Comment 12

[Honza Bambas (:mayhemer)]

Pasha, can you please install Firefox Nightly and add events:1 to the list of log modules? It would be better to start logs from the command line. Nightly will create a new profile, but after you've made the browser restart, that won't matter. Thanks.

Comment 13

[Pasha]

Honza, this is the command I used, and I am attaching cnn_logs_firefox_nightly.zip here

"C:\Program Files\Firefox Nightly\firefox.exe" -MOZ_LOG=timestamp,rotate:200,nsHttp:5,cache2:5,nsSocketTransport:5,nsHostResolver:5,cookie:5,events:1 -MOZ_LOG_FILE=%TEMP%\cnn_logs.txt

I

Comment 14

[Pasha]

Attachment: cnn_logs_firefox_nightly.7z

Comment 15

[Markus Stange [:mstange]]

(In reply to Honza Bambas (:mayhemer) from comment #10)

There is no proxy involved.

I was looking at log lines that included "000002F1BEA0C000", the channel for the URL I posted. And then I saw a 6 second gap between those two lines, both mentioning proxy:

2020-07-10 20:28:14.848000 UTC - [Parent 1220: Main Thread]: D/nsHttp nsHttpChannel::ResolveProxy [this=000002F1BEA0C000]
[...]
2020-07-10 20:28:20.356000 UTC - [Parent 1220: Main Thread]: D/nsHttp nsHttpChannel::OnProxyAvailable [this=000002F1BEA0C000 pi=0000000000000000 status=0 mStatus=0]

Comment 16

[Honza Bambas (:mayhemer)]

(In reply to Pasha from comment #13)

Honza, this is the command I used, and I am attaching cnn_logs_firefox_nightly.zip here

"C:\Program Files\Firefox Nightly\firefox.exe" -MOZ_LOG=timestamp,rotate:200,nsHttp:5,cache2:5,nsSocketTransport:5,nsHostResolver:5,cookie:5,events:1 -MOZ_LOG_FILE=%TEMP%\cnn_logs.txt

I

Thank you very much, but we are blocked by bug 1651068 to get the proper logs. I pushed on review and landed that patch now. It will be in tomorrow Nightly, hopefully. I will let you know when, then just let Nightly autoupdate and run again the logging. Thanks.

Comment 17

[Honza Bambas (:mayhemer)]

(In reply to Markus Stange [:mstange] from comment #15)
pi=0000000000000000 - no proxy. The resolution is very likely blocked by something happening on the main thread. Need logging of the recently enabled TaskController tasks to see if this is delayed by main thread and how long the blocking tasks are.

Comment 18

[Markus Stange [:mstange]]

Ah, thanks.

Comment 19

[Honza Bambas (:mayhemer)]

Could be related to bug 1641696

Comment 20

[Honza Bambas (:mayhemer)]

Pasha, bug 1651068 has landed. Please update to the latest Nightly and capture a log again. Thanks.

Comment 21

[Pasha]

Attachment: cnn_logs_2020.07.16.7z.001

Comment 22

[Pasha]

Attachment: cnn_logs_2020.07.16.7z.002

Comment 23

[Pasha]

Attached cnn_logs_2020.07.16.7z.001 and cnn_logs_2020.07.16.7z.002.
Sorry about breaking it up, but it looks like I can't upload files more than 10MBs
Is there a better way to share larger files?

Comment 24

[Honza Bambas (:mayhemer)]

(In reply to Pasha from comment #23)

Attached cnn_logs_2020.07.16.7z.001 and cnn_logs_2020.07.16.7z.002.
Sorry about breaking it up, but it looks like I can't upload files more than 10MBs
Is there a better way to share larger files?

I'll merge them, thanks! https://send.firefox.com/ ?

Comment 25

[Honza Bambas (:mayhemer)]

So for this particular bug it IS the proxy resolution that slows things down, quite unexpected under default configuration. Pasha, I will ask you for one more log with added proxy:5 module to the list. Thanks!

Comment 26

[Pasha]

Attachment: cnn_logs_2.7z

Comment 27

[Pasha]

Honza, let me know if the file contains the right info.

Comment 28

[Markus Stange [:mstange]]

Hmm, I think the logs are missing the "beginning" of the parent process. For example, I can see a request at 22:40:21 in cnn_logs_2.txt.child-5.moz_log.0, but the first log from the parent process, cnn_logs_2.txt.moz_log.0, only starts at 22:40:51.

Comment 29

[Honza Bambas (:mayhemer)]

Apparently, the system resolves the proxy at least 110ms, for each request, here, called from here through this called from here.

Assuming you are on windows, this method is cause of the delay.

Are there any special settings in your system regarding proxy? Any VPN or AV software, anything special that could make your system slow down like this?

The workaround is to switch to "No proxy" in about:preferences --> Network settings.

I'm strongly persuaded this not a Firefox bug.

The next step is to enable the ProxyResolution thread in the profiler and capture a profile. If the symbolication is going to work for system functions, we may check where we get stuck.

Comment 30

[Pasha]

Honza, disabling the proxy setting in firefox actually loaded CNN in a reasonable time. However, I don't have any proxy enabled on windows.
If this was a system wide setting, wouldn't this impact all the browsers? Edge and Chrome don't have this issue.

Comment 31

[Markus Stange [:mstange]]

Pasha, if you get a Firefox profiler profile with the ProxyResolution thread (use the Custom preset and go to "Edit Settings..."), the information from it might let us answer that question more easily.

Comment 32

[Pasha]

Markus, here are profiles from nightly with the ProxyResolution added (I hope I did it correctly)
This one has "Use system proxy settings" https://share.firefox.dev/3jgzW1h
This one has "No proxy" https://share.firefox.dev/398nigm

Comment 33

[Markus Stange [:mstange]]

Perfect, thanks!

So yes, each call to ReadInternetOption seems to take 55ms, and we seem to do two of them per URL.
There is a surprising amount of InitOnceExecuteOnce calls on the thread that decidedly do not execute just once... but every time. WININET.dll is re-initializing two structures over and over again.

Naively, it seems that caching the result of ReadInternetOption for a certain time would work around this problem.

Comment 34

[Honza Bambas (:mayhemer)]

We have at least one bug to do so. I happen to be soon working on a project that will likely introduce some kind of caching exactly here, if possible.

Comment 35

[Markus Stange [:mstange]]

I'm curious if there's a way forward on this bug. Is the project that Honza was referring to still planned?

Comment 36

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

I'm not aware of any ongoing work in this area.
I'll take a look if anything can be done to improve this issue, but I'm fairly busy right now. If anyone can contribute a patch I'm happy to review it.

Comment 37

[Florian Quèze [:florian]]

I think this is being fixed in bug 1392272, so closing as duplicate.