Closed Bug 1645651 Opened 4 years ago Closed 13 days ago

Changes in Reddit's comment section JS code makes selecting text slow on Nightly

Categories

(Core :: JavaScript Engine, defect, P2)

Product:
Core
Component:
JavaScript Engine
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: mayankleoboy1, Unassigned)

References

(
URL
)

Details

(Keywords: perf, regression)

Attachments

(2 files)

slow selecting text on comments.mp4
1.17 MB, video/mp4
Details
about:support
28.23 KB, text/plain
Details

start a new profile
go to https://www.reddit.com/r/india/comments/aeblpo/r_please_dont_get_jio_gigafiber_and_i_have/

Load some comments
Select text of some comment OR double/triple click on a comment to select some text OR Select text from multiple comments

AR: Lag in selecting text.
ER: not so

Profile: https://share.firefox.dev/3d2j7D7

Profile from my usual daily profile : https://share.firefox.dev/2BWyHmP

Tested on a nightly from an year back, and it also showed the same issue.
Looks like they changed some JS code in the comment moderation, which runs slow on Nightly.

Summary: Selecting text on Reddit lags a lot. Appears to spend large time in JS → Changes in Reddit's comment section JS code makes selecting text slow on Nightly

Regression window:
https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=6875c54fd481eeb715a96474b5babb2734423d04&tochange=563e860bea95f6696ac5a90c0e7b35b7874a4184

Suspect:
1e6a2dbfa104081bed1a4273aff4cbd2c29d3335 Tom Schuster — Bug 1317422 - Implement JavaScript globalThis proposal. r=jandem

Keywords: perf, regression
Type: task → defect

Looking at the profile from comment 0, while focusing on the 8.8s event delay, it seems that while most of the time is spent under JavaScript, a lot of this time is spent free-ing memory, which is highly unusual.

ProfilerBacktrace appears in more than a quarter of the stacks which are being reported. So I wonder if this is not a huge profiler overhead.

Component: JavaScript Engine → Gecko Profiler

In the profile from comment 0, "nativeallocations" is enabled, so all malloc&frees are intercepted, and a subset of them are actually captured with a stack, this is why there are lots of calls through ProfilerBacktrace.
Now I'm not entirely sure if that particular 8.8s delay is caused or worsened by the ProfilerBacktrace overhead itself, or the amount of allocations&deallocations that are happening at that time -- or a combination of both!?

Mayank, could you please confirm that the text selection was also slow when not profiling, and also when capturing your 2nd profile in comment 1? (Which doesn't have "nativeallocations")

Flags: needinfo?(mayankleoboy1)

Text selection was slow when not profiling. Text selection was slow during capturing profiles from comment #0 and comment 1

Here is a new profile from my normal daily profile (with ublock, 128MB buffer in profiler) : https://share.firefox.dev/2CdSGOa

Edit: IIRC, the profiler buffer was set to 1GB when i captured the profile in comment 0. That might have lead to tons of memcpy?
Edit2: You can replicate the slowness if you continuously triple click on the text of the comments.

Flags: needinfo?(mayankleoboy1)

Thank you Mayank.

So the ProfilerBacktraces were a red herring in that profile; but they are probably a symptom showing a lot of memory activity (and making things worst in that case, but not causing it per se).
Moving bug back to the JS engine component for further analysis.

(Note: We have bug 1578792 and others, to lower the overhead of capturing backtraces, so hopefuly this will get less distracting...)

Component: Gecko Profiler → JavaScript Engine

I can't reproduce this on 77.0.1 64-bit, running on Windows. Followed steps from comment 1.

The regression patch that Alice identified seems possibly plausible, but it's hard to rate the severity of this without an understanding of how common/reproducible it is, and some understanding of how severe the lag is.

Mayank do you have any additional info about the setup, build, and architecture you are running on?

Flags: needinfo?(mayankleoboy1)
Flags: needinfo?(mayankleoboy1)
Attached file about:support —

about:support is from my usual profile, but i also see similr slowness on a new profile

Flags: needinfo?(kvijayan)

Have you tried with a clean profile?

I tried installing the list of addons but did notice a slow-down but not as major as reported in the video.

on a clean profile, the slow down is a bit less. But it is still very noticable

I started off wanting to triage this bug but ended up doing a bit more than that.

I tried this again with a fresh profile on windows, with ublock installed. I can definitely reproduce this now. Not nearly as terrible as what it shows on Mayank's video, but definitely a lag between triple-clicking and the whole paragraph getting selected.

ublock is definitely necessary, and also.. this behaviour (for me at least) only happens when the page is immediately loaded. The triple-clicking works pretty fast once the page is loaded and I expand comments and scroll down and triple-click there.

I captured a profile of one of these clicks: https://share.firefox.dev/38uKEwh

The interesting thing to look at here is the marker chart. There are a whole lot of setTimeout(0) that are taking anywhere from 800ms to >2000ms to get scheduled. These setTimeout delays correspond to the lag between the input events and the first paint of the full selection.

I noticed looking at the network tab in that profile, that the setTimeout(0) marker lag corresponds reasonably well to when a bunch of network requests complete. The network requests in question are to first-party domains which are different from the site domain: v.redd.it, preview.redd.it, and external-preview.redd.it.

Given that this happens only with uBlock installed, and only happens during load, and the setTimeout delays correspond to the selection delay, and also correspond to network requests for off-domain resources in that same time period.. there are some hints of what may be happening here.

Is there some blocking code uBlock runs on requests to external domains? Has uBlock changed it's JS code recently to use globalThis more heavily (considering the regression window analysis and suggested culprit patch)? Or has reddit maybe changed its behaviour recently to more heavily use external resources, and the heavy globalThis usage wasn't getting exercised because uBlock code wasn't running for most requests?

Given the context and conditions of the regression, I'm marking this S3 and P2.

Flags: needinfo?(kvijayan)
Severity: -- → S3
Priority: -- → P2

Is there some blocking code uBlock runs on requests to external domains? Has uBlock changed it's JS code recently to use globalThis more heavily (considering the regression window analysis and suggested culprit patch)? Or has reddit maybe changed its behaviour recently to more heavily use external resources, and the heavy globalThis usage wasn't getting exercised because uBlock code wasn't running for most requests?

Rather than ask this question to the air, I thought it might be more worthwhile to direct it at someone :)

Conley, do you happen to know how uBlock works, and whether it may be responsible for this sort of behaviour (causing click events handling to get delayed because of blocking code running on external network requests and tying up main thread)?

Flags: needinfo?(mconley)

(In reply to Kannan Vijayan [:djvj] from comment #15)

Conley, do you happen to know how uBlock works

Only at an extremely superficial level. I believe it uses blocking webRequests to filter network traffic and block requests for advertisements.

Hey Jorge, do you know if gorhill uses Bugzilla at all? Perhaps we can get him in here to talk with djvj about what might be going on.

Flags: needinfo?(mconley) → needinfo?(jorge)

Redirecting to gorhill.

Flags: needinfo?(jorge) → needinfo?(rhill)

I captured a profile of one of these clicks: https://share.firefox.dev/38uKEwh

Unfortunately, the WebExtensions process is not included in that profiling session -- but I don't think it's a problem, similar cases[1] have been reported and the WebExtensions process was not an issue performance-wise.

In the profling session above, uBO's javascript execution amount to 24 ms out of roughly 6-second range. Since uBO is JavaScript, select "JavaScript" in "Call Tree" pane, and enter "ublock" in "Filter stacks" field.

This means that most of javaScript execution is from the site itself, which totals 2,692 ms for the 6-second range of the profiling session.

The fact that uBO needs to be installed to reproduce could be merely a case of the site not expecting having some of its network requests blocked or some of its HTML elements hidden and misbehaving as a result.

It would be useful to try these scenarios (separately) to find out if this makes a difference:

Notice how the Network thread seems flooded along with a lots of "Waiting for response" which seems to never resolve. I have tried two URLs at random which were reported as "Waiting for response" and these were Minecraft videos. (??)

[1] Example of what appears to be a similar case: https://www.reddit.com/r/firefox/comments/hlf9gl/firefox_has_become_slow_most_of_the_time/fx4ckks/

Flags: needinfo?(rhill)

Here is another case from weeks ago, I also didn't know what to make of it:
https://www.reddit.com/r/firefox/comments/gg8424/why_is_firefox_so_slow/fpzng8e/?context=10000

The user provided a profile session data:
https://profiler.firefox.com/public/93b29000a2845266e9c87f3d49e04d73ad093097/calltree/?globalTrackOrder=0-1-2-3&implementation=js&localTrackOrderByPid=20388-1-0~6632-0~20772-0~20012-0~&thread=3&v=4

Again, a whole lot of code spend on the site's own JavaScript, and though URLs have been anonymized in the profiling session data, I can see reddit mentioned in the path of some script URLs in the call tree.

Again, a lot of network requests in the Network thread of the parent process marked as "Waiting for response".

Here's a profile where the user included the WebExtensions process, and also saw the network panel waiting for lots of responses: https://share.firefox.dev/2VPuFUz

And here it is without uBlock:
https://share.firefox.dev/3209kvg

(Both of these profiles are via https://www.reddit.com/r/firefox/comments/hlf9gl/firefox_has_become_slow_most_of_the_time/fx4ckks/)

Interestingly, the content process with Reddit loaded in it doesn't show these long requests in its network track.

When I profile my own machine using "new Reddit", logged out, I do see long network requests too. So far, all of these seem to be for ad networks.

site not expecting having some of its network requests blocked

I found an example of this for (new layout) Reddit, by merely adding the following filter in uBO's "My filters" pane:

||redditstatic.com/*/reddit-components-SidebarNativeAd.

When not logged into Reddit and visiting https://www.reddit.com/r/uBlockOrigin/, I get constant CPU usage and never-ending memory usage growth -- up to running out of memory -- which I experienced and had to reboot. Don't let this happen to you, close the tab before you run out of memory.

The point is that I was able to create a serious performance issue on Reddit by merely blocking very specific resources. The filter above will block two network requests, one for a script resource, and the other for a stylesheet resource, and the serious performance issue can be reproduced by merely blocking just the stylesheet resource.

In the scenario with the filter above, I could see constant flow of network requests in uBO's own logger, not unlike what can be seen in the problematic reported scenarios. Included in the constant flow of network requests, including repeated requests to 3rd party googletagservices.com (which are redirected by uBO to its own surrogate scriptlet).

That's a very interesting finding - thanks, gorhill.

Hey twisniewski, does this sound like something that falls within the WebCompat bucket? A site starts going wild if a resource is blocked?

Flags: needinfo?(twisniewski)

I think I'm seeing the same behavior in Chrome with uBo and that specific filter on reddit.com, so it seems more likely that Reddit's code just isn't expecting the resources to be blocked, and handles that condition ungracefully (to say the least).

As such it could simply be that Chrome handles such ungraceful behavior more gracefully in turn, which strikes me more as a perf issue than a webcompat one.

As for the original report of slow text-selection, it's not happening for me on the latest nightly on OSX, so it's hard to makee a call on that case.

Flags: needinfo?(twisniewski)

This is still reproducible.
Here is a profile with ublock disabled : https://share.firefox.dev/3deZMo8

Given this is a Reddit issue, I'm going to close this as there's not much we can do here unfortunately.

Please re-open in case there's an action here that I missed reading the bug history.

Status: NEW → RESOLVED
Closed: 13 days ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: