1579127 - Video playback regression when playing back video on YouTube sped up 2x

Status: VERIFIED FIXED

(Core :: Audio/Video: Playback, defect, P2)

Description

[Asif Youssuff]

Attachment: bxxjenabxhk31.jpg

Reported on reddit: https://www.reddit.com/r/firefox/comments/czfdfe/noticeable_improvement_of_esr_over_other_flavors/

STR:

1. Navigate to: https://www.youtube.com/watch?v=8gYV0tczWdA
2. changed the resolution of the video to 720p60fps and 1080p60fps, and sped it up to x2.

What happens:

Firefox drops many frames when playing back video.

2019-09-04T22:58:23: INFO : Narrowed nightly regression window from [2018-08-09, 2018-08-11] (2 days) to [2018-08-10, 2018-08-11] (1 days) (~0 steps left)

Seeing a lot of

WARNING: Decoder=1de33c56e10 Decode error: NS_ERROR_DOM_MEDIA_FATAL_ERR (0x806e0005) - RefPtr<MediaSourceTrackDemuxer::SamplesPromise> __cdecl mozilla::MediaSourceTrackDemuxer::DoGetSamples(int32_t):

in the mozregression log.

Comment 1

[Asif Youssuff]

Attachment: mozregression-log.txt

Comment 2

[Ryan VanderMeulen [:RyanVM]]

Pushlog for the regression range in the attached log:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=9a6728f46269868c5f24f18c95cd2319b5b67a0a&tochange=4bf146738292330c1fba2dc84df3ecb27e09872c

Is this with WebRender enabled? If so, does it reproduce with it off?

Comment 3

[Asif Youssuff]

Attachment: about:config prior to regression (ESR)

Comment 4

[Asif Youssuff]

Attachment: about:config Beta (WebRender)

Comment 5

[Asif Youssuff]

Attachment: about:config Beta (WebRender off)

Comment 6

[Asif Youssuff]

User reports that the issue persists with WebRender off, but reproduces with it on as well.

Comment 7

[Ryan VanderMeulen [:RyanVM]]

Bug 1480190 seems like a plausible candidate in that range. Does flipping media.media-capabilities.enabled to false solve it?

Comment 8

[pcvl441]

(In reply to Ryan VanderMeulen [:RyanVM] from comment #7)

Bug 1480190 seems like a plausible candidate in that range. Does flipping media.media-capabilities.enabled to false solve it?

no it didn't help

Comment 10

[Alastor Wu [:alwu]]

I found that frame dropping would only happen on playback rate > 1.5x, it won't happen when adjust speed to 1.25x or slower.

Comment 11

[Alastor Wu [:alwu]]

NI myself for further investigation.

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+1]]

A good set of video tests can be found at https://ytlr-cert.appspot.com/2019/main.html?test_type=playbackperf-test. Lots of those report a lot of dropped frames. Especially test 98 is a good candidate here.

With using this video the regression range is:

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d0a17fc80dabd76aca148d42684a385ba41f9ed8&tochange=47091a68bf3a7f0706cab19f00c414134a63a787

Bug 1480190 is the only media related change here, so I would assume that some code in that patch is not aware of the media.media-capabilities.enabled preference and gets run at any time? Also requesting needinfo from Jean-Yve given that he landed that patch for Firefox 63.

Fixing this bug should result in vastly improved performance test results for the youtube-playback tests. See the following graph how MacOS is behind other platforms:

https://treeherder.mozilla.org/perf.html#/graphs?series=mozilla-central,2041824,1,10&series=mozilla-central,2042691,1,10&series=mozilla-central,2042402,1,10&series=mozilla-central,2054686,1,10

Comment 13

[Alastor Wu [:alwu]]

So far the only thing I can only tell is that all dropped frames are dropped by compositor, but I couldn't figure out why compositor does so. The frames dropping comes from [1] and [2]. In addition, I think this issue is not related with media capability, it seems more related with bug 1245400 where we started to count the dropped frames from compositor.

[1] https://searchfox.org/mozilla-central/rev/588814f2edddf0e132d77d326ddae50911e8bad1/gfx/layers/composite/ImageComposite.cpp#110-115
[2] https://searchfox.org/mozilla-central/rev/588814f2edddf0e132d77d326ddae50911e8bad1/gfx/layers/composite/ImageComposite.cpp#170-187

Comment 14

[Alastor Wu [:alwu]]

Hi, Matt,
We found out that compositor keeps dropping frames when we watch 60fps video on Youtube in 1.5x speed. Do you know who can help to investigate this problem?
Thank you.

Comment 15

[Sylvestre Ledru [:Sylvestre]]

Featured on reddit: https://www.reddit.com/r/firefox/comments/d32ioa/my_first_time_filing_a_bug_and_it_went_great/

Comment 16

[Liz Henry (:lizzard) (relman/hg->git project)]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #12)

Fixing this bug should result in vastly improved performance test results for the youtube-playback tests. See the following graph how MacOS is behind other platforms:

Given that fixing this might improve performance on macOS I'd like to keep an eye on this for 70 since we're still in early beta.

Comment 17

[Matt Woodrow (:mattwoodrow)]

Attachment: Screenshot_2019-09-13 Firefox 71 0 - Intel Mac OS X 10 13 - 9 12 2019, 9 12 36 PM UTC - Firefox profiler.png

How are people determining that frames are being dropped? Are there visible issues during playback, or is it just the reported stats?

I haven't been able to reproduce any visual problems, but I do see roughly 10% frame drop reported when running the video from comment #0 at 2x (consistently across both graphics cards and monitor setups).

I've attached a screenshot from the profiler. You can see the VsyncTimestamp and Composite markers are are in sync, evenly spaced (at ~16.7ms intervals, 60hz) and complete quickly.

We can also see a significantly higher rate of ImageBridgeTransactions (expected, since we're now effectively playing a 120fps video).

There's also 3 'video frame dropped' markers (which is much higher than the 10% I see reported, but I zoomed in on a particularly bad section of the profile).

That seems like a bug to me. We can't actually present all the frames, since we're on a 60hz monitor and the video is producing 120fps. The obvious bug would be that we'd only be able to present every second frame, and would report a 50% frame drop. That's not what's happening.

I think someone needs to dig into the frame drop logic, figure out why we're only sometimes reporting a dropped from despite clearly dropping lots, and figure out an algorithm that understands videos that play faster than the monitor refresh rate.

Comment 18

[Alastor Wu [:alwu]]

Thank Matt, I will start to dig into the frame drop logic and figure out what correct behavior is when we exceed the maximum rendering frame threshold of compositor.

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+1]]

It would be interesting to know why this also only seems to happen on MacOS and maybe Aarch64 on Windows:

https://treeherder.mozilla.org/perf.html#/graphs?timerange=1209600&series=mozilla-central,2042980,1,10&series=mozilla-central,2041824,1,10&series=mozilla-central,2042402,1,10&series=mozilla-central,2042691,1,10&series=mozilla-central,2043558,1,10&series=mozilla-central,2054686,1,10&highlightAlerts=1

All the other platforms report only a hand-full of frame drops.

Comment 20

[Jean-Yves Avenard [:jya]]

This is what Chrome does too.

If you attempt to play a 120Hz video on a 60Hz screen, it will report 50% frames dropped.

Comment 21

[Adam Stevenson [:adamopenweb]]

If you look at this query, the dropped frames on 1080p60 and 720p60 (at 1.5x and 2x) using H264 were fine until around July 15th.

Edit: this is on Windows 64.

https://health.graphics/playback?platform=win64&browser=firefox&encoding=H264&past=3month&ending=2019-09-13

Comment 22

[Alastor Wu [:alwu]]

The way we used to calculate dropped frame in ImageComposite is, we would remember the last chosen image, and update the chosen image when (1) set new images or (2) any one is asking for a current image, no matter for painting it or just checking its information, eg. size.

For (1), if the timestamp of the eariest image from the new images, which video sink gave to compositor, is later than the timestamp of the chosen image, then we would check how many frames are in between those two images, and add this number to the dropped frame amount.

For (2), every time someone is asking for a current image, we would check the current time to see if the chosen frame's timestamp fall behind the current time. If so, we would update the chosen image until the image's timestamp exceed the current time.

---

Back to our issue, as the highest composited rate is 60hz, so in theory we are not able to render any video, which frame rate is higher than 60, without dropping any frame. So why we only see frame dropping on playback rate in 1.5x or higher? according to the theory, it should also happen on 1.25x or any playback rate higher than 1.

That is because our frame dropping calculation logic didn't reflect exactly how many frames we drop. As I mentioned above, we have two places where we would do the frame dropping calculation, but both operations are not restricted by being run 60 times per second, they can be run more frequently than that.

If the video sink sets images more frequently than 60 times per second, then we would get the frame drop in (1).
If asking for a current images more frequently than 60 times per second, then we would get the frame drop in (2).

And because of (2), we actually update the image index way more frequently, which results in our frame dropping number is less than our expectation. However, those dropped frame are acutally not caused by overloaded machine, which is simply that we couldn't compositor image on such high rate.

Therefore, we should check the image update rate and the compositored rate to decide if the dropped frame is caused by slow machine or higher image update rate, and only report the former one to FrameStatisticsData.

Comment 23

[Alastor Wu [:alwu]]

And a possible explanation for the difference of dropped frame amount on different platforms is, some platforms might run (2) faster, and some of them run it in a slow frequency. In this case, the platform running in slower frequency would get more frame dropping than other platforms, and it apparently is OSX from our report.

Comment 24

[Alastor Wu [:alwu]]

Attachment: Bug 1579127 - only count the frame dropping due to system overload.

When user adjusts the video playback rate, which might cause we sending images in a speed that is faster than the speend we composite images.

In this situation, the frame dropping actually won't cause any visual defect and we also don't want to report this frame dropping to user, because it's not caused by system overloading, it's just our compositor doesn't support compositing images in such a high rate.

Therefore, we should check if the dropped images are caused by system overload or high update rate, and only report the former to user.

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/348fa5ed7407
only count the frame dropping due to system overload. r=mattwoodrow

Comment 26

[Raul Gurzau (:RaulG)]

Backed out changeset 348fa5ed7407 (bug 1579127) for image raster crashes on a CLOSED TREE.

Backout link: https://hg.mozilla.org/integration/autoland/rev/f69570cd08304a581d2285100b79e5bd135484f6

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception&revision=5f5e153eb14b8ecd44b5453e7a4a9e53e95193dd&selectedJob=269386950

Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269386950&repo=autoland&lineNumber=2209

Log snippet:
[task 2019-10-02T09:13:17.467Z] 09:13:17 INFO - TEST-PASS | dom/media/test/test_autoplay_policy_activation.html | played - inaudible playback in unactivated same-origin iframe in activated parent allowed
[task 2019-10-02T09:13:17.467Z] 09:13:17 INFO - Buffered messages finished
[task 2019-10-02T09:13:17.468Z] 09:13:17 ERROR - TEST-UNEXPECTED-FAIL | dom/media/test/test_autoplay_policy_activation.html | application terminated with exit code 1
[task 2019-10-02T09:13:17.468Z] 09:13:17 INFO - runtests.py | Application ran for: 0:00:58.758469
[task 2019-10-02T09:13:17.468Z] 09:13:17 INFO - zombiecheck | Reading PID log: /var/folders/36/klpkks_52sn740vy6z74ktnh000017/T/tmpPcN5XQpidlog
[task 2019-10-02T09:13:17.468Z] 09:13:17 INFO - ==> process 1721 launched child process 1722
[task 2019-10-02T09:13:17.468Z] 09:13:17 INFO - ==> process 1721 launched child process 1723
[task 2019-10-02T09:13:17.468Z] 09:13:17 INFO - ==> process 1721 launched child process 1724
[task 2019-10-02T09:13:17.468Z] 09:13:17 INFO - ==> process 1721 launched child process 1725
[task 2019-10-02T09:13:17.468Z] 09:13:17 INFO - zombiecheck | Checking for orphan process with PID: 1722
[task 2019-10-02T09:13:17.468Z] 09:13:17 INFO - zombiecheck | Checking for orphan process with PID: 1723
[task 2019-10-02T09:13:17.469Z] 09:13:17 INFO - zombiecheck | Checking for orphan process with PID: 1724
[task 2019-10-02T09:13:17.469Z] 09:13:17 INFO - zombiecheck | Checking for orphan process with PID: 1725
[task 2019-10-02T09:13:17.469Z] 09:13:17 INFO - mozcrash Copy/paste: /Users/cltbld/tasks/task_1570006377/build/macosx64-minidump_stackwalk /var/folders/36/klpkks_52sn740vy6z74ktnh000017/T/tmpifuRuy.mozrunner/minidumps/2B7D716E-D9FC-49A6-9293-77579DE9D8B3.dmp /Users/cltbld/tasks/task_1570006377/build/symbols
[task 2019-10-02T09:13:25.221Z] 09:13:25 INFO - mozcrash Saved minidump as /Users/cltbld/tasks/task_1570006377/build/blobber_upload_dir/2B7D716E-D9FC-49A6-9293-77579DE9D8B3.dmp
[task 2019-10-02T09:13:25.221Z] 09:13:25 INFO - mozcrash Saved app info as /Users/cltbld/tasks/task_1570006377/build/blobber_upload_dir/2B7D716E-D9FC-49A6-9293-77579DE9D8B3.extra
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - PROCESS-CRASH | dom/media/test/test_autoplay_policy_activation.html | application crashed [@ mozilla::layers::ImageComposite::IsImagesUpdateRateFasterThanCompositedRate(mozilla::layers::ImageComposite::TimedImage const&, mozilla::layers::ImageComposite::TimedImage const&) const]
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - Crash dump filename: /var/folders/36/klpkks_52sn740vy6z74ktnh000017/T/tmpifuRuy.mozrunner/minidumps/2B7D716E-D9FC-49A6-9293-77579DE9D8B3.dmp
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - Operating system: Mac OS X
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - 10.14.5 18F132
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - CPU: amd64
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - family 6 model 69 stepping 1
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - 4 CPUs
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO -
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - GPU: UNKNOWN
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO -
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - Crash reason: EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - Crash address: 0x0
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - Process uptime: 39 seconds
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO -
[task 2019-10-02T09:13:25.373Z] 09:13:25 INFO - Thread 18 (crashed)

Comment 27

[Alastor Wu [:alwu]]

Attachment: Bug 1579127 - part2 : always present a valid timestamp on image.

We should always assign a non-null value to image's timestamp, it makes no sense to have a null timestamp.

Especially considering that the image composite would calculate the time difference between frames to know the update rate, so we have to keep the timestamp not null.

Comment 28

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fabb105bcda3
only count the frame dropping due to system overload. r=mattwoodrow
https://hg.mozilla.org/integration/autoland/rev/379a22d15598
part2 : always present a valid timestamp on image. r=jolin

Comment 29

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/fabb105bcda3
https://hg.mozilla.org/mozilla-central/rev/379a22d15598

Comment 30

[Liz Henry (:lizzard) (relman/hg->git project)]

Given that we only have one beta left in this cycle, it seems best to let this fix ride with 71.
Let me know if you feel strongly that it should be in 70, though.

Comment 31

[Ryan VanderMeulen [:RyanVM]]

Is this something we should consider uplifting to ESR68 or can this fix ride with mainline release? The patches graft cleanly as-landed.

Comment 32

[Alastor Wu [:alwu]]

Yep, I think we can uplift them to ESR 68 as well, because it would indeed improve the dropping frame counting on Youtube, which could allow them to determine what the best quality video for being watched smoothly should be.

Comment 33

[Alastor Wu [:alwu]]

Comment on attachment 9093460 [details]
Bug 1579127 - only count the frame dropping due to system overload.

ESR Uplift Approval Request

• If this is not a sec:{high,crit} bug, please state case for ESR consideration: When user is playing a video which frame rate is higher than 60 frames per second, these patches could improve the dropping frame counting a lots, which allows website to determine correctly what the best quality video for being watched smoothly should be.
• User impact if declined: When user is playing a video which frame rate is higher than 60 frames per second, a lots of amount of dropped frame would be reported, it might result in worse quality video which website serves to user, because dropping frame indicates that user's computer might not be able to play current resolution video.
• Fix Landed on Version: 71
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): 1. It doesn't change the play behavior, we only change the frame dropped logic

2. It only takes effect when user is playing 60+ frame rate video

• String or UUID changes made by this patch: no

Comment 34

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9093460 [details]
Bug 1579127 - only count the frame dropping due to system overload.

Fixes a compat issue with playback of some Youtube videos. Approved for 68.3esr.

Comment 35

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr68/rev/fc92c73816af
https://hg.mozilla.org/releases/mozilla-esr68/rev/f637cbfabf00

Comment 36

[Daniel Bodea [:danibodea]]

According to the status of the tracking flags, this bug should be fixed in Nightly 72, Beta 71, and ESR 68, but the results show otherwise. A more detailed testing procedure may be needed. I will post screenshots of each channel with the video about 20 sec in with the nerd stats displayed.

Comment 37

[Daniel Bodea [:danibodea]]

Attachment: nigholdaffected.png

This is Nightly v71.0a1 (2019-09-05), the nightly build of the date when it was reported, so it should be an affected build.

797 dropped / 1234

Comment 38

[Daniel Bodea [:danibodea]]

Attachment: nighlastunafected.png

This is Nightly v72.0a1 (2019-11-25), the latest Nightly build available, so it should be an unaffected build.

462 dropped / 1224

Comment 39

[Daniel Bodea [:danibodea]]

Attachment: betafixed.png

This is Beta v71.0b12, the latest Beta build officially available, so it should be an unaffected build.

434 dropped / 1236

Comment 40

[Daniel Bodea [:danibodea]]

Attachment: rellastseriouslyunafected.png

This is Release v70.0.1, the latest Release build officially available, so it should be an affected build. It definitely is not.

2 dropped / 1651

Comment 41

[Daniel Bodea [:danibodea]]

Attachment: esrlastseriouslyunafected.png

This is ESR v68.2.0esr, the latest ESR build officially available, it should be an unaffected build, since the push isn't in the last ESR version yet.

19 dropped / 1592

Comment 42

[Daniel Bodea [:danibodea]]

I followed the steps in comment 0. Is there a better way to verify this bug? How should I proceed?

Comment 43

[Alastor Wu [:alwu]]

Which platform were you testing on? I've tried to use Nightly and Beta on OSX and Windows, they both worked well.

I didn't see the dropped frame in [1] (only 2 frames, which happened when the Firefox info panel showed up), I've played both 720p60 and 1080p60 video and the dropped frame amount were both nearly to zero.

The way I tried is simple change the playback speed to 1.5x or 2x, when playing 720p60 or 1080p60.

[1]
Nightly https://drive.google.com/file/d/1pNXU7pT_invxP6APh9FtT9cye7nYj-sj/view?usp=sharing
Beta https://drive.google.com/file/d/1pC3GQ8sAZ0uAZpnbYgZxY8oVdfqjcqHO/view?usp=sharing

Comment 44

[Daniel Bodea [:danibodea]]

I tested on Windows 10 x64 and these are my exact steps:

1. Opened browser.
2. Loaded the Youtube link.
3. During the ad, I would open the video in theatre mode (not default mode, not full screen).
4. During the start of the video, I would set the video quality to 1080p60.
5. Then I would set the video speed to 2x.
6. I would open the "nerd stats".
7. I would leave the video to run until the first 20-25 seconds, pause it and print screen.

I have noticed that going full-screen and/or exiting full-screen would drop a lot of frames at once, the reason why I avoided changing video size during playback, but many frames were consistently dropped while using those steps. What are you doing differently?

However, I have retested today on the same machine (Windows 10) and the dropped frames were close to zero after using the exact same steps on all the versions (+ ESR v68.3.0esr), except the old affected nightly which had about 15 dropped frames in 1000 (not much). It appears it is definitely related to the hardware or resources used at a certain time on the current running machine. Also tested in Mac OS with similar results.

In conclusion, the provided steps to reproduce might not be good to verify the implementation well enough, but SOME improvements were observed so I will consider them decent. I will consider this fix verified, but please add feedback if you consider more testing is needed or a new bug needs logging.