From 1c7c06999e45b596e6e52a01b42090138291e379 Mon Sep 17 00:00:00 2001 From: andrewlewis Date: Mon, 27 Nov 2023 08:52:41 -0800 Subject: [PATCH] Turn off debug trace logging by default The issue that motivated adding this (frames unexpectedly being dropped by the decoder) has been addressed, so we can turn off the logging to reduce unnecessary allocations during transformation. We can easily turn on debug logging in future as needed by setting `DebugTraceUtil.DEBUG = true`. Also avoid allocations for string building at logging call sites by passing a format string for extra info. Formatting the string now only happens when debugging is turned on. Tested manually by running transformations in the new state (DEBUG = false) and with debugging turned on. PiperOrigin-RevId: 585666349 --- .../media3/effect/BitmapTextureManager.java | 4 +- .../media3/effect/DebugTraceUtil.java | 42 +++++++++++++++---- .../effect/DefaultVideoFrameProcessor.java | 7 ++-- .../media3/effect/TexIdTextureManager.java | 4 +- .../TransformerAndroidTestRunner.java | 2 + .../ExoAssetLoaderVideoRenderer.java | 5 ++- .../media3/transformer/MuxerWrapper.java | 6 ++- 7 files changed, 54 insertions(+), 16 deletions(-) diff --git a/libraries/effect/src/main/java/androidx/media3/effect/BitmapTextureManager.java b/libraries/effect/src/main/java/androidx/media3/effect/BitmapTextureManager.java index d6f8f27d50..4b4849ea77 100644 --- a/libraries/effect/src/main/java/androidx/media3/effect/BitmapTextureManager.java +++ b/libraries/effect/src/main/java/androidx/media3/effect/BitmapTextureManager.java @@ -171,7 +171,9 @@ import org.checkerframework.checker.nullness.qual.MonotonicNonNull; DebugTraceUtil.logEvent( DebugTraceUtil.EVENT_VFP_QUEUE_BITMAP, currentPresentationTimeUs, - /* extra= */ currentFrameInfo.width + "x" + currentFrameInfo.height); + /* extraFormat= */ "%dx%d", + /* extraArgs...= */ currentFrameInfo.width, + currentFrameInfo.height); if (!currentBitmapInfo.inStreamOffsetsUs.hasNext()) { isNextFrameInTexture = false; diff --git a/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java b/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java index b8ffa1cddf..6172241682 100644 --- a/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java +++ b/libraries/effect/src/main/java/androidx/media3/effect/DebugTraceUtil.java @@ -26,6 +26,7 @@ import androidx.annotation.StringDef; 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.Strings; import com.google.common.collect.ImmutableList; import java.io.IOException; @@ -41,9 +42,17 @@ import java.util.List; import java.util.Map; import java.util.Queue; -/** A debugging tracing utility. */ +/** A debugging tracing utility. Debug logging is disabled at compile time by default. */ @UnstableApi public final class DebugTraceUtil { + + /** + * Whether to store tracing events for debug logging. Should be set to {@code true} for testing + * and debugging purposes only, before running transformer. + */ + @SuppressWarnings("NonFinalStaticField") // Only for debugging/testing. + public static boolean enableTracing = false; + /** Events logged by {@link #logEvent}. */ @Retention(RetentionPolicy.SOURCE) @StringDef({ @@ -153,25 +162,35 @@ public final class DebugTraceUtil { } /** - * Logs a new event. + * Logs a new event, if debug logging is enabled. * * @param eventName The {@linkplain DebugTraceEvent event name} to log. * @param presentationTimeUs The current presentation time of the media. Use {@link C#TIME_UNSET} * if unknown, {@link C#TIME_END_OF_SOURCE} if EOS. - * @param extra Optional extra info about the event being logged. + * @param extraFormat Format string for optional extra information. See {@link + * Util#formatInvariant(String, Object...)}. + * @param extraArgs Arguments for optional extra information. */ public static synchronized void logEvent( - @DebugTraceEvent String eventName, long presentationTimeUs, @Nullable String extra) { + @DebugTraceEvent String eventName, + long presentationTimeUs, + @Nullable String extraFormat, + Object... extraArgs) { + if (!enableTracing) { + return; + } long eventTimeMs = SystemClock.DEFAULT.elapsedRealtime() - startTimeMs; if (!events.containsKey(eventName)) { events.put(eventName, new EventLogger()); } EventLogger logger = events.get(eventName); + @Nullable + String extra = extraFormat != null ? Util.formatInvariant(extraFormat, extraArgs) : null; logger.addLog(new EventLog(presentationTimeUs, eventTimeMs, extra)); } /** - * Logs a new event. + * Logs a new event, if debug logging is enabled. * * @param eventName The {@linkplain DebugTraceEvent event name} to log. * @param presentationTimeUs The current presentation time of the media. Use {@link C#TIME_UNSET} @@ -179,14 +198,17 @@ public final class DebugTraceUtil { */ public static synchronized void logEvent( @DebugTraceEvent String eventName, long presentationTimeUs) { - logEvent(eventName, presentationTimeUs, /* extra= */ null); + logEvent(eventName, presentationTimeUs, /* extraFormat= */ null); } /** - * Generate a summary of the traced events, containing the total number of times an event happened + * Generate a summary of the logged events, containing the total number of times an event happened * and the detailed log on the first and last {@link #MAX_FIRST_LAST_LOGS} times. */ public static synchronized String generateTraceSummary() { + if (!enableTracing) { + return "Tracing disabled"; + } StringBuilder stringBuilder = new StringBuilder().append('{'); for (int i = 0; i < EVENT_TYPES.size(); i++) { String eventType = EVENT_TYPES.get(i); @@ -203,8 +225,12 @@ public final class DebugTraceUtil { return stringBuilder.toString(); } - /** Dumps all the stored events to a tsv file. */ + /** Dumps all the logged events to a tsv file. */ public static synchronized void dumpTsv(Writer writer) throws IOException { + if (!enableTracing) { + writer.write("Tracing disabled"); + return; + } writer.write("event\ttimestamp\tpresentation\textra\n"); for (Map.Entry entry : events.entrySet()) { ImmutableList eventLogs = entry.getValue().getLogs(); 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 da0b9bd814..c129d95647 100644 --- a/libraries/effect/src/main/java/androidx/media3/effect/DefaultVideoFrameProcessor.java +++ b/libraries/effect/src/main/java/androidx/media3/effect/DefaultVideoFrameProcessor.java @@ -459,9 +459,10 @@ public final class DefaultVideoFrameProcessor implements VideoFrameProcessor { logEvent( EVENT_VFP_REGISTER_NEW_INPUT_STREAM, /* presentationTimeUs= */ frameInfo.offsetToAddUs, - /* extra= */ Util.formatInvariant( - "InputType %s - %dx%d", - getInputTypeString(inputType), frameInfo.width, frameInfo.height)); + /* extraFormat= */ "InputType %s - %dx%d", + /* extraArgs...= */ getInputTypeString(inputType), + frameInfo.width, + frameInfo.height); nextInputFrameInfo = adjustForPixelWidthHeightRatio(frameInfo); try { diff --git a/libraries/effect/src/main/java/androidx/media3/effect/TexIdTextureManager.java b/libraries/effect/src/main/java/androidx/media3/effect/TexIdTextureManager.java index f2fd383d41..f3b926a3a5 100644 --- a/libraries/effect/src/main/java/androidx/media3/effect/TexIdTextureManager.java +++ b/libraries/effect/src/main/java/androidx/media3/effect/TexIdTextureManager.java @@ -84,7 +84,9 @@ import org.checkerframework.checker.nullness.qual.MonotonicNonNull; DebugTraceUtil.logEvent( DebugTraceUtil.EVENT_VFP_QUEUE_TEXTURE, presentationTimeUs, - /* extra= */ frameInfo.width + "x" + frameInfo.height); + /* extraFormat= */ "%dx%d", + /* extraArgs...= */ frameInfo.width, + frameInfo.height); }); } diff --git a/libraries/transformer/src/androidTest/java/androidx/media3/transformer/TransformerAndroidTestRunner.java b/libraries/transformer/src/androidTest/java/androidx/media3/transformer/TransformerAndroidTestRunner.java index 36f9fea425..30f9fccd5a 100644 --- a/libraries/transformer/src/androidTest/java/androidx/media3/transformer/TransformerAndroidTestRunner.java +++ b/libraries/transformer/src/androidTest/java/androidx/media3/transformer/TransformerAndroidTestRunner.java @@ -316,6 +316,8 @@ public class TransformerAndroidTestRunner { CountDownLatch countDownLatch = new CountDownLatch(1); long startTimeMs = SystemClock.DEFAULT.elapsedRealtime(); + DebugTraceUtil.enableTracing = true; + Transformer testTransformer = transformer .buildUpon() 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 2871a7cf17..f8e3689b88 100644 --- a/libraries/transformer/src/main/java/androidx/media3/transformer/ExoAssetLoaderVideoRenderer.java +++ b/libraries/transformer/src/main/java/androidx/media3/transformer/ExoAssetLoaderVideoRenderer.java @@ -72,7 +72,10 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; @Override protected void onInputFormatRead(Format inputFormat) { DebugTraceUtil.logEvent( - DebugTraceUtil.EVENT_VIDEO_INPUT_FORMAT, C.TIME_UNSET, inputFormat.toString()); + DebugTraceUtil.EVENT_VIDEO_INPUT_FORMAT, + C.TIME_UNSET, + /* extraFormat= */ "%s", + /* extraArgs...= */ inputFormat); if (flattenForSlowMotion) { sefVideoSlowMotionFlattener = new SefSlowMotionFlattener(inputFormat); } 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 5ff7bcb505..14c51eef40 100644 --- a/libraries/transformer/src/main/java/androidx/media3/transformer/MuxerWrapper.java +++ b/libraries/transformer/src/main/java/androidx/media3/transformer/MuxerWrapper.java @@ -311,12 +311,14 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull; DebugTraceUtil.logEvent( DebugTraceUtil.EVENT_MUXER_CAN_WRITE_SAMPLE_VIDEO, presentationTimeUs, - String.valueOf(canWriteSample)); + /* extraFormat= */ "%s", + /* extraArgs...= */ canWriteSample); } else if (trackType == C.TRACK_TYPE_AUDIO) { DebugTraceUtil.logEvent( DebugTraceUtil.EVENT_MUXER_CAN_WRITE_SAMPLE_AUDIO, presentationTimeUs, - String.valueOf(canWriteSample)); + /* extraFormat= */ "%s", + /* extraArgs...= */ canWriteSample); } if (!canWriteSample) { return false;