1716196 - Misleading log message: "AppleVTDecoder: system doesn't support hardware acceleration"

Status: RESOLVED FIXED

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

Description

[ptrbrzozowski]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:89.0) Gecko/20100101 Firefox/89.0

Steps to reproduce:

Play any 1080p/4k video on youtube, I used: https://www.youtube.com/watch?v=LXb3EKWsInQ

Actual results:

Firefox will start draining significiant ammount of energy (>25 in Activity Monitor->Energy) and CPU usage will rise to 30-35%.

Running Firefox from terminal with MOZ_LOG="PlatformDecoderModule:5" gives the following output:

[snip]
[RDD 38920: MediaSupervisor #1]: D/PlatformDecoderModule AppleVTDecoder[108c88580] Creating AppleVTDecoder for 1920x1080 VP9 video
[RDD 38920: MediaPDecoder #1]: D/PlatformDecoderModule AppleVTDecoder[108c88580] AppleVTDecoder: system doesn't support hardware acceleration
[RDD 38920: MediaPDecoder #1]: D/PlatformDecoderModule AppleVTDecoder[108c88580] AppleVTDecoder: not using hardware accelerated decoding
[RDD 38920: MediaPDecoder #1]: D/PlatformDecoderModule AppleVTDecoder[108c88580] mp4 input sample 108cb65c0 pts 0 duration 17000 us keyframe 126547 bytes
[RDD 38920: Unnamed thread 108b72490]: D/PlatformDecoderModule AppleVTDecoder[108c88580] AppleVideoDecoder PlatformCallback status 0 flags 5
[RDD 38920: Unnamed thread 108b72490]: D/PlatformDecoderModule AppleVTDecoder[108c88580] mp4 output frame 126794 dts 0 pts 0 duration 17000 us keyframe
[RDD 38920: Unnamed thread 108b72490]: D/PlatformDecoderModule AppleVTDecoder[108c88580] 0 decoded frames queued
[RDD 38920: MediaPDecoder #3]: D/PlatformDecoderModule AppleVTDecoder[108c88580] ProcessShutdown: cleaning up session 108b35e40
[RDD 38920: MediaPDecoder #3]: D/PlatformDecoderModule AppleVTDecoder[108c88580] ProcessShutdown: releasing format 108d1dcf0
[Child 38898: MediaSupervisor #1]: D/PlatformDecoderModule Sandbox RDD decoder supports requested type
[Child 38898: MediaSupervisor #1]: D/PlatformDecoderModule Sandbox RDD decoder supports requested type
[RDD 38920: MediaSupervisor #1]: D/PlatformDecoderModule Agnostic decoder supports requested type
[RDD 38920: MediaSupervisor #1]: D/PlatformDecoderModule Agnostic decoder supports requested type
[RDD 38920: MediaSupervisor #1]: D/PlatformDecoderModule AppleVTDecoder[108c88e80] Creating AppleVTDecoder for 1920x1080 VP9 video
[Child 38898: MediaPDecoder #1]: D/PlatformDecoderModule AudioTrimmer[1106a7e20] ::PrepareTrimmers: sample[0,21000] no trimming information
[RDD 38920: MediaPDecoder #2]: D/PlatformDecoderModule OpusDataDecoder[108cb4540] ::Decode: Opus decoder skipping 312 of 960 frames
[Child 38898: MediaPDecoder #2]: D/PlatformDecoderModule AudioTrimmer[1106a7e20] ::HandleDecodedResult: sample[0,21000] (decoded[0,13500] no trimming needed
[RDD 38920: MediaPDecoder #1]: D/PlatformDecoderModule AppleVTDecoder[108c88e80] AppleVTDecoder: system doesn't support hardware acceleration
[RDD 38920: MediaPDecoder #1]: D/PlatformDecoderModule AppleVTDecoder[108c88e80] AppleVTDecoder: not using hardware accelerated decoding
[snip]

Entire log here: https://hastebin.com/hadobimati.md

Expected results:

CPU and energy usage should be lower - the same video under MS Edge (v91, arm64) plays back at <20% CPU and energy drain at an average of 2.0-3.0.

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

The Bugbug bot thinks this bug should belong to the 'Core::Audio/Video: Playback' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Comment 2

[Matthew Gregan [:kinetik]]

I wonder if the AppleVTDecoder: system doesn't support hardware acceleration log message is misleading on macOS 11/M1 - bug 1679356 comment 2 claims "kVTDecompressionPropertyKey_UsingHardwareAcceleratedVideoDecoder always returns false" and the code is querying that flag where the log message is emitted. Logging rv from VTSessionCopyProperty in a local build, I get kVTPropertyNotSupportedErr.

Idle CPU in Chrome and Safari are around 85-90% playing this video at 4k (not quite apples to apples, since they're using the HDR version) and around 80% in Firefox. If I set media.hardware-video-decoding.enabled to false in about:config, restart Firefox and reload the linked 4k video, CPU use is significantly higher (idle drops to ~65%).

Comment 3

[ptrbrzozowski]

OK, what about Activity Monitor's energy usage stats? Is that some sort of "misreport" as well?

Thanks.

Comment 4

[Matthew Gregan [:kinetik]]

(In reply to ptrbrzozowski from comment #3)

OK, what about Activity Monitor's energy usage stats?

I see similar results to you. I don't know how that figure is calculated, so can't add much more.

Using powermetrics and watching the Package Power (total SoC power, if I understand correctly) while watching a downloaded copy of the linked 4k video (vp9 SDR version) shows, approximately: 290mW for Safari, 700mW for Firefox Nightly, 4400mW for Firefox Nightly with media.hardware-video-decoding.enabled disabled, 600mW for Chrome, and 5900mW for Chrome with Hardware-accelerated video decode disabled in chrome://flags.

That seems to suggest that Firefox is using HW accelerated decoding, despite the log message suggesting otherwise. There's still obvious energy use differences between browsers. Bug 1696107 looks related, and may explain some of that delta.

Comment 5

[ptrbrzozowski]

Thanks for your input. Considering the above, both issues seem more like a misreport (coming from Firefox - regarding HW decoding and Activity Monitor - regarding power usage) than bugs, correct?
If so, feel free to close this bug report.

Comment 6

[Jon Bauman [:jbauman:]]

I do think we should fix the misleading log message if possible, so I'm re-titling the issue. Thanks for the report, ptrbrzozowski

Comment 7

[Jon Bauman [:jbauman:]]

Given these logs:

[RDD 38920: MediaPDecoder #1]: D/PlatformDecoderModule AppleVTDecoder[108c88580] AppleVTDecoder: system doesn't support hardware acceleration
[RDD 38920: MediaPDecoder #1]: D/PlatformDecoderModule AppleVTDecoder[108c88580] AppleVTDecoder: not using hardware accelerated decoding

Looking a little more closely at the logging code:

  CFBooleanRef isUsingHW = nullptr;
  rv = VTSessionCopyProperty(
      mSession,
      kVTDecompressionPropertyKey_UsingHardwareAcceleratedVideoDecoder,
      kCFAllocatorDefault, &isUsingHW);
  if (rv != noErr) {
    LOG("AppleVTDecoder: system doesn't support hardware acceleration");
  }
  mIsHardwareAccelerated = rv == noErr && isUsingHW == kCFBooleanTrue;
  LOG("AppleVTDecoder: %s hardware accelerated decoding",
      mIsHardwareAccelerated ? "using" : "not using");

The log message "AppleVTDecoder: system doesn't support hardware acceleration" implies that the VTSessionCopyProperty() call wasn't successful, so we shouldn't expect to get any information out of isUsingHW. I'm not sure why the call is failing, but at least we can make the logging more informative.

Comment 8

[Jon Bauman [:jbauman:]]

Attachment: Bug 1716196 - Misleading log message: "AppleVTDecoder: system doesn't support hardware acceleration". r=jolin

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9317e6a8cf03
Misleading log message: "AppleVTDecoder: system doesn't support hardware acceleration". r=jolin

Comment 10

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/9317e6a8cf03