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
This commit is contained in:
andrewlewis 2023-11-27 08:52:41 -08:00 committed by Copybara-Service
parent 63062a9c10
commit 1c7c06999e
7 changed files with 54 additions and 16 deletions

View File

@ -171,7 +171,9 @@ import org.checkerframework.checker.nullness.qual.MonotonicNonNull;
DebugTraceUtil.logEvent( DebugTraceUtil.logEvent(
DebugTraceUtil.EVENT_VFP_QUEUE_BITMAP, DebugTraceUtil.EVENT_VFP_QUEUE_BITMAP,
currentPresentationTimeUs, currentPresentationTimeUs,
/* extra= */ currentFrameInfo.width + "x" + currentFrameInfo.height); /* extraFormat= */ "%dx%d",
/* extraArgs...= */ currentFrameInfo.width,
currentFrameInfo.height);
if (!currentBitmapInfo.inStreamOffsetsUs.hasNext()) { if (!currentBitmapInfo.inStreamOffsetsUs.hasNext()) {
isNextFrameInTexture = false; isNextFrameInTexture = false;

View File

@ -26,6 +26,7 @@ import androidx.annotation.StringDef;
import androidx.media3.common.C; import androidx.media3.common.C;
import androidx.media3.common.util.SystemClock; import androidx.media3.common.util.SystemClock;
import androidx.media3.common.util.UnstableApi; import androidx.media3.common.util.UnstableApi;
import androidx.media3.common.util.Util;
import com.google.common.base.Strings; import com.google.common.base.Strings;
import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableList;
import java.io.IOException; import java.io.IOException;
@ -41,9 +42,17 @@ import java.util.List;
import java.util.Map; import java.util.Map;
import java.util.Queue; import java.util.Queue;
/** A debugging tracing utility. */ /** A debugging tracing utility. Debug logging is disabled at compile time by default. */
@UnstableApi @UnstableApi
public final class DebugTraceUtil { 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}. */ /** Events logged by {@link #logEvent}. */
@Retention(RetentionPolicy.SOURCE) @Retention(RetentionPolicy.SOURCE)
@StringDef({ @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 eventName The {@linkplain DebugTraceEvent event name} to log.
* @param presentationTimeUs The current presentation time of the media. Use {@link C#TIME_UNSET} * @param presentationTimeUs The current presentation time of the media. Use {@link C#TIME_UNSET}
* if unknown, {@link C#TIME_END_OF_SOURCE} if EOS. * 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( 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; long eventTimeMs = SystemClock.DEFAULT.elapsedRealtime() - startTimeMs;
if (!events.containsKey(eventName)) { if (!events.containsKey(eventName)) {
events.put(eventName, new EventLogger()); events.put(eventName, new EventLogger());
} }
EventLogger logger = events.get(eventName); EventLogger logger = events.get(eventName);
@Nullable
String extra = extraFormat != null ? Util.formatInvariant(extraFormat, extraArgs) : null;
logger.addLog(new EventLog(presentationTimeUs, eventTimeMs, extra)); 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 eventName The {@linkplain DebugTraceEvent event name} to log.
* @param presentationTimeUs The current presentation time of the media. Use {@link C#TIME_UNSET} * @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( public static synchronized void logEvent(
@DebugTraceEvent String eventName, long presentationTimeUs) { @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. * and the detailed log on the first and last {@link #MAX_FIRST_LAST_LOGS} times.
*/ */
public static synchronized String generateTraceSummary() { public static synchronized String generateTraceSummary() {
if (!enableTracing) {
return "Tracing disabled";
}
StringBuilder stringBuilder = new StringBuilder().append('{'); StringBuilder stringBuilder = new StringBuilder().append('{');
for (int i = 0; i < EVENT_TYPES.size(); i++) { for (int i = 0; i < EVENT_TYPES.size(); i++) {
String eventType = EVENT_TYPES.get(i); String eventType = EVENT_TYPES.get(i);
@ -203,8 +225,12 @@ public final class DebugTraceUtil {
return stringBuilder.toString(); 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 { public static synchronized void dumpTsv(Writer writer) throws IOException {
if (!enableTracing) {
writer.write("Tracing disabled");
return;
}
writer.write("event\ttimestamp\tpresentation\textra\n"); writer.write("event\ttimestamp\tpresentation\textra\n");
for (Map.Entry<String, EventLogger> entry : events.entrySet()) { for (Map.Entry<String, EventLogger> entry : events.entrySet()) {
ImmutableList<EventLog> eventLogs = entry.getValue().getLogs(); ImmutableList<EventLog> eventLogs = entry.getValue().getLogs();

View File

@ -459,9 +459,10 @@ public final class DefaultVideoFrameProcessor implements VideoFrameProcessor {
logEvent( logEvent(
EVENT_VFP_REGISTER_NEW_INPUT_STREAM, EVENT_VFP_REGISTER_NEW_INPUT_STREAM,
/* presentationTimeUs= */ frameInfo.offsetToAddUs, /* presentationTimeUs= */ frameInfo.offsetToAddUs,
/* extra= */ Util.formatInvariant( /* extraFormat= */ "InputType %s - %dx%d",
"InputType %s - %dx%d", /* extraArgs...= */ getInputTypeString(inputType),
getInputTypeString(inputType), frameInfo.width, frameInfo.height)); frameInfo.width,
frameInfo.height);
nextInputFrameInfo = adjustForPixelWidthHeightRatio(frameInfo); nextInputFrameInfo = adjustForPixelWidthHeightRatio(frameInfo);
try { try {

View File

@ -84,7 +84,9 @@ import org.checkerframework.checker.nullness.qual.MonotonicNonNull;
DebugTraceUtil.logEvent( DebugTraceUtil.logEvent(
DebugTraceUtil.EVENT_VFP_QUEUE_TEXTURE, DebugTraceUtil.EVENT_VFP_QUEUE_TEXTURE,
presentationTimeUs, presentationTimeUs,
/* extra= */ frameInfo.width + "x" + frameInfo.height); /* extraFormat= */ "%dx%d",
/* extraArgs...= */ frameInfo.width,
frameInfo.height);
}); });
} }

View File

@ -316,6 +316,8 @@ public class TransformerAndroidTestRunner {
CountDownLatch countDownLatch = new CountDownLatch(1); CountDownLatch countDownLatch = new CountDownLatch(1);
long startTimeMs = SystemClock.DEFAULT.elapsedRealtime(); long startTimeMs = SystemClock.DEFAULT.elapsedRealtime();
DebugTraceUtil.enableTracing = true;
Transformer testTransformer = Transformer testTransformer =
transformer transformer
.buildUpon() .buildUpon()

View File

@ -72,7 +72,10 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull;
@Override @Override
protected void onInputFormatRead(Format inputFormat) { protected void onInputFormatRead(Format inputFormat) {
DebugTraceUtil.logEvent( 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) { if (flattenForSlowMotion) {
sefVideoSlowMotionFlattener = new SefSlowMotionFlattener(inputFormat); sefVideoSlowMotionFlattener = new SefSlowMotionFlattener(inputFormat);
} }

View File

@ -311,12 +311,14 @@ import org.checkerframework.checker.nullness.qual.RequiresNonNull;
DebugTraceUtil.logEvent( DebugTraceUtil.logEvent(
DebugTraceUtil.EVENT_MUXER_CAN_WRITE_SAMPLE_VIDEO, DebugTraceUtil.EVENT_MUXER_CAN_WRITE_SAMPLE_VIDEO,
presentationTimeUs, presentationTimeUs,
String.valueOf(canWriteSample)); /* extraFormat= */ "%s",
/* extraArgs...= */ canWriteSample);
} else if (trackType == C.TRACK_TYPE_AUDIO) { } else if (trackType == C.TRACK_TYPE_AUDIO) {
DebugTraceUtil.logEvent( DebugTraceUtil.logEvent(
DebugTraceUtil.EVENT_MUXER_CAN_WRITE_SAMPLE_AUDIO, DebugTraceUtil.EVENT_MUXER_CAN_WRITE_SAMPLE_AUDIO,
presentationTimeUs, presentationTimeUs,
String.valueOf(canWriteSample)); /* extraFormat= */ "%s",
/* extraArgs...= */ canWriteSample);
} }
if (!canWriteSample) { if (!canWriteSample) {
return false; return false;