Closed Bug 1535693 Opened 5 years ago Closed 5 years ago

Diagnose paint delay

Categories

(Firefox :: New Tab Page, enhancement, P1)

enhancement

Tracking

()

RESOLVED FIXED
Iteration:
68.4 - Apr 29 - May 12

People

(Reporter: gsuntop, Assigned: andreio)

References

Details

Attachments

(2 files)

According to Andrei there's about a 4-5 second delay between search box appearing and paint of the rest of the Discovery Stream content.

The cause of this is currently unknown and needs diagnosis so we can fix.

One possible tool for diagnosis would be to create a React “hello world” to measure only time to react rendering without all the DS code.

Have you tried using the Firefox Profiler to understand how the time is spent?

Andrei have you tried Firefox Profiler?

Flags: needinfo?(andrei.br92)

Yes, here is a profile recorded on the reference hardware https://perfht.ml/2GXyilF
It captures how document load event on about:newtab happened after 4800ms.

Flags: needinfo?(andrei.br92)

(In reply to Andrei Oprea [:andreio] from comment #3)

Yes, here is a profile recorded on the reference hardware https://perfht.ml/2GXyilF
It captures how document load event on about:newtab happened after 4800ms.

Can you explain how this profile was captured? I'm asking because it's not a startup profile, and I see 4 content processes attempting to load activity stream at the same time. Also, I'm not sure where you are looking to find the 4800ms value.

Attached image Screenshot 2019-03-18 at 11.46.44.png (deleted) —

It's a recording taken while launching a new window.

(In reply to Andrei Oprea [:andreio] from comment #5)

Created attachment 9051644 [details]
Screenshot 2019-03-18 at 11.46.44.png

Thanks! When I look in the 'Marker Chart' panel, I see 4 DocumentLoad markers with durations ranging from 2.8s to 17s. There are also FirstNonBlankPaint and FirstContentfulPaint markers that might be relevant to your interests.

(In reply to Andrei Oprea [:andreio] from comment #6)

It's a recording taken while launching a new window.

If it's when opening a single new window, it would be interesting to figure out why we are loading activity stream in 4 different content processes.

Severity: normal → enhancement
Priority: P2 → P1

Can you add info about the build of React that would be helpful here?

Flags: needinfo?(dmose)
Assignee: nobody → gsuntop

Andrei, would you like to take this ticket since you've been working on this diagnosis/profiling already?

Flags: needinfo?(andrei.br92)
Assignee: gsuntop → andrei.br92
Flags: needinfo?(andrei.br92)
No longer blocks: 1512725

Here's a startup profile with screenshots from the same reference hardware: https://perfht.ml/2TKGSuy
I'm not sure if this is Activity Stream only or general startup URL loading problem. For example here's a profile from the same device but this time it's loading google.com in the startup instead of about:newtab: https://perfht.ml/2TP09v1
When we also think about the network time, they look pretty similar.

If it's when opening a single new window, it would be interesting to figure out why we are loading activity stream in 4 different content processes.

I don't see that problem with these profiles. Maybe the new tab was opened 4 times on the previous profile? For example this is a profile when we open another window while one was already opened(previous profile case). And there is one privileged content: https://perfht.ml/2TQnEE2

(Also one notable difference from the first profile is that the new profiles are from nightly and the previous one is from stable. Used nightly so we could take the screenshots on windows.)

After Andrei's suggestion, changed browser.newtabpage.activity-stream.discoverystream.config and added "enabled": true, now I can see that there is a problem: https://perfht.ml/2TQaNSg
As you see here, first search box inside about:newtab is being rendered and after a while the other content.

(In reply to Nazım Can Altınova [:canaltinova] from comment #12)

As you see here, first search box inside about:newtab is being rendered and after a while the other content.

This is expected. The sections load separately from each other.

Attached image Screenshot 2019-03-21 at 09.23.38.png (deleted) —

The profile seems to suggest that as soon as the network requests end we start displaying content.
And the large number of image requests is slowing down painting. CDN response time is still fast but the machine seems to take longer to process them.

Machine Layout variant Number of images Average load time
Dev (fast) Basic 3 136 ms
Dev (fast) Complex 28 235 ms
Reference Basic 3 1105 ms
Reference Complex 28 3858 ms

Per request time goes up 1.7x on my fast development machine.
For the reference hardware it's closer to 3.5x

(In reply to Andrei Oprea [:andreio] from comment #14)

Created attachment 9052507 [details]
Screenshot 2019-03-21 at 09.23.38.png

The profile seems to suggest that as soon as the network requests end we start displaying content.

Perhaps due to this? https://github.com/mozilla/activity-stream/blob/master/content-src/components/DiscoveryStreamBase/DiscoveryStreamBase.jsx#L166

It itself is gated on the loaded flags, which are largely made synchronous in DiscoveryStreamFeed.jsm using awaits.

Flags: needinfo?(dmose)

(In reply to Dan Mosedale (:dmose, :dmosedale) from comment #15)

(In reply to Andrei Oprea [:andreio] from comment #14)

Created attachment 9052507 [details]
Screenshot 2019-03-21 at 09.23.38.png

The profile seems to suggest that as soon as the network requests end we start displaying content.

Perhaps due to this? https://github.com/mozilla/activity-stream/blob/master/content-src/components/DiscoveryStreamBase/DiscoveryStreamBase.jsx#L166

It itself is gated on the loaded flags, which are largely made synchronous in DiscoveryStreamFeed.jsm using awaits.

loaded is set to true as soon as the JSON payloads for feeds and spocs are available. What I'm seeing in the profile is that we are still spending a lot of time loading images instead of rendering the content (and loading the images afterwards).

There's bug 1535749 to not load assets (including images ?) until they might be shown and bug 1531933 to use smaller images.

Perhaps as a sanity check, force the images to nothing or resource: ?

We did have some image loading logic with the old page to show placeholder, etc:
https://github.com/mozilla/activity-stream/blob/409b3a42ce95d805242a89953d999498b3ac9031/content-src/components/Card/Card.jsx#L36-L71

As an exercise to see if this is really the whole problem here, I'd guess it wouldn't be hard to prototype lazy-loading using react-image (perhaps together with react-visibility-sensor) as suggested in the README: https://github.com/mbrevda/react-image#delay-rendering-until-element-is-visible-lazy-rendering).

And to finally respond to the needinfo, I was referring to the React Profiler, (more video here)[https://elijahmanor.com/react-devtools-profiler/]. That, however, requires React DevTools, so we'd need to get that running in our development environment (bug 1448364) first.

Likely easier than that will be to try some of the stuff suggested in https://reactjs.org/docs/optimizing-performance.html.

Iteration: 68.1 - Mar 18 - 31 → 68.2 - Apr 1 - 14
Iteration: 68.2 - Apr 1 - 14 → 68.3 - Apr 15 - 28
Iteration: 68.3 - Apr 15 - 28 → 68.4 - Apr 29 - May 12

There's been a lot of work to mitigate any performance issues. Specifically lazy loading images which was the main cause I was noticing in my previous comment. We can re-open if we consider this to still be an issue.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Component: Activity Streams: Newtab → New Tab Page
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: