1641696 - Firefox takes 50% more time than Microsoft Edge to display first paint of comments in reddit posts

Status: NEW

(Core :: Networking, defect, P3)

Description

[Asif Youssuff]

As seen on: https://www.reddit.com/r/firefox/comments/grmimf/any_chance_of_firefox_team_thinking_on_how_to/fs0burm/

Basic information

Steps to Reproduce:

1. Navigate to: https://www.reddit.com/r/firefox/
2. Click on comments for post "Any chance of Firefox team thinking on how to regain or retain it users through multitude of browsers across platforms looking at the rise of Edge?" (https://www.reddit.com/r/firefox/comments/grmimf/any_chance_of_firefox_team_thinking_on_how_to/)
3. Wait for text to appear.

Expected Results:

Firefox shows text faster than Edge (or at least at the same time).

Actual Results:

Firefox shows text after after Edge.

There are two screencasts shared by users:

• https://imgur.com/a/F15qEdw where Edge took 1.05 seconds and Firefox took 1.77 seconds
• https://imgur.com/a/yGQUqT8 where performance is worse than that.

---

More information

Screenshot: (if relevant, please attach a screenshot or screencast to this bug report)

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

Basic systems configuration:

OS version: Windows 10

GPU model: Nvidia GTX 1060 (3GB)

Number of cores: 4 i5-3470 @ 3.2ghz

Amount of memory (RAM): 16GB

Thanks so much for your help.

Comment 1

[Asif Youssuff]

Attachment: about:support

Comment 2

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

:yoasif, if you think that's a regression, then could you try to find a regression range in using for example mozregression?

Comment 3

[Daniel Holbert [:dholbert]]

Looks like the reddit comments load at around 4s in the profile.

Before/around that point there are some long-to-resolve requests in the network panel, and not a lot of CPU usage. Speculatively classifying this as Networking, but I'm not entirely sure.

Calling this [qf:pageload:p2] (p2 because it's a popular site).

Comment 4

[Honza Bambas (:mayhemer)]

Profiles don't provide enough information. Can you please provide a log with MOZ_LOG=timestamp,nsHttp:5,events:1 ? See https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging for more details how to capture it. It would also be very helpful to identify the request that loads the comments. Thanks.

Comment 5

[Asif Youssuff]

Attachment: log.7z

Log attached. I started Firefox with a stored session that loads https://www.reddit.com/r/firefox/search?q=edge%20team&restrict_sr=1 then I clicked the link that leads to https://www.reddit.com/r/firefox/comments/grmimf/any_chance_of_firefox_team_thinking_on_how_to/

I'm not sure how to identify which request loads the comments, or at least which identifier is interesting to you.

Comment 6

[Asif Youssuff]

NIing Honza in response to their request.

Comment 7

[Honza Bambas (:mayhemer)]

Thanks, I was deliberately waiting for more logging patches to land before asking for more information.

Aisf, you didn't modify the set of log modules to be MOZ_LOG=timestamp,nsHttp:5,events:1 so I can't see the cause of delays to requests for comments. Those seem to be XHRs to https://gateway.reddit.com/desktopapi/v1/postcomments/...

So I'll ask you to capture this again with the modified list of modules and with the Nightly build, from here. Thanks.

Comment 8

[Asif Youssuff]

Attachment: moz.zip

Honza,

Attached a new log file. I started Firefox with a stored session that loads https://www.reddit.com/r/firefox/search?q=edge%20team&restrict_sr=1 then I clicked the link that leads to https://www.reddit.com/r/firefox/comments/grmimf/any_chance_of_firefox_team_thinking_on_how_to/

Thanks!

Comment 9

[Honza Bambas (:mayhemer)]

Thanks. You missed the timestamp module. That's vital.

Comment 10

[Asif Youssuff]

Honza,

Is there a bug in about:networking? I copied and pasted the MOZ_LOG=timestamp,nsHttp:5,events:1 into the text box next to "Set Log Modules", clicked "Set Log Modules", and then started the log.

I then uploaded the file. Does that work if you try it on your machine?

Comment 11

[Asif Youssuff]

Attachment: screenshot of about:networking

Honza,

I am seeing a very strange bug after I paste MOZ_LOG=timestamp,nsHttp:5,events:1 and click the Set Log Modules button.

The current log modules shows as events:1,nsHttp:5,MOZ_LOG=timestam:0 -- for some reason it is being accepted as timestam.

I can't reproduce the issue when loading the profile via mozregression and build id 20200316154314.

Any ideas? Perhaps that is why the last two logs were unusable?

Comment 12

[Honza Bambas (:mayhemer)]

There may be, yes. I'll look into it.

In the meantime - maybe rather use command line arguments or environment variables?

Thank you.

Comment 13

[Asif Youssuff]

Attachment: log.7z

Honza, I hope this log helps.

Comment 14

[Honza Bambas (:mayhemer)]

(waiting for another log to be added to the code base)

Comment 15

[Honza Bambas (:mayhemer)]

Thanks, but, again you didn't modify the set of log modules (MOZ_LOG) to be added events:1 module. I was also waiting for some more logging added to Firefox codebase (bug 1651068).

Can you please repeat the request from Comment 12 with events:1 added?

Make sure you r Firefox Nightly is up to date!

Thanks.

Comment 16

[Asif Youssuff]

Honza, I followed your instructions - I have no idea why it is not outputting what you want to see.

In any case, please see the new log files: https://drive.google.com/file/d/1wGpGxOTn5NiamLPhsHEYrItUJOZYETDP/view?usp=sharing

Thanks!

Comment 17

[Honza Bambas (:mayhemer)]

I see one request for comments (presumable) being delayed by about 1.5 seconds. But it is simply the server response being slow:

2020-07-16 15:07:06.843000 UTC - [Parent 14712: Socket Thread]: I/nsHttp Http2Session::ReadSegments 0000018D1D9DE000 stream=0000018D167241A0 stream send complete
2020-07-16 15:07:08.152000 UTC - [Parent 14712: Socket Thread]: I/nsHttp Http2Session::RecvHeaders 0000018D1D9DE000 stream 0x21 priorityLen=0 stream=0000018D167241A0 end_stream=0 end_headers=4 priority_group=0 paddingLength=0 padded=0

In between there are few other requests made on the same h2 session for:
https://gateway.reddit.com/desktopapi/v1/sidebar_ads?allow_over18=&include=
https://gql.reddit.com/?request_timestamp=1594912027148
https://gql.reddit.com/?request_timestamp=1594912026857
https://gql.reddit.com/?request_timestamp=1594912026857
https://gql.reddit.com/?request_timestamp=1594912027148

they all are pretty fast.

so, this could be caused by different connection coalescing strategy against edge or how we prioritize the stream(s).

Comment 18

[Honza Bambas (:mayhemer)]

CC'ing Dragana in case she can see something I can't.