1363354 - (FirstVideoPlay_YouTube) [meta] YouTube first video play is slow

Status: NEW

(Core :: General, defect)

Description

[Alin Rus]

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

Comment 1

[(no longer active)]

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.

Comment 2

[Alin Rus]

https://perfht.ml/2q09woK
Here's the Gecko profile obtained on Acer Aspire e15.
Version: 55.0a1
Windows 10 64 bit
buildID: 20170518030213

Comment 3

[Chris Peterson [:cpeterson]]

Softvision has provided a new profile for someone to analyze in comment 2.

Comment 4

[Chris Peterson [:cpeterson]]

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.

Comment 5

[Jean Gong :jgong]

Samael, Please do an analysis of the profiles in comment 1 and comment 2.

Comment 6

[Samael Wang [:freesamael] (away for now)]

(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

Comment 7

[Samael Wang [:freesamael] (away for now)]

(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?

Comment 8

[Matt Woodrow (:mattwoodrow)]

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.

Comment 9

[Samael Wang [:freesamael] (away for now)]

Put it back to QRC_NeedAnalysis bug list.

Comment 10

[Bobby Chien]

Sotaro, could you help to follow above profiling investigation? Thanks.

Comment 11

[Sotaro Ikeda [:sotaro]]

Attachment: pach - Output log when TextureClient::TryReadLock() waits longer

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.

Comment 12

[Sotaro Ikeda [:sotaro]]

Composition was triggered based by CompositorVsyncScheduler. If client side continuously paint to ClientPaintedLayer, TryReadLock() wait duration could be one CompositorVsyncScheduler's period at most.

Comment 13

[Sotaro Ikeda [:sotaro]]

(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.

Comment 15

[Bobby Chien]

As previous comments, I don't see more action here and look like a low priority issue. Note and track under quantum flow.