diff --git a/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java b/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java new file mode 100644 index 0000000000..741be3bef5 --- /dev/null +++ b/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java @@ -0,0 +1,197 @@ +/* + * Copyright 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package androidx.media3.effect; + +import androidx.annotation.GuardedBy; +import androidx.media3.common.C; +import androidx.media3.common.util.SystemClock; +import androidx.media3.common.util.UnstableApi; +import androidx.media3.common.util.Util; +import com.google.common.base.Joiner; +import java.util.ArrayDeque; +import java.util.Queue; + +/** A debugging tracing utility. */ +@UnstableApi +public final class DebugTraceUtil { + + private static final int MUXER_CAN_WRITE_SAMPLE_RECORD_COUNT = 10; + + /** The timestamps at which the decoder received end of stream signal, in milliseconds. */ + @GuardedBy("DebugTraceUtil.class") + private static final Queue DECODER_RECEIVE_EOS_TIMES_MS = new ArrayDeque<>(); + + /** The timestamps at which the decoder signalled end of stream, in milliseconds. */ + @GuardedBy("DebugTraceUtil.class") + private static final Queue DECODER_SIGNAL_EOS_TIMES_MS = new ArrayDeque<>(); + + /** + * The timestamps at which {@code VideoFrameProcessor} received end of stream signal from the + * decoder, in milliseconds. + */ + @GuardedBy("DebugTraceUtil.class") + private static final Queue VIDEO_FRAME_PROCESSOR_RECEIVE_DECODER_EOS_TIMES_MS = + new ArrayDeque<>(); + + /** + * The timestamps at which {@code VideoFrameProcessor} signalled end of stream, in milliseconds. + */ + @GuardedBy("DebugTraceUtil.class") + private static final Queue VIDEO_FRAME_PROCESSOR_SIGNAL_EOS_TIMES_MS = new ArrayDeque<>(); + + /** The timestamps at which the encoder received end of stream signal, in milliseconds. */ + @GuardedBy("DebugTraceUtil.class") + private static final Queue ENCODER_RECEIVE_EOS_TIMES_MS = new ArrayDeque<>(); + + /** + * The last {@link #MUXER_CAN_WRITE_SAMPLE_RECORD_COUNT} values returned by {@code + * MuxerWrapper#canWriteSample}. + */ + @GuardedBy("DebugTraceUtil.class") + private static final Queue MUXER_CAN_WRITE_VIDEO_SAMPLE = new ArrayDeque<>(); + + /** The timestamps at which the muxer video track is stopped, in milliseconds. */ + @GuardedBy("DebugTraceUtil.class") + private static final Queue MUXER_TRACK_END_TIMES_MS = new ArrayDeque<>(); + + /** The number of decoded frames. */ + @GuardedBy("DebugTraceUtil.class") + private static int numberOfDecodedFrames = 0; + + /** The number of frames made available on {@code VideoFrameProcessor}'s input surface. */ + @GuardedBy("DebugTraceUtil.class") + private static int numberOfFramesRenderedToVideoFrameProcessorInput = 0; + + /** The number of frames rendered to {@code VideoFrameProcessor}'s output. */ + @GuardedBy("DebugTraceUtil.class") + private static int numberOfFramesRenderedToVideoFrameProcessorOutput = 0; + + /** The number of encoded frames. */ + @GuardedBy("DebugTraceUtil.class") + private static int numberOfEncodedFrames = 0; + + /** The number of video frames written to the muxer. */ + @GuardedBy("DebugTraceUtil.class") + private static int numberOfMuxedFrames = 0; + + private DebugTraceUtil() {} + + public static synchronized void reset() { + numberOfDecodedFrames = 0; + numberOfFramesRenderedToVideoFrameProcessorInput = 0; + numberOfFramesRenderedToVideoFrameProcessorOutput = 0; + numberOfEncodedFrames = 0; + numberOfMuxedFrames = 0; + DECODER_RECEIVE_EOS_TIMES_MS.clear(); + DECODER_SIGNAL_EOS_TIMES_MS.clear(); + VIDEO_FRAME_PROCESSOR_RECEIVE_DECODER_EOS_TIMES_MS.clear(); + VIDEO_FRAME_PROCESSOR_SIGNAL_EOS_TIMES_MS.clear(); + ENCODER_RECEIVE_EOS_TIMES_MS.clear(); + MUXER_CAN_WRITE_VIDEO_SAMPLE.clear(); + MUXER_TRACK_END_TIMES_MS.clear(); + } + + public static synchronized void recordDecodedFrame() { + numberOfDecodedFrames++; + } + + public static synchronized void recordFrameRenderedToVideoFrameProcessorInput() { + numberOfFramesRenderedToVideoFrameProcessorInput++; + } + + public static synchronized void recordFrameRenderedToVideoFrameProcessorOutput() { + numberOfFramesRenderedToVideoFrameProcessorOutput++; + } + + public static synchronized void recordEncodedFrame() { + numberOfEncodedFrames++; + } + + public static synchronized void recordMuxerInput(@C.TrackType int trackType) { + if (trackType == C.TRACK_TYPE_VIDEO) { + numberOfMuxedFrames++; + } + } + + public static synchronized void recordDecoderReceiveEos() { + DECODER_RECEIVE_EOS_TIMES_MS.add(SystemClock.DEFAULT.elapsedRealtime()); + } + + public static synchronized void recordDecoderSignalEos() { + DECODER_SIGNAL_EOS_TIMES_MS.add(SystemClock.DEFAULT.elapsedRealtime()); + } + + public static synchronized void recordVideoFrameProcessorReceiveDecoderEos() { + VIDEO_FRAME_PROCESSOR_RECEIVE_DECODER_EOS_TIMES_MS.add(SystemClock.DEFAULT.elapsedRealtime()); + } + + public static synchronized void recordVideoFrameProcessorSignalEos() { + VIDEO_FRAME_PROCESSOR_SIGNAL_EOS_TIMES_MS.add(SystemClock.DEFAULT.elapsedRealtime()); + } + + public static synchronized void recordEncoderReceiveEos() { + ENCODER_RECEIVE_EOS_TIMES_MS.add(SystemClock.DEFAULT.elapsedRealtime()); + } + + public static synchronized void recordMuxerCanAddSample( + @C.TrackType int trackType, boolean canAddSample) { + if (trackType == C.TRACK_TYPE_VIDEO) { + if (MUXER_CAN_WRITE_VIDEO_SAMPLE.size() == MUXER_CAN_WRITE_SAMPLE_RECORD_COUNT) { + MUXER_CAN_WRITE_VIDEO_SAMPLE.poll(); + } + MUXER_CAN_WRITE_VIDEO_SAMPLE.add(canAddSample); + } + } + + public static synchronized void recordMuxerTrackEnded(@C.TrackType int trackType) { + if (trackType == C.TRACK_TYPE_VIDEO) { + MUXER_TRACK_END_TIMES_MS.add(SystemClock.DEFAULT.elapsedRealtime()); + } + } + + public static synchronized String generateTrace() { + return "Decoded: " + + numberOfDecodedFrames + + ", Rendered to VFP: " + + numberOfFramesRenderedToVideoFrameProcessorInput + + ", Rendered to encoder: " + + numberOfFramesRenderedToVideoFrameProcessorOutput + + ", Encoded: " + + numberOfEncodedFrames + + ", Muxed: " + + numberOfMuxedFrames + + ", Decoder receive EOS: " + + generateString(DECODER_RECEIVE_EOS_TIMES_MS) + + ", Decoder signal EOS: " + + generateString(DECODER_SIGNAL_EOS_TIMES_MS) + + ", VFP receive EOS: " + + generateString(VIDEO_FRAME_PROCESSOR_RECEIVE_DECODER_EOS_TIMES_MS) + + ", VFP signal EOS: " + + generateString(VIDEO_FRAME_PROCESSOR_SIGNAL_EOS_TIMES_MS) + + ", Encoder receive EOS: " + + generateString(ENCODER_RECEIVE_EOS_TIMES_MS) + + Util.formatInvariant( + ", Muxer last %d video canWriteSample: ", MUXER_CAN_WRITE_SAMPLE_RECORD_COUNT) + + generateString(MUXER_CAN_WRITE_VIDEO_SAMPLE) + + ", Muxer stopped: " + + generateString(MUXER_TRACK_END_TIMES_MS); + } + + private static String generateString(Queue queue) { + return queue.isEmpty() ? "NO" : Util.formatInvariant("[%s]", Joiner.on(',').join(queue)); + } +} diff --git a/libraries/effect/src/main/java/androidx/media3/effect/DefaultVideoFrameProcessor.java b/libraries/effect/src/main/java/androidx/media3/effect/DefaultVideoFrameProcessor.java index 34e7e49340..a6476d0fb7 100644 --- a/libraries/effect/src/main/java/androidx/media3/effect/DefaultVideoFrameProcessor.java +++ b/libraries/effect/src/main/java/androidx/media3/effect/DefaultVideoFrameProcessor.java @@ -419,6 +419,7 @@ public final class DefaultVideoFrameProcessor implements VideoFrameProcessor { @Override public void signalEndOfInput() { + DebugTraceUtil.recordVideoFrameProcessorReceiveDecoderEos(); checkState(!inputStreamEnded); inputStreamEnded = true; boolean allInputStreamsProcessed; diff --git a/libraries/effect/src/main/java/androidx/media3/effect/ExternalTextureManager.java b/libraries/effect/src/main/java/androidx/media3/effect/ExternalTextureManager.java index 2958ddd058..4361e4246f 100644 --- a/libraries/effect/src/main/java/androidx/media3/effect/ExternalTextureManager.java +++ b/libraries/effect/src/main/java/androidx/media3/effect/ExternalTextureManager.java @@ -97,6 +97,7 @@ import java.util.concurrent.atomic.AtomicInteger; unused -> videoFrameProcessingTaskExecutor.submit( () -> { + DebugTraceUtil.recordFrameRenderedToVideoFrameProcessorInput(); if (numberOfFramesToDropOnBecomingAvailable > 0) { numberOfFramesToDropOnBecomingAvailable--; surfaceTexture.updateTexImage(); diff --git a/libraries/effect/src/main/java/androidx/media3/effect/FinalShaderProgramWrapper.java b/libraries/effect/src/main/java/androidx/media3/effect/FinalShaderProgramWrapper.java index 09e27802e4..20dacf686b 100644 --- a/libraries/effect/src/main/java/androidx/media3/effect/FinalShaderProgramWrapper.java +++ b/libraries/effect/src/main/java/androidx/media3/effect/FinalShaderProgramWrapper.java @@ -181,6 +181,7 @@ import org.checkerframework.checker.nullness.qual.MonotonicNonNull; boolean frameProcessingEnded = checkNotNull(onInputStreamProcessedListener).onInputStreamProcessed(); if (frameProcessingEnded) { + DebugTraceUtil.recordVideoFrameProcessorSignalEos(); videoFrameProcessorListenerExecutor.execute(videoFrameProcessorListener::onEnded); } } @@ -325,6 +326,7 @@ import org.checkerframework.checker.nullness.qual.MonotonicNonNull; ? System.nanoTime() : renderTimeNs); EGL14.eglSwapBuffers(eglDisplay, outputEglSurface); + DebugTraceUtil.recordFrameRenderedToVideoFrameProcessorOutput(); } private void renderFrameToOutputTexture(GlTextureInfo inputTexture, long presentationTimeUs) diff --git a/libraries/transformer/src/main/java/androidx/media3/transformer/DefaultCodec.java b/libraries/transformer/src/main/java/androidx/media3/transformer/DefaultCodec.java index 235a35e301..025aa20f8e 100644 --- a/libraries/transformer/src/main/java/androidx/media3/transformer/DefaultCodec.java +++ b/libraries/transformer/src/main/java/androidx/media3/transformer/DefaultCodec.java @@ -41,6 +41,7 @@ import androidx.media3.common.util.TraceUtil; import androidx.media3.common.util.UnstableApi; import androidx.media3.common.util.Util; import androidx.media3.decoder.DecoderInputBuffer; +import androidx.media3.effect.DebugTraceUtil; import java.io.IOException; import java.nio.ByteBuffer; import org.checkerframework.checker.initialization.qual.UnknownInitialization; @@ -214,6 +215,9 @@ public final class DefaultCodec implements Codec { if (inputBuffer.isEndOfStream()) { inputStreamEnded = true; flags = MediaCodec.BUFFER_FLAG_END_OF_STREAM; + if (isVideo && isDecoder) { + DebugTraceUtil.recordDecoderReceiveEos(); + } } try { mediaCodec.queueInputBuffer(inputBufferIndex, offset, size, inputBuffer.timeUs, flags); @@ -227,6 +231,7 @@ public final class DefaultCodec implements Codec { @Override public void signalEndOfInputStream() throws ExportException { + DebugTraceUtil.recordEncoderReceiveEos(); try { mediaCodec.signalEndOfInputStream(); } catch (RuntimeException e) { diff --git a/libraries/transformer/src/main/java/androidx/media3/transformer/ExoAssetLoaderVideoRenderer.java b/libraries/transformer/src/main/java/androidx/media3/transformer/ExoAssetLoaderVideoRenderer.java index 117d0be6b6..22c6189f52 100644 --- a/libraries/transformer/src/main/java/androidx/media3/transformer/ExoAssetLoaderVideoRenderer.java +++ b/libraries/transformer/src/main/java/androidx/media3/transformer/ExoAssetLoaderVideoRenderer.java @@ -24,6 +24,7 @@ import androidx.media3.common.C; import androidx.media3.common.ColorInfo; import androidx.media3.common.Format; import androidx.media3.decoder.DecoderInputBuffer; +import androidx.media3.effect.DebugTraceUtil; import java.nio.ByteBuffer; import java.util.ArrayList; import java.util.List; @@ -127,6 +128,7 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; @RequiresNonNull({"sampleConsumer", "decoder"}) protected boolean feedConsumerFromDecoder() throws ExportException { if (decoder.isEnded()) { + DebugTraceUtil.recordDecoderSignalEos(); sampleConsumer.signalEndOfVideoInput(); isEnded = true; return false; @@ -154,6 +156,7 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; } decoder.releaseOutputBuffer(presentationTimeUs); + DebugTraceUtil.recordDecodedFrame(); return true; } diff --git a/libraries/transformer/src/main/java/androidx/media3/transformer/MuxerWrapper.java b/libraries/transformer/src/main/java/androidx/media3/transformer/MuxerWrapper.java index 53a86e3fd4..0a04002c80 100644 --- a/libraries/transformer/src/main/java/androidx/media3/transformer/MuxerWrapper.java +++ b/libraries/transformer/src/main/java/androidx/media3/transformer/MuxerWrapper.java @@ -22,6 +22,7 @@ import static androidx.media3.common.util.Assertions.checkState; import static java.lang.Math.max; import static java.util.concurrent.TimeUnit.MILLISECONDS; +import android.util.Log; import android.util.SparseArray; import androidx.annotation.IntRange; import androidx.annotation.Nullable; @@ -30,6 +31,7 @@ import androidx.media3.common.Format; import androidx.media3.common.Metadata; import androidx.media3.common.MimeTypes; import androidx.media3.common.util.Util; +import androidx.media3.effect.DebugTraceUtil; import com.google.common.collect.ImmutableList; import java.io.File; import java.nio.ByteBuffer; @@ -47,6 +49,9 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; */ /* package */ final class MuxerWrapper { + private static final String MUXER_TIMEOUT_ERROR_FORMAT_STRING = + "Abort: no output sample written in the last %d milliseconds. DebugTrace: %s"; + public interface Listener { void onTrackEnded( @C.TrackType int trackType, Format format, int averageBitrate, int sampleCount); @@ -191,8 +196,9 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; // SparseArray.get() returns null by default if the value is not found. checkArgument( trackInfo != null, "Could not write sample because there is no track of type " + trackType); - - if (!canWriteSample(trackType, presentationTimeUs)) { + boolean canWriteSample = canWriteSample(trackType, presentationTimeUs); + DebugTraceUtil.recordMuxerCanAddSample(trackType, canWriteSample); + if (!canWriteSample) { return false; } @@ -204,6 +210,7 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; resetAbortTimer(); muxer.writeSampleData( trackInfo.index, data, presentationTimeUs, isKeyFrame ? C.BUFFER_FLAG_KEY_FRAME : 0); + DebugTraceUtil.recordMuxerInput(trackType); previousTrackType = trackType; return true; } @@ -225,12 +232,15 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; listener.onTrackEnded( trackType, trackInfo.format, trackInfo.getAverageBitrate(), trackInfo.sampleCount); + DebugTraceUtil.recordMuxerTrackEnded(trackType); + trackTypeToInfo.delete(trackType); if (trackTypeToInfo.size() == 0) { abortScheduledExecutorService.shutdownNow(); if (!isEnded) { isEnded = true; listener.onEnded(Util.usToMs(maxEndedTrackTimeUs), getCurrentOutputSizeBytes()); + Log.e("LYC", DebugTraceUtil.generateTrace()); } } } @@ -298,9 +308,10 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; listener.onError( ExportException.createForMuxer( new IllegalStateException( - "No output sample written in the last " - + maxDelayBetweenSamplesMs - + " milliseconds. Aborting transformation."), + Util.formatInvariant( + MUXER_TIMEOUT_ERROR_FORMAT_STRING, + maxDelayBetweenSamplesMs, + DebugTraceUtil.generateTrace())), ExportException.ERROR_CODE_MUXING_TIMEOUT)); }, maxDelayBetweenSamplesMs, diff --git a/libraries/transformer/src/main/java/androidx/media3/transformer/Transformer.java b/libraries/transformer/src/main/java/androidx/media3/transformer/Transformer.java index b5deb783e7..b95ec0dbb6 100644 --- a/libraries/transformer/src/main/java/androidx/media3/transformer/Transformer.java +++ b/libraries/transformer/src/main/java/androidx/media3/transformer/Transformer.java @@ -38,6 +38,7 @@ import androidx.media3.common.util.HandlerWrapper; import androidx.media3.common.util.ListenerSet; import androidx.media3.common.util.UnstableApi; import androidx.media3.common.util.Util; +import androidx.media3.effect.DebugTraceUtil; import androidx.media3.effect.DefaultVideoFrameProcessor; import androidx.media3.effect.Presentation; import androidx.media3.exoplayer.source.DefaultMediaSourceFactory; @@ -712,6 +713,7 @@ public final class Transformer { HandlerWrapper applicationHandler = clock.createHandler(looper, /* callback= */ null); FallbackListener fallbackListener = new FallbackListener(composition, listeners, applicationHandler, transformationRequest); + DebugTraceUtil.reset(); transformerInternal = new TransformerInternal( context, diff --git a/libraries/transformer/src/main/java/androidx/media3/transformer/VideoSamplePipeline.java b/libraries/transformer/src/main/java/androidx/media3/transformer/VideoSamplePipeline.java index afede7e70f..622f5e1db8 100644 --- a/libraries/transformer/src/main/java/androidx/media3/transformer/VideoSamplePipeline.java +++ b/libraries/transformer/src/main/java/androidx/media3/transformer/VideoSamplePipeline.java @@ -49,6 +49,7 @@ import androidx.media3.common.util.Log; import androidx.media3.common.util.Size; import androidx.media3.common.util.Util; import androidx.media3.decoder.DecoderInputBuffer; +import androidx.media3.effect.DebugTraceUtil; import androidx.media3.effect.Presentation; import com.google.common.collect.ImmutableList; import com.google.common.util.concurrent.MoreExecutors; @@ -289,6 +290,7 @@ import org.checkerframework.dataflow.qual.Pure; bufferInfo.presentationTimeUs = finalFramePresentationTimeUs; } } + DebugTraceUtil.recordEncodedFrame(); encoderOutputBuffer.timeUs = bufferInfo.presentationTimeUs; encoderOutputBuffer.setFlags(bufferInfo.flags); return encoderOutputBuffer;