androidx / media

Jetpack Media3 support libraries for media use cases, including ExoPlayer, an extensible media player for Android
https://developer.android.com/media/media3
Apache License 2.0
1.71k stars 411 forks source link

Adding `player#setVideoEffect(emptyList())` workaround causes hevc video to be stuck #1630

Open how8570 opened 3 months ago

how8570 commented 3 months ago

Version

Media3 1.4.0

More version details

commit hash: b01c6ffcb3fca3d038476dab5d3bc9c9f2010781

Devices that reproduce the issue

Sony BRAVIA device build-in Android 9

Devices that do not reproduce the issue

CCwGTV

Reproducible in the demo app?

Yes

Reproduction steps

This is a workaround from https://github.com/google/ExoPlayer/issues/11038

This can be reproduce on demo app.

  1. Add the lib-effect dependency to build.gradle (:demo). image

  2. Add player.setVideoEffects(new ArrayList<>()); to PlayerActivity#initializePlayer(). image

  3. Build the demo app and select any H.265 codec video to play. (Here, I selected clear dash HD (mp4, H.265)).

  4. Observe the issue.

Expected result

play correctly, each frame correct and player will stop(ended) when content finish.

Actual result

PlayerView frame display stucked, but (progress bar time /upper log rb:<value>) keep growing.

When Play to end, the progress bar time still go over (e.g. timer display will show 13:38-12:14, even video only got 12m14s) image

Media

demo app clear dash HD (mp4, H.265)

Bug Report

claincly commented 3 months ago

Hmm I cannot reproduce locally, can you try turn on the DebugTraceUtil, capture the log and report it here?

https://github.com/androidx/media/blob/b01c6ffcb3fca3d038476dab5d3bc9c9f2010781/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java#L57

how8570 commented 3 months ago

After turning on DebugTraceUtil (setting enableTracing to true), the issue with clear dash HD (MP4, H265) is hard to reproduce. 🤔

However, the issue with UHD (MP4, H265) can still be reproduced.

Here's the bugreport: bugreport-BRAVIA_ATV2_TW-PTT1.190515.001.S38-2024-08-20-10-55-17.zip

Here's the partial logcat: filter_package_logcat.txt

The issue happened around 10:58:40. It seems that the system was performing GC at that time. I'm not sure if the issue is related to the GC. 🤔


I have another question: Should I provide an adb bugreport, or is it enough to just paste the logcat dump? With package filter (androidx.media3.demo.main) or full dump? There lots MtkOmxVenc or other seems not relative log in logcat if without filter, I'm not really sure which one better.

how8570 commented 3 months ago

Back to the old issue google/ExoPlayer#11038

I tested the old app that was provided earlier, which would cause the content to go in the wrong orination (the version without the workaround applied), and the expected direction error occurred.

I noticed something strange: when using the Running Devices function in Android Studio to mirror the TV, the content orientation appears correctly on the IDE, but the real device display content in wrong orientation. 🤔

claincly commented 3 months ago

I'm not sure how the old issue is related, it seems this issue is about the video didn't end at the correct moment?

Also I didn't see the DebugTrace in the log - maybe you didn't call the method to generate the trace string and log it? (The method to call is here)

https://github.com/androidx/media/blob/b01c6ffcb3fca3d038476dab5d3bc9c9f2010781/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java#L323

Note though android Log has a line limit, so you need to break the line down and you could use this code snippet to do it

public static List<String> breakString(String longString, int x) {
    List<String> substrings = new ArrayList<>();
    int length = longString.length();
    for (int start = 0; start < length; start += x) {
        int end = Math.min(start + x, length);
        substrings.add(longString.substring(start, end));
    }
    return substrings;
}
how8570 commented 3 months ago

So, should I call generateTraceSummary() then logging strings to somewhere them provide it? I'm not sure what you mean call the method to generate the trace string and log it and where to insert this part of code. 🤔

Did you mean call this after issue happend, then print it out?

If so, I can return to a reproducible environment in about 12 hours to prepare these.

claincly commented 3 months ago

So, should I call generateTraceSummary() then logging strings to somewhere them provide it?

Yes, it's not automatically logged. I think you can call it when you exit the PlayerView, maybe onDestroy()?

No rush!

how8570 commented 3 months ago

I put it on onDestroy(), here is what I get

when issue occur(video stuck on some frame), press back leave activity immediately.

generateTraceSummary() log 1 ```json { "AssetLoader": { "InputFormat": "No events", "OutputFormat": "No events" }, "AudioDecoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "AudioGraph": { "RegisterNewInputStream": "No events", "OutputEnded": "No events" }, "AudioMixer": { "RegisterNewInputStream": "No events", "OutputFormat": "No events", "ProducedOutput": "No events" }, "AudioEncoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "VideoDecoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "VFP": { "RegisterNewInputStream": { "count": 5, "first": [ "0us@0ms(InputType Surface - 640x284)", "0us@13973ms(InputType Surface - 1280x570)", "0us@14788ms(InputType Surface - 1280x570)", "0us@25680ms(InputType Surface - 1920x856)", "0us@26526ms(InputType Surface - 1920x856)" ] }, "SurfaceTextureInput": { "count": 10505, "first": [ "UNSET@657ms", "UNSET@693ms", "UNSET@1476ms", "UNSET@1527ms", "UNSET@1613ms", "UNSET@1656ms", "UNSET@1755ms", "UNSET@1782ms", "UNSET@1871ms", "UNSET@1939ms" ], "last": [ "UNSET@446147ms", "UNSET@446427ms", "UNSET@446450ms", "UNSET@446522ms", "UNSET@446544ms", "UNSET@446560ms", "UNSET@446634ms", "UNSET@446684ms", "UNSET@446726ms", "UNSET@446957ms" ] }, "QueueFrame": { "count": 10504, "first": [ "1000000083333us@686ms", "1000000125000us@1007ms", "1000000166666us@1513ms", "1000000208333us@1588ms", "1000000250000us@1650ms", "1000000291666us@1739ms", "1000000333333us@1766ms", "1000000375000us@1863ms", "1000000416666us@1920ms", "1000000458333us@1970ms" ], "last": [ "1000444666666us@446154ms", "1000444708333us@446433ms", "1000444750000us@446501ms", "1000444791666us@446527ms", "1000444833333us@446552ms", "1000444875000us@446626ms", "1000444916666us@446669ms", "1000444958333us@446703ms", "1000445000000us@446803ms", "1000445041666us@446960ms" ] }, "QueueBitmap": "No events", "QueueTexture": "No events", "RenderedToOutputSurface": { "count": 8075, "first": [ "1000000083333us@1002ms", "1000000125000us@1475ms", "1000000166666us@1578ms", "1000000250000us@1703ms", "1000000333333us@1822ms", "1000000416666us@1964ms", "1000000541666us@2103ms", "1000000625000us@2225ms", "1000000708333us@2360ms", "1000000791666us@2466ms" ], "last": [ "1000444375000us@445218ms", "1000444416666us@445263ms", "1000444458333us@445323ms", "1000444500000us@445359ms", "1000444583333us@445537ms", "1000444625000us@445743ms", "1000444666666us@446185ms", "1000444708333us@446497ms", "1000444833333us@446623ms", "1000444958333us@446792ms" ] }, "OutputTextureRendered": "No events", "ReceiveEndOfAllInput": "No events", "SignalEnded": "No events" }, "ExternalTextureManager": { "SignalEOS": { "count": 4, "first": [ "EOS@13980ms", "EOS@14791ms", "EOS@25713ms", "EOS@26532ms" ] }, "SurfaceTextureTransformFix": "No events" }, "BitmapTextureManager": { "SignalEOS": "No events" }, "TexIdTextureManager": { "SignalEOS": "No events" }, "Compositor": { "OutputTextureRendered": "No events" }, "VideoEncoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "Muxer": { "InputFormat": "No events", "CanWriteSample": "No events", "AcceptedInput": "No events", "InputEnded": "No events", "OutputEnded": "No events" } }{ "AssetLoader": { "InputFormat": "No events", "OutputFormat": "No events" }, "AudioDecoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "AudioGraph": { "RegisterNewInputStream": "No events", "OutputEnded": "No events" }, "AudioMixer": { "RegisterNewInputStream": "No events", "OutputFormat": "No events", "ProducedOutput": "No events" }, "AudioEncoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "VideoDecoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "VFP": { "RegisterNewInputStream": { "count": 6, "first": [ "0us@0ms(InputType Surface - 640x284)", "0us@13973ms(InputType Surface - 1280x570)", "0us@14788ms(InputType Surface - 1280x570)", "0us@25680ms(InputType Surface - 1920x856)", "0us@26526ms(InputType Surface - 1920x856)", "0us@508193ms(InputType Surface - 3840x1714)" ] }, "SurfaceTextureInput": { "count": 12274, "first": [ "UNSET@657ms", "UNSET@693ms", "UNSET@1476ms", "UNSET@1527ms", "UNSET@1613ms", "UNSET@1656ms", "UNSET@1755ms", "UNSET@1782ms", "UNSET@1871ms", "UNSET@1939ms" ], "last": [ "UNSET@612724ms", "UNSET@612769ms", "UNSET@612825ms", "UNSET@612863ms", "UNSET@612903ms", "UNSET@612957ms", "UNSET@612997ms", "UNSET@613039ms", "UNSET@613086ms", "UNSET@613151ms" ] }, "QueueFrame": { "count": 12273, "first": [ "1000000083333us@686ms", "1000000125000us@1007ms", "1000000166666us@1513ms", "1000000208333us@1588ms", "1000000250000us@1650ms", "1000000291666us@1739ms", "1000000333333us@1766ms", "1000000375000us@1863ms", "1000000416666us@1920ms", "1000000458333us@1970ms" ], "last": [ "1000100458333us@612764ms", "1000100500000us@612802ms", "1000100541666us@612855ms", "1000100583333us@612895ms", "1000100625000us@612936ms", "1000100666666us@612988ms", "1000100708333us@613033ms", "1000100750000us@613080ms", "1000100791666us@613136ms", "1000100833333us@613189ms" ] }, "QueueBitmap": "No events", "QueueTexture": "No events", "RenderedToOutputSurface": { "count": 8874, "first": [ "1000000083333us@1002ms", "1000000125000us@1475ms", "1000000166666us@1578ms", "1000000250000us@1703ms", "1000000333333us@1822ms", "1000000416666us@1964ms", "1000000541666us@2103ms", "1000000625000us@2225ms", "1000000708333us@2360ms", "1000000791666us@2466ms" ], "last": [ "1000099875000us@612076ms", "1000100000000us@612213ms", "1000100125000us@612338ms", "1000100250000us@612499ms", "1000100333333us@612620ms", "1000100416666us@612724ms", "1000100500000us@612825ms", "1000100625000us@612956ms", "1000100750000us@613096ms", "1000100833333us@613220ms" ] }, "OutputTextureRendered": "No events", "ReceiveEndOfAllInput": "No events", "SignalEnded": "No events" }, "ExternalTextureManager": { "SignalEOS": { "count": 4, "first": [ "EOS@13980ms", "EOS@14791ms", "EOS@25713ms", "EOS@26532ms" ] }, "SurfaceTextureTransformFix": "No events" }, "BitmapTextureManager": { "SignalEOS": "No events" }, "TexIdTextureManager": { "SignalEOS": "No events" }, "Compositor": { "OutputTextureRendered": "No events" }, "VideoEncoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "Muxer": { "InputFormat": "No events", "CanWriteSample": "No events", "AcceptedInput": "No events", "InputEnded": "No events", "OutputEnded": "No events" } } ```

when issue occur(video stuck on some frame), Let it keep playing until the timer displays a time that exceeds the video length Then press back leave activity to log.

generateTraceSummary() log 2 ```json { "AssetLoader": { "InputFormat": "No events", "OutputFormat": "No events" }, "AudioDecoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "AudioGraph": { "RegisterNewInputStream": "No events", "OutputEnded": "No events" }, "AudioMixer": { "RegisterNewInputStream": "No events", "OutputFormat": "No events", "ProducedOutput": "No events" }, "AudioEncoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "VideoDecoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "VFP": { "RegisterNewInputStream": { "count": 12, "first": [ "0us@0ms(InputType Surface - 640x284)", "0us@13973ms(InputType Surface - 1280x570)", "0us@14788ms(InputType Surface - 1280x570)", "0us@25680ms(InputType Surface - 1920x856)", "0us@26526ms(InputType Surface - 1920x856)", "0us@508193ms(InputType Surface - 3840x1714)", "0us@940848ms(InputType Surface - 1920x856)", "0us@964484ms(InputType Surface - 1280x570)", "0us@965004ms(InputType Surface - 1280x570)", "0us@976441ms(InputType Surface - 1920x856)" ], "last": [ "0us@977071ms(InputType Surface - 1920x856)", "0us@1318705ms(InputType Surface - 3840x1714)" ] }, "SurfaceTextureInput": { "count": 14800, "first": [ "UNSET@657ms", "UNSET@693ms", "UNSET@1476ms", "UNSET@1527ms", "UNSET@1613ms", "UNSET@1656ms", "UNSET@1755ms", "UNSET@1782ms", "UNSET@1871ms", "UNSET@1939ms" ], "last": [ "UNSET@1340134ms", "UNSET@1340176ms", "UNSET@1340246ms", "UNSET@1340302ms", "UNSET@1340366ms", "UNSET@1340412ms", "UNSET@1340472ms", "UNSET@1340527ms", "UNSET@1340586ms", "UNSET@1340635ms" ] }, "QueueFrame": { "count": 14798, "first": [ "1000000083333us@686ms", "1000000125000us@1007ms", "1000000166666us@1513ms", "1000000208333us@1588ms", "1000000250000us@1650ms", "1000000291666us@1739ms", "1000000333333us@1766ms", "1000000375000us@1863ms", "1000000416666us@1920ms", "1000000458333us@1970ms" ], "last": [ "1000016500000us@1340166ms", "1000016541666us@1340222ms", "1000016583333us@1340283ms", "1000016625000us@1340338ms", "1000016666666us@1340398ms", "1000016708333us@1340448ms", "1000016750000us@1340509ms", "1000016791666us@1340570ms", "1000016833333us@1340629ms", "1000016875000us@1340684ms" ] }, "QueueBitmap": "No events", "QueueTexture": "No events", "RenderedToOutputSurface": { "count": 10632, "first": [ "1000000083333us@1002ms", "1000000125000us@1475ms", "1000000166666us@1578ms", "1000000250000us@1703ms", "1000000333333us@1822ms", "1000000416666us@1964ms", "1000000541666us@2103ms", "1000000625000us@2225ms", "1000000708333us@2360ms", "1000000791666us@2466ms" ], "last": [ "1000016166666us@1339661ms", "1000016208333us@1339765ms", "1000016291666us@1339864ms", "1000016375000us@1340015ms", "1000016458333us@1340133ms", "1000016541666us@1340246ms", "1000016625000us@1340365ms", "1000016708333us@1340472ms", "1000016791666us@1340586ms", "1000016875000us@1340719ms" ] }, "OutputTextureRendered": "No events", "ReceiveEndOfAllInput": "No events", "SignalEnded": "No events" }, "ExternalTextureManager": { "SignalEOS": { "count": 8, "first": [ "EOS@13980ms", "EOS@14791ms", "EOS@25713ms", "EOS@26532ms", "EOS@964491ms", "EOS@965047ms", "EOS@976471ms", "EOS@977076ms" ] }, "SurfaceTextureTransformFix": "No events" }, "BitmapTextureManager": { "SignalEOS": "No events" }, "TexIdTextureManager": { "SignalEOS": "No events" }, "Compositor": { "OutputTextureRendered": "No events" }, "VideoEncoder": { "InputFormat": "No events", "OutputFormat": "No events", "AcceptedInput": "No events", "ProducedOutput": "No events", "InputEnded": "No events", "OutputEnded": "No events" }, "Muxer": { "InputFormat": "No events", "CanWriteSample": "No events", "AcceptedInput": "No events", "InputEnded": "No events", "OutputEnded": "No events" } } ```
claincly commented 2 months ago

Ah I wonder if you are using an adaptive stream? We have not extensively tested player.setVideoEffects() with adaptive streams, but I'll take a closer look.

Also I noticed the stream adaptation occurred more (by looking at RegisterNewInputStream), any idea why that's the case? Maybe just network issues?

claincly commented 2 months ago

Could you confirm that the isLastBuffer is set to true on your last sample?

https://github.com/androidx/media/blob/b01c6ffcb3fca3d038476dab5d3bc9c9f2010781/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/video/MediaCodecVideoRenderer.java#L1339

how8570 commented 2 months ago

I'm not sure if the demo is using adaptive stream or not. (Clear Dash UHD (mp4, H.265))

But I replaced the mediaItems in PlayerActivity.java initializePlayer() like this, and I can still reproduce the issue.

image

"https://www.libde265.org/hevc-bitstreams/bbb-1280x720-cfg02.mkv"
"https://www.libde265.org/hevc-bitstreams/tos-1720x720-cfg01.mkv"

It seems that whether it's an adaptive stream or not might not be very relevant. 🤔 Only need a HEVC video?

how8570 commented 2 months ago

I also tried simply adding log isLastBuffer in processOutputBuffer(...) image

Then check the log, it seems it has not been set to true. Last log still isLastBuffer: false


And I also found that when the playback time exceeds the video duration, processOutputBuffer(...) still being called even I click the pause.

Then, when clicking seek backward and then clicking play, isLastBuffer turns true. I guess processOutputBuffer(...) has been called somewhere too many times, causing the issue? 🤔

claincly commented 2 months ago

Clear Dash UHD (mp4, H.265)

This one is an adaptive stream - meaning the resolution could switch during playback, as you can see from the log.

Then check the log, it seems it has not been set to true.

I think this might be an extractor/decoder issue then rather than a video frame processing issue. It seems the problem is the decoder/extractor didn't mark the last frame in the file as the last one. But before I can be 100% sure, could you double check this only happens when you use setVideoEffects()?

processOutputBuffer() has been called somewhere too many times, causing the issue?

It actually can be called multiple times on one buffer before that buffer is fully processed. So the fact that it is called multiple times doesn't necessarily mean there's a problem in there

how8570 commented 2 months ago

Okay, I will test without setVideoEffects() when I get back to the place where I can reproduce the issue.

sorry this comment make the bot update labels

how8570 commented 2 months ago

I tried 5-7 times to play the whole video through.

Unfortunately, after I removed setVideoEffects(), I can no longer reproduce the issue. 😢 isLastBuffer is set to true correctly, and generateTraceSummary() gives all fields "No events".

And also tried on main branch(b95b534f), got the same result.

Any other idea or some change wanna try?

claincly commented 2 months ago

generateTraceSummary() gives all fields "No events".

This is expected - it only works when effects are used.

isLastBuffer is set to true correctly

This is very strange - it should be set regardless of video effects, let me try to see if something's obviously wrong, but I'm very surprised to see this.