search

google / ExoPlayer

This project is deprecated and stale. The latest ExoPlayer code is available in https://github.com/androidx/media
https://developer.android.com/media/media3/exoplayer
Apache License 2.0
21.72k stars 6.02k forks source link

TS stream don't start playing automatically #10035

Open skogl opened 2 years ago

skogl commented 2 years ago

My issue is that I feel that some mpeg-ts streams don't start playing automatically. The stream source is terrestrial dvb-t2 so I imagine that there are some noise in the stream which makes it unable to start.

I have tested this in the demo player in version 2.16.1 and the issue can be resolved by just fast forward and then the stream starts playing again. I haven't found any similar issues to this so that's why I'm filing this issue.

Here's the log output:

2022-03-08 14:15:31.036 3822-3963/? I/MitvPolicyDatabaseManager: updatePackageUsage com.google.android.exoplayer2.demo/com.google.android.exoplayer2.demo.SampleChooserActivity (0,1,55)
2022-03-08 14:15:31.106 3822-3822/? D/MiTv-Service-TvService-Parent: current foreground packagename is com.google.android.exoplayer2.demo
2022-03-08 14:15:31.113 12016-12016/com.google.android.exoplayer2.demo W/ActivityThread: handleWindowVisibility: no activity for token android.os.BinderProxy@f80037
2022-03-08 14:15:31.800 12016-12016/com.google.android.exoplayer2.demo I/DefaultRenderersFactory: Loaded LibvpxVideoRenderer.
2022-03-08 14:15:31.801 12016-12016/com.google.android.exoplayer2.demo I/DefaultRenderersFactory: Loaded Libgav1VideoRenderer.
2022-03-08 14:15:31.815 12016-12016/com.google.android.exoplayer2.demo I/DefaultRenderersFactory: Loaded LibopusAudioRenderer.
2022-03-08 14:15:31.817 12016-12016/com.google.android.exoplayer2.demo I/DefaultRenderersFactory: Loaded LibflacAudioRenderer.
2022-03-08 14:15:31.817 12016-12016/com.google.android.exoplayer2.demo I/DefaultRenderersFactory: Loaded FfmpegAudioRenderer.
2022-03-08 14:15:31.822 12016-12016/com.google.android.exoplayer2.demo I/ExoPlayerImpl: Init 6606001 [ExoPlayerLib/2.16.1] [aquaman, MiTV-AESP0, Xiaomi, 28]
2022-03-08 14:15:31.910 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: playWhenReady [eventTime=0.01, mediaPos=0.00, window=0, true, USER_REQUEST]
2022-03-08 14:15:31.950 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: timeline [eventTime=0.05, mediaPos=0.00, window=0, periodCount=1, windowCount=1, reason=PLAYLIST_CHANGED
2022-03-08 14:15:31.950 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   period [?]
2022-03-08 14:15:31.951 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   window [?, seekable=false, dynamic=true]
2022-03-08 14:15:31.951 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: ]
2022-03-08 14:15:31.954 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: mediaItem [eventTime=0.05, mediaPos=0.00, window=0, reason=PLAYLIST_CHANGED]
2022-03-08 14:15:31.961 3187-3380/? I/MediaFocusControl: requestAudioFocus() from uid/pid 10137/12016 clientId=android.media.AudioManager@5fee3aacom.google.android.exoplayer2.AudioFocusManager$AudioFocusListener@25c494 callingPack=com.google.android.exoplayer2.demo req=1 flags=0x0 sdk=29
2022-03-08 14:15:31.971 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: state [eventTime=0.07, mediaPos=0.00, window=0, BUFFERING]
2022-03-08 14:15:32.017 12016-12016/com.google.android.exoplayer2.demo I/Choreographer: Skipped 54 frames!  The application may be doing too much work on its main thread.
2022-03-08 14:15:32.029 12016-12169/com.google.android.exoplayer2.demo I/OpenGLRenderer: Davey! duration=921ms; Flags=0, IntendedVsync=132649314916314, Vsync=132650214916278, OldestInputEvent=9223372036854775807, NewestInputEvent=0, HandleInputStart=132650224842603, AnimationStart=132650224935437, PerformTraversalsStart=132650227151395, DrawStart=132650227380895, SyncQueued=132650228738312, SyncStart=132650228856604, IssueDrawCommandsStart=132650229016604, SwapBuffers=132650235484604, FrameCompleted=132650236928021, DequeueBufferDuration=441000, QueueBufferDuration=799000, 
2022-03-08 14:15:32.180 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: surfaceSize [eventTime=0.28, mediaPos=0.00, window=0, 1920, 1080]
2022-03-08 14:15:32.202 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: loading [eventTime=0.30, mediaPos=0.00, window=0, period=0, true]
2022-03-08 14:15:32.218 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: timeline [eventTime=0.31, mediaPos=0.00, window=0, period=0, periodCount=1, windowCount=1, reason=SOURCE_UPDATE
2022-03-08 14:15:32.219 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   period [?]
2022-03-08 14:15:32.219 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   window [?, seekable=false, dynamic=false]
2022-03-08 14:15:32.220 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: ]
2022-03-08 14:15:32.355 3187-3209/? I/ActivityManager: Displayed com.google.android.exoplayer2.demo/.PlayerActivity: +1s249ms
2022-03-08 14:15:32.411 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: timeline [eventTime=0.50, mediaPos=0.00, window=0, period=0, periodCount=1, windowCount=1, reason=SOURCE_UPDATE
2022-03-08 14:15:32.414 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   period [12.20]
2022-03-08 14:15:32.416 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   window [12.20, seekable=true, dynamic=false]
2022-03-08 14:15:32.417 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: ]
2022-03-08 14:15:32.508 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: videoEnabled [eventTime=0.60, mediaPos=0.00, window=0, period=0]
2022-03-08 14:15:32.513 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: audioEnabled [eventTime=0.61, mediaPos=0.00, window=0, period=0]
2022-03-08 14:15:32.541 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: tracks [eventTime=0.62, mediaPos=0.00, window=0, period=0
2022-03-08 14:15:32.542 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   MediaCodecVideoRenderer [
2022-03-08 14:15:32.542 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:     Group:0, adaptive_supported=N/A [
2022-03-08 14:15:32.543 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:       [X] Track:0, id=7560/7561, mimeType=video/avc, codecs=avc1.640028, res=1280x720, supported=YES
2022-03-08 14:15:32.544 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:     ]
2022-03-08 14:15:32.544 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   ]
2022-03-08 14:15:32.544 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   LibvpxVideoRenderer []
2022-03-08 14:15:32.545 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   Libgav1VideoRenderer []
2022-03-08 14:15:32.546 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   MediaCodecAudioRenderer []
2022-03-08 14:15:32.546 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   LibopusAudioRenderer []
2022-03-08 14:15:32.547 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   LibflacAudioRenderer []
2022-03-08 14:15:32.547 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   FfmpegAudioRenderer [
2022-03-08 14:15:32.548 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:     Group:0, adaptive_supported=N/A [
2022-03-08 14:15:32.549 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:       [X] Track:0, id=7560/7562, mimeType=audio/mpeg-L2, channels=2, sample_rate=48000, language=sv, supported=YES
2022-03-08 14:15:32.549 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:     ]
2022-03-08 14:15:32.549 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   ]
2022-03-08 14:15:32.550 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   TextRenderer []
2022-03-08 14:15:32.550 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   MetadataRenderer []
2022-03-08 14:15:32.551 12016-12016/com.google.android.exoplayer2.demo D/EventLogger:   CameraMotionRenderer []
2022-03-08 14:15:32.551 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: ]
2022-03-08 14:15:32.570 12016-12027/com.google.android.exoplayer2.demo I/exoplayer2.dem: Background concurrent copying GC freed 7289(714KB) AllocSpace objects, 24(1704KB) LOS objects, 25% free, 3MB/5MB, paused 265us total 185.961ms
2022-03-08 14:15:32.603 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: downstreamFormat [eventTime=0.70, mediaPos=0.00, window=0, period=0, id=7560/7561, mimeType=video/avc, codecs=avc1.640028, res=1280x720]
2022-03-08 14:15:32.614 12016-12538/com.google.android.exoplayer2.demo I/OMXClient: IOmx service obtained
2022-03-08 14:15:32.642 12016-12537/com.google.android.exoplayer2.demo D/SurfaceUtils: connecting to surface 0xcd6b5808, reason connectToSurface
2022-03-08 14:15:32.651 12016-12537/com.google.android.exoplayer2.demo I/MediaCodec: [OMX.amlogic.avc.decoder.awesome] setting surface generation to 12304393
2022-03-08 14:15:32.651 12016-12537/com.google.android.exoplayer2.demo D/SurfaceUtils: disconnecting from surface 0xcd6b5808, reason connectToSurface(reconnect)
2022-03-08 14:15:32.653 12016-12537/com.google.android.exoplayer2.demo D/SurfaceUtils: connecting to surface 0xcd6b5808, reason connectToSurface(reconnect)
2022-03-08 14:15:32.654 12016-12538/com.google.android.exoplayer2.demo I/AmAVUtils: AmAVUtils::getComponentRole isEncoder :0 mime:video/avc 
2022-03-08 14:15:32.654 12016-12538/com.google.android.exoplayer2.demo V/AVUtils: AVUtils::getComponentRole
2022-03-08 14:15:32.669 12016-12538/com.google.android.exoplayer2.demo E/ACodec: [OMX.amlogic.avc.decoder.awesome] setPortMode on output to DynamicANWBuffer failed w/ err -2147483648
2022-03-08 14:15:32.686 12016-12538/com.google.android.exoplayer2.demo I/AmAVUtils: AmAVUtils::isAudioExtendFormat input = video/avc
2022-03-08 14:15:32.687 12016-12538/com.google.android.exoplayer2.demo I/ACodec: codec does not support config priority (err -1010)
2022-03-08 14:15:32.732 12016-12538/com.google.android.exoplayer2.demo D/SurfaceUtils: disconnecting from surface 0xcd6b5808, reason setNativeWindowSizeFormatAndUsage
2022-03-08 14:15:32.732 12016-12538/com.google.android.exoplayer2.demo D/SurfaceUtils: connecting to surface 0xcd6b5808, reason setNativeWindowSizeFormatAndUsage
2022-03-08 14:15:32.733 12016-12538/com.google.android.exoplayer2.demo D/SurfaceUtils: set up nativeWindow 0xcd6b5808 for 1280x720, color 0x11, rotation 0, usage 0x402933
2022-03-08 14:15:32.804 12016-12139/com.google.android.exoplayer2.demo I/exoplayer2.dem: Waiting for a blocking GC ProfileSaver
2022-03-08 14:15:32.831 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: videoDecoderInitialized [eventTime=0.93, mediaPos=0.00, window=0, period=0, OMX.amlogic.avc.decoder.awesome]
2022-03-08 14:15:32.836 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: videoInputFormat [eventTime=0.93, mediaPos=0.00, window=0, period=0, id=7560/7561, mimeType=video/avc, codecs=avc1.640028, res=1280x720]
2022-03-08 14:15:32.839 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: downstreamFormat [eventTime=0.94, mediaPos=0.00, window=0, period=0, id=7560/7562, mimeType=audio/mpeg-L2, channels=2, sample_rate=48000, language=sv]
2022-03-08 14:15:32.889 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: audioDecoderInitialized [eventTime=0.99, mediaPos=-0.63, window=0, period=0, ffmpegLavc58.54.100-mp3]
2022-03-08 14:15:32.894 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: audioInputFormat [eventTime=0.99, mediaPos=-0.63, window=0, period=0, id=7560/7562, mimeType=audio/mpeg-L2, channels=2, sample_rate=48000, language=sv]
2022-03-08 14:15:32.967 12016-12027/com.google.android.exoplayer2.demo I/exoplayer2.dem: Background concurrent copying GC freed 12342(972KB) AllocSpace objects, 0(0B) LOS objects, 25% free, 6MB/8MB, paused 3.130ms total 210.652ms
2022-03-08 14:15:32.967 12016-12139/com.google.android.exoplayer2.demo I/exoplayer2.dem: WaitForGcToComplete blocked ProfileSaver on ProfileSaver for 163.517ms
2022-03-08 14:15:35.127 12016-12016/com.google.android.exoplayer2.demo D/EventLogger: loading [eventTime=3.22, mediaPos=-0.63, window=0, period=0, false]

When comparing against working streams what I can see is that "mediaPos" has negative values (mediaPos=-0.63). It seems like the player i stuck (or waiting for pos 0).

Like I said, the originating issue is probably noise in the stream but since there's no changing the input from a terrestrial signal I feel that Exoplayer needs to be stable enough to handle this and to be able to start anyway.

I have sent an email with a none-working stream to dev.exoplayer@gmail.com.

ojw28 commented 2 years ago

I think this happens when the first audio samples end up with negative timestamps. When this happens:

  1. The current audio playback position is allowed to step backwards, due to this workaround.
  2. In the video renderer, this line evaluates to false. This prevents the first video frame from ever being rendered, which then prevents playback from starting.

I can see there being multiple solutions to this:

  1. Stop ProgressiveMediaPeriod from outputting negative timestamp samples (or at least setting the isDecodeOnly flag on them). I think this is what happens if there's an explicit seek to t=0, which is why seeking to the start of the stream allows playback to start.
  2. Looking at the workaround in MediaCodecAudioRenderer and evaluating whether we still need it.
  3. Tweaking the condition in MediaCodecVideoRenderer.

Assigning for @tonihei , although it'll probably be some time before this issue is looked at in more detail.

Rudnev commented 2 years ago
  • The current audio playback position is allowed to step backwards, due to this workaround.
  • In the video renderer, this line evaluates to false. This prevents the first video frame from ever being rendered, which then prevents playback from starting.

I have the same issue, for example buffer.timeUs was 999999176000 and currentPositionUs was 1000000000000. What would be the best solution on the app side? I currently solved that with a background task that checks the player.getCurrentPosition() and calls player.seekTo(0) if the position is negative until the first frame has been rendered.

skogl commented 2 years ago
  1. Stop ProgressiveMediaPeriod from outputting negative timestamp samples (or at least setting the isDecodeOnly flag on them). I think this is what happens if there's an explicit seek to t=0, which is why seeking to the start of the stream allows playback to start.
  2. Looking at the workaround in MediaCodecAudioRenderer and evaluating whether we still need it.
  3. Tweaking the condition in MediaCodecVideoRenderer.

Not sure if these points are meant as internal or not? Point 2 and 3 require knowledge of the renderers that I don't have so there is no way for me to go in there and make changes that I feel comfortable with. Point 1 looks promising enough but I'm not sure if there's a simple way of overriding the ProgressiveMediaPeriod without having to make changes in the library itself? Is this also internal or is it something that I can try and modify myself?

I tested the workaround proposed by @Rudnev and it seem to work. A bit ugly I admit but then it's more ugly to be faced with a black screen when trying to start playback.

Rudnev commented 2 years ago

@skogl I tested another workaround, it doesn't require background task management, but I also do not have enough knowledge of the rendering pipeline to validate this solution:

public class AudioRenderer extends MediaCodecAudioRenderer {
    public AudioRenderer(
            Context context,
            MediaCodecAdapter.Factory codecAdapterFactory,
            MediaCodecSelector mediaCodecSelector,
            boolean enableDecoderFallback,
            @Nullable Handler eventHandler,
            @Nullable AudioRendererEventListener eventListener,
            AudioSink audioSink
    ) {
        super(
                context,
                codecAdapterFactory,
                mediaCodecSelector,
                enableDecoderFallback,
                eventHandler,
                eventListener,
                audioSink
        );
    }

    @Override
    protected void onQueueInputBuffer(DecoderInputBuffer buffer) {
        // TODO Workaround the issue https://github.com/google/ExoPlayer/issues/10035
        if (buffer.timeUs >= 1_000_000_000_000L) {
            super.onQueueInputBuffer(buffer);
        }
    }
}
public class RenderersFactory extends DefaultRenderersFactory {
    public RenderersFactory(Context context) {
        super(context);
    }

    @Override
    protected void buildAudioRenderers(
            Context context,
            @ExtensionRendererMode int extensionRendererMode,
            MediaCodecSelector mediaCodecSelector,
            boolean enableDecoderFallback,
            AudioSink audioSink,
            Handler eventHandler,
            AudioRendererEventListener eventListener,
            ArrayList<Renderer> out
    ) {
        out.add(new AudioRenderer(
                context,
                getCodecAdapterFactory(),
                mediaCodecSelector,
                enableDecoderFallback,
                eventHandler,
                eventListener,
                audioSink
        ));
        // Add extension renderers here
    }
}
ExoPlayer player = new ExoPlayer.Builder(context)
        .setRenderersFactory(new RenderersFactory(context))
        .build();

In my case it works (udp multicast), but it also looks ugly to me: Firstly I have no idea what the original workaround was made for, secondly I have no idea buffer.timeUs < 1_000_000_000_000L is this the expected value or not, and lastly, I don't like to inherit library classes. I think we should wait for a fix from @tonihei or someone else from the library developers.

skogl commented 2 years ago

Thanks @Rudnev but this workaround does not work for me. Buffer position does not seem to be the issue for me but player position. I use your first workaround but modified it to only check if player's currentPosition() is a negative value, and if so I immediately to a seekTo(0) which kicks off playback. I am not sure about the correlation of buffer vs position. Without knowing about your specific case it sounds feasable that buffer and position are different values. Maybe you have the same issue as me and that current position is just below zero?

Rudnev commented 2 years ago

I use your first workaround but modified it to only check if player's currentPosition() is a negative value, and if so I immediately to a seekTo(0) which kicks off playback.

On the next line after player.play()? At first I wanted to bind to events, but getCurrentPosition() will return 0 for a while. And often the first event where it goes negative is the end of loading (max buffer size reached). So I run a task right after player.play(), it checks the position every 2 seconds, calls seekTo(0) if necessary, and then I cancel that task when the "rendered first frame" event is received.

I am not sure about the correlation of buffer vs position.

I don't know same issue or not, but my issue is exactly as @ojw28 described: 1) Position 0 is equal to 1000000000000 in the internal representation 2) Received data with a negative timestamp, for example -824000us, after adding offset -824000 + 1000000000000 = 999999176000 3) This condition is triggered, because 824000 > 500000. 4) The current position now is 999999176000, if we convert this from internal representation to human format the current position becomes -0.824ms

I'm still trying to figure out how it all works, but I hope I'm moving in the right direction.