Open Bug 1363354 (FirstVideoPlay_YouTube) Opened 5 years ago Updated 4 years ago

YouTube first video play is slow

Categories

(Core :: General, defect)

55 Branch
x86_64
Windows 10
defect
Not set
normal

Tracking

()

People

(Reporter: arus, Unassigned)

References

(Depends on 1 open bug, Blocks 2 open bugs, )

Details

(Keywords: meta, perf, Whiteboard: [qf:p3][QRC][QRC_Analyzed])

Attachments

(1 file)

Name: Firefox
Version: 55.0a1
Windows 10 64 bit
buildID: 20170508030204

Steps to reproduce:
1. Launch browser.
2. Fill youtoube.com in Navigation Start, then press enter.
3. Type "mozilla" in youtube searchbox, then press enter.
4. Record with Gecko Profile:
   Tap on first video. (How to download Mozilla Firefox on Windows 7)
5. Share the profile.

Gecko profile:
https://perfht.ml/2pZOIAG

Notes:
https://docs.google.com/spreadsheets/d/1Kxn850VasyaG_WfRg3pMInW0hbIT8LP7pRPBYTIpdbM/edit?pli=1#gid=1483467512
Here is a profile that I captured from this:

  https://perfht.ml/2pYMxJC

Here's a very short analysis:

  * 29ms in nsGlobalWindow::ScrollTo flushing layout, bug 1365830
  * 21ms in createScriptForLazilyInterpretedFunction(), bug 1365835

There is a lot to dig more into, I will do so tomorrow.
Depends on: 1365835, 1365830
Summary: STR youtube first video play → Quantum Release Criteria: youtube first video play
https://perfht.ml/2q09woK
Here's the Gecko profile obtained on Acer Aspire e15.
Version: 55.0a1
Windows 10 64 bit
buildID: 20170518030213
Assignee: nihsanullah → ehsan
Blocks: Quantum
Keywords: meta
Alias: FirstVideoPlay_YouTube
Blocks: QRC_FX57
No longer blocks: Quantum
Softvision has provided a new profile for someone to analyze in comment 2.
Summary: Quantum Release Criteria: youtube first video play → YouTube first video play is slow
Whiteboard: [QRC][QRC_NeedAnalysis]
Unassigning this bug from Ehsan so it goes back into the QRC_NeedAnalysis bug list. We need an engineer to analyze the profiles in comment 1 and comment 2.
Assignee: ehsan → nobody
Samael, Please do an analysis of the profiles in comment 1 and comment 2.
Assignee: nobody → sawang
(In reply to Alin Rus from comment #2)
> https://perfht.ml/2q09woK
> Here's the Gecko profile obtained on Acer Aspire e15.
> Version: 55.0a1
> Windows 10 64 bit
> buildID: 20170518030213

There were some suspicious slow painting

- PresShell::Paint chrome://browser/content/browser.xul took 294ms
  + ContentClientRemoteBuffer::BeginPaintBuffer         took 249ms

- PresShell::Paint https://www.youtube.com/results?search_query=mozilla took 174ms
  + FrameLayerBuilder::DrawPaintedLayer                                 took 152ms 

- PresShell::Paint https://www.youtube.com/watch?v=yWiym2Ej1S0 took 895ms
  + ContentClientRemoteBuffer::BeginPaintBuffer                took 347ms

These seems to be causing synchronize restyling

- MouseEventBinding::get_offsetX  took 29ms
- ElementBinding::get_clientWidth took 52ms
- WindowBinding::scroll           took 55ms

I found 2 slow construction

- mozilla::dom::HTMLFormElementBinding::get_elements took 40ms
  + js::ProxyObject::New                             took 40ms

- js::ConstructFromStack(JSContext *,JS::CallArgs const &)          took 21ms
  + mozilla::dom::Constructor(JSContext *,unsigned int,JS::Value *) took 21ms

One GC walking

- nsPurpleBuffer::VisitEntries took 257ms

And some other suspicious slow APIs

- PCookieService::Msg_GetCookieString             took 933.77ms => bug 1331680
- nsComponentManagerImpl::GetServiceByContractID  took 22ms
- nsTableRowFrame::GetNextRow()                   took 71ms
- nsDisplayList::GetClippedBoundsWithRespectToASR took 20ms
- MediaSourceBinding::isTypeSupported             took 24ms
- HTMLMediaElementBinding::canPlayType            took 16ms
- date_toGMTString                                took 12ms
(In reply to Samael Wang [:freesamael] from comment #6)
> There were some suspicious slow painting
> 
> - PresShell::Paint chrome://browser/content/browser.xul took 294ms
>   + ContentClientRemoteBuffer::BeginPaintBuffer         took 249ms
> 
> - PresShell::Paint https://www.youtube.com/results?search_query=mozilla took 174ms
>   + FrameLayerBuilder::DrawPaintedLayer                                 took 152ms 
> 
> - PresShell::Paint https://www.youtube.com/watch?v=yWiym2Ej1S0 took 895ms
>   + ContentClientRemoteBuffer::BeginPaintBuffer                took 347ms

Hi Matt, do you think there's any useful information in the profile that can help us finding possible causes of slow painting?
Flags: needinfo?(matt.woodrow)
It looks like there's quite a few samples missing from that profile unfortunately.

The time under BeginPaintBuffer is being spent in CrossProcessSemaphore::Wait, which is waiting for the compositor to finish reading from the buffer we want to write to.

There's a few possibilities for that:

- The composition is taking a long time, and that's the underlying problem.
- We didn't schedule composition properly, or it didn't start when expected for some reason.
- Composition finished, but forgot to notify us that it was done with the buffer.
- We tried to draw to the same buffer two frames in a row (with double buffering, we'd expect to write to a given buffer every second frame, which buys time for the compositor to finish using the old one).

It's hard to narrow it down further than that from this profile alone.
Flags: needinfo?(matt.woodrow)
Put it back to QRC_NeedAnalysis bug list.
Assignee: sawang → nobody
Sotaro, could you help to follow above profiling investigation? Thanks.
Assignee: nobody → sotaro.ikeda.g
Flags: needinfo?(sotaro.ikeda.g)
Between BeginPaintBuffer() and CrossProcessSemaphore::Wait(), TextureClient::TryReadLock() exists. I checked actual wait duration with the STR on my several windows pcs. But I did not see the duration more than 33ms.
Flags: needinfo?(sotaro.ikeda.g)
Composition was triggered based by CompositorVsyncScheduler. If client side continuously paint to ClientPaintedLayer, TryReadLock() wait duration could be one CompositorVsyncScheduler's period at most.
(In reply to Bobby Chien [:bchien] from comment #10)
> Sotaro, could you help to follow above profiling investigation? Thanks.

Around graphics, BeginPaintBuffer seems graphics related, but as in Comment 11, I could not reproduce such a long wait. From it, it might be related to underlying problem.
Duplicate of this bug: 1362069
As previous comments, I don't see more action here and look like a low priority issue. Note and track under quantum flow.
Whiteboard: [QRC][QRC_NeedAnalysis] → [qf][QRC][QRC_Analyzed]
Whiteboard: [qf][QRC][QRC_Analyzed] → [qf:p3][QRC][QRC_Analyzed]
Assignee: sotaro.ikeda.g → nobody
Keywords: perf
You need to log in before you can comment on or make changes to this bug.