Diagnose paint delay
Categories
(Firefox :: New Tab Page, enhancement, P1)
Tracking
()
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.
Comment 1•5 years ago
|
||
Have you tried using the Firefox Profiler to understand how the time is spent?
Reporter | ||
Comment 2•5 years ago
|
||
Andrei have you tried Firefox Profiler?
Assignee | ||
Comment 3•5 years ago
|
||
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.
Comment 4•5 years ago
|
||
(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.
Assignee | ||
Comment 5•5 years ago
|
||
Assignee | ||
Comment 6•5 years ago
|
||
It's a recording taken while launching a new window.
Comment 7•5 years ago
|
||
(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.
Updated•5 years ago
|
Comment 8•5 years ago
|
||
Can you add info about the build of React that would be helpful here?
Updated•5 years ago
|
Reporter | ||
Comment 9•5 years ago
|
||
Andrei, would you like to take this ticket since you've been working on this diagnosis/profiling already?
Assignee | ||
Updated•5 years ago
|
Updated•5 years ago
|
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.
Assignee | ||
Comment 13•5 years ago
|
||
(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.
Assignee | ||
Comment 14•5 years ago
|
||
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
Comment 15•5 years ago
|
||
(In reply to Andrei Oprea [:andreio] from comment #14)
Created attachment 9052507 [details]
Screenshot 2019-03-21 at 09.23.38.pngThe 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.
Assignee | ||
Comment 16•5 years ago
|
||
(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.pngThe 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).
Comment 17•5 years ago
|
||
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
Updated•5 years ago
|
Comment 18•5 years ago
|
||
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).
Comment 19•5 years ago
|
||
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.
Updated•5 years ago
|
Updated•5 years ago
|
Updated•5 years ago
|
Assignee | ||
Comment 20•5 years ago
|
||
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.
Updated•5 years ago
|
Description
•