Closed Bug 1579127 Opened 7 months ago Closed 6 months ago

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

Categories

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

Unspecified
All
defect

Tracking

()

VERIFIED FIXED
mozilla71
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- verified
firefox69 --- wontfix
firefox70 + wontfix
firefox71 --- verified
firefox72 --- verified

People

(Reporter: yoasif, Assigned: alwu)

References

(Regression, )

Details

(Keywords: regression, Whiteboard: [sci-exclude])

Attachments

(13 files)

Attached image 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.

Attached file mozregression-log.txt
Has Regression Range: --- → yes
Has STR: --- → yes
Keywords: regression

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

Flags: needinfo?(yoasif)

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

(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

Duplicate of this bug: 1579842
Priority: -- → P2

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.

NI myself for further investigation.

Flags: needinfo?(alwu)

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

Flags: needinfo?(jyavenard)
Regressed by: 1480190

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

Flags: needinfo?(alwu)
Whiteboard: [sci-exclude]

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.

Flags: needinfo?(matt.woodrow)

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

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.

Flags: needinfo?(matt.woodrow)

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.

Assignee: nobody → alwu

This is what Chrome does too.

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

Flags: needinfo?(jyavenard)

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

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.

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.

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.

Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/348fa5ed7407
only count the frame dropping due to system overload. r=mattwoodrow

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)

Flags: needinfo?(alwu)

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.

Flags: needinfo?(alwu)
Attachment #9098460 - Attachment description: Bug 1579127 - part2 : always ensure that we store value from non-null timestamp. → Bug 1579127 - part2 : always present a valid timestamp on image.
Pushed by alwu@mozilla.com:
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
Status: NEW → RESOLVED
Closed: 6 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla71

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.

Flags: qe-verify+

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

Flags: needinfo?(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.

Flags: needinfo?(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
  1. It only takes effect when user is playing 60+ frame rate video
  • String or UUID changes made by this patch: no
Attachment #9093460 - Flags: approval-mozilla-esr68?
Attachment #9098460 - Flags: approval-mozilla-esr68?
QA Whiteboard: [qa-triaged]

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.

Attachment #9093460 - Flags: approval-mozilla-esr68? → approval-mozilla-esr68+
Attachment #9098460 - Flags: approval-mozilla-esr68? → approval-mozilla-esr68+

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.

Attached image 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

Attached image 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

Attached image betafixed.png

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

434 dropped / 1236

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

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

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

Flags: needinfo?(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

Flags: needinfo?(alwu)

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.

Status: RESOLVED → VERIFIED
Flags: qe-verify+
You need to log in before you can comment on or make changes to this bug.