From 05529d4d6cd857e5bcd87be3b342c3fe7ba7655e Mon Sep 17 00:00:00 2001 From: Sven Gothel Date: Wed, 4 Oct 2023 16:31:11 +0200 Subject: Bug 1472: AVSync: Add more comprehensive DEBUG info to detect sync issues --- src/java/com/jogamp/openal/util/ALAudioSink.java | 123 ++++++++++------------- src/java/com/jogamp/openal/util/ALHelpers.java | 87 ++++++++++++++++ 2 files changed, 139 insertions(+), 71 deletions(-) diff --git a/src/java/com/jogamp/openal/util/ALAudioSink.java b/src/java/com/jogamp/openal/util/ALAudioSink.java index 009fb2d..5602375 100644 --- a/src/java/com/jogamp/openal/util/ALAudioSink.java +++ b/src/java/com/jogamp/openal/util/ALAudioSink.java @@ -28,7 +28,6 @@ package com.jogamp.openal.util; import java.nio.ByteBuffer; -import java.util.Arrays; import java.util.concurrent.TimeUnit; import jogamp.openal.Debug; @@ -358,39 +357,28 @@ public final class ALAudioSink implements AudioSink { @Override public final String toString() { - final int alBuffersLen = null != alBufferNames ? alBufferNames.length : 0; final int ctxHash = context != null ? context.hashCode() : 0; - final int alFramesFreeSize = alFramesFree != null ? alFramesFree.size() : 0; - final int alFramesPlayingSize = alFramesPlaying != null ? alFramesPlaying.size() : 0; + final int alFramesEnqueued = alFramesPlaying != null ? alFramesPlaying.size() : 0; + final int alFramesFree_ = alFramesFree!= null ? alFramesFree.size() : 0; return String.format("ALAudioSink[playReq %b, device '%s', ctx 0x%x, alSource %d"+ - ", chosen %s, al[chan %s, type %s, fmt 0x%x, tlc %b, soft[buffer %b, events %b/%b], latency %.2f/%.2f ms, sources %d]"+ - ", playSpeed %.2f, buffers[total %d, free %d], queued[%d, apts %d/%d, %.1f ms, %d bytes, avg %.2f ms/frame, max %d ms]]", + ", chosen %s, al[chan %s, type %s, fmt 0x%x, tlc %b, soft[buffer %b, events %b/%b]"+ + ", latency %.2f/%.2f ms, sources %d], playSpeed %.2f, "+ + "play[used %d, apts %d], queued[free %d, apts %d, %.1f ms, %d bytes, avg %.2f ms/frame, max %d ms]]", playRequested, device.getName(), ctxHash, alSource.getID(), chosenFormat, ALHelpers.alChannelLayoutName(alChannelLayout), ALHelpers.alSampleTypeName(alSampleType), alFormat, hasALC_thread_local_context, hasSOFTBufferSamples, useAL_SOFT_events, hasAL_SOFT_events, - 1000f*latency, 1000f*defaultLatency, sourceCount, playSpeed, alBuffersLen, alFramesFreeSize, - alFramesPlayingSize, getPTS(), getLastBufferedPTS(), 1000f*getQueuedTime(), alBufferBytesQueued, 1000f*avgFrameDuration, queueSize - ); - } - - private final String shortString() { - final int ctxHash = context != null ? context.hashCode() : 0; - final int alFramesEnqueued = alFramesPlaying != null ? alFramesPlaying.size() : 0; - final int alBuffersLen = null != alBufferNames ? alBufferNames.length : 0; - return String.format("[ctx 0x%x, playReq %b, alSrc %d"+ - ", play[buffer %d/%d, apts %d], queued[%d, apts %d, %.1f ms, %d bytes, avg %.2f ms/frame, max %d ms]]", - ctxHash, playRequested, alSource.getID(), - alFramesPlaying.size(), alBuffersLen, getPTS(), - alFramesEnqueued, getLastBufferedPTS(), 1000f*getQueuedTime(), alBufferBytesQueued, 1000f*avgFrameDuration, queueSize + 1000f*latency, 1000f*defaultLatency, sourceCount, playSpeed, + alFramesEnqueued, getPTS(), + alFramesFree_, getLastBufferedPTS(), 1000f*getQueuedTime(), alBufferBytesQueued, 1000f*avgFrameDuration, queueSize ); } public final String getPerfString() { final int alFramesEnqueued = alFramesPlaying != null ? alFramesPlaying.size() : 0; - final int alBuffersLen = null != alBufferNames ? alBufferNames.length : 0; - return String.format("play[buffer %d/%d, apts %d], queued[%d, apts %d, %.1f ms, %d bytes, avg %.2f ms/frame, max %d ms]", - alFramesPlaying.size(), alBuffersLen, getPTS(), - alFramesEnqueued, getLastBufferedPTS(), 1000f*getQueuedTime(), alBufferBytesQueued, 1000f*avgFrameDuration, queueSize + final int alFramesFree_ = alFramesFree!= null ? alFramesFree.size() : 0; + return String.format("play[used %d, apts %d], queued[free %d, apts %d, %.1f ms, %d bytes, avg %.2f ms/frame, max %d ms]", + alFramesEnqueued, getPTS(), + alFramesFree_, getLastBufferedPTS(), 1000f*getQueuedTime(), alBufferBytesQueued, 1000f*avgFrameDuration, queueSize ); } @@ -610,10 +598,10 @@ public final class ALAudioSink implements AudioSink { // Allocate new buffers { - final int initialFrameCount = requestedFormat.getFrameCount( + final int frameCount = requestedFormat.getFrameCount( queueSize > 0 ? queueSize/1000f : AudioSink.DefaultQueueSize/1000f, frameDurationHintS); - alBufferNames = new int[initialFrameCount]; - al.alGenBuffers(initialFrameCount, alBufferNames, 0); + alBufferNames = new int[frameCount]; + al.alGenBuffers(frameCount, alBufferNames, 0); if( AudioSystem3D.checkALError("alGenBuffers", true, false) ) { alBufferNames = null; destroySource(); @@ -621,12 +609,12 @@ public final class ALAudioSink implements AudioSink { releaseContext = false; return false; } - final ALAudioFrame[] alFrames = new ALAudioFrame[initialFrameCount]; - for(int i=0; i(alFrames); - alFramesPlaying = new LFRingbuffer(ALAudioFrame[].class, initialFrameCount); + alFramesPlaying = new LFRingbuffer(ALAudioFrame[].class, frameCount); this.queueSize = queueSize > 0 ? queueSize : AudioSink.DefaultQueueSize; if( DEBUG_TRACE ) { alFramesFree.dump(System.err, "Avail-init"); @@ -655,18 +643,6 @@ public final class ALAudioSink implements AudioSink { return chosenFormat; } - private static int[] concat(final int[] first, final int[] second) { - final int[] result = Arrays.copyOf(first, first.length + second.length); - System.arraycopy(second, 0, result, first.length, second.length); - return result; - } - /** - private static T[] concat(T[] first, T[] second) { - final T[] result = Arrays.copyOf(first, first.length + second.length); - System.arraycopy(second, 0, result, first.length, second.length); - return result; - } */ - private void destroyBuffers() { if( !staticsInitialized ) { return; @@ -798,7 +774,7 @@ public final class ALAudioSink implements AudioSink { if( DEBUG ) { slept += TimeUnit.NANOSECONDS.toMillis(Clock.currentNanos()-t0); final String warnInfo = releasedBuffers != releasedBuffersByEvent ? " ** Warning ** " : ""; - System.err.println(getThreadName()+": ALAudioSink.DeqEvent["+wait_cycles+"]: released buffers "+releasedBuffers+warnInfo+ + System.err.println(getThreadName()+": ALAudioSink.DeqEvent["+wait_cycles+"]: released "+releasedBuffers+warnInfo+ " [enqeueud "+enqueuedBuffers+", event "+ releasedBuffersByEvent+", query "+releasedBuffersByQuery+"], req "+releaseBufferCountReq+", slept "+ slept+" ms, free total "+alFramesFree.size()); @@ -813,8 +789,8 @@ public final class ALAudioSink implements AudioSink { if( slept + sleep + 1 <= sleepLimes ) { if( DEBUG ) { System.err.println(getThreadName()+": ALAudioSink: DeqPoll["+wait_cycles+"].1:"+ - "releasedBuffers "+releasedBuffers+"/"+releaseBufferCountReq+", sleep "+sleep+"/"+slept+"/"+sleepLimes+ - " ms, playImpl "+(ALConstants.AL_PLAYING == getSourceState(false))+", "+getPerfString()); + "released "+releasedBuffers+"/"+releaseBufferCountReq+", sleep "+sleep+"/"+slept+"/"+sleepLimes+ + " ms, "+getPerfString()+", state "+ALHelpers.alSourceStateString(getSourceState(false))); } release(true /* throw */); try { @@ -829,8 +805,8 @@ public final class ALAudioSink implements AudioSink { if( DEBUG ) { if( onceBusyDebug ) { System.err.println(getThreadName()+": ALAudioSink: DeqPoll["+wait_cycles+"].2:"+ - "releasedBuffers "+releasedBuffers+"/"+releaseBufferCountReq+", sleep "+sleep+"->1/"+slept+"/"+sleepLimes+ - " ms, playImpl "+(ALConstants.AL_PLAYING == getSourceState(false))+", "+getPerfString()); + "released "+releasedBuffers+"/"+releaseBufferCountReq+", sleep "+sleep+"->1/"+slept+"/"+sleepLimes+ + " ms, "+getPerfString()+", state "+ALHelpers.alSourceStateString(getSourceState(false))); onceBusyDebug = false; } } @@ -862,9 +838,6 @@ public final class ALAudioSink implements AudioSink { throw new InternalError("Internal Error: "+this); } } else { - if(DEBUG_TRACE) { - System.err.println("< [al "+buffers[i]+", q "+releasedBuffer.alBuffer+"] <- "+shortString()+" @ "+getThreadName()); - } if( releasedBuffer.alBuffer != buffers[i] ) { if( !ignoreBufferInconsistency ) { alFramesFree.dump(System.err, "Avail-deq02-post"); @@ -877,7 +850,7 @@ public final class ALAudioSink implements AudioSink { throw new InternalError("Internal Error: "+this); } if(DEBUG_TRACE) { - System.err.println("<< [al "+buffers[i]+", q "+releasedBuffer.alBuffer+"] <- "+shortString()+" @ "+getThreadName()); + System.err.println("<< [al "+buffers[i]+", q "+releasedBuffer.alBuffer+"] <- "+getPerfString()+" @ "+getThreadName()); } } } @@ -885,14 +858,14 @@ public final class ALAudioSink implements AudioSink { if( DEBUG ) { final long t1 = Clock.currentNanos(); System.err.println(getThreadName()+": ALAudioSink.Dequeued["+wait_cycles+"]: "+TimeUnit.NANOSECONDS.toMillis(t1-t0)+ - "ms , releasedBuffers "+releasedBufferCount+"/"+releaseBufferCountReq+", slept "+slept+" ms, playImpl "+(ALConstants.AL_PLAYING == getSourceState(false))+ - ", "+getPerfString()); + "ms , released "+releasedBufferCount+"/"+releaseBufferCountReq+", slept "+slept+" ms, "+getPerfString()+ + ", state "+ALHelpers.alSourceStateString(getSourceState(false))); } return releasedBufferCount; } private final void dequeueForceAll() { if(DEBUG_TRACE) { - System.err.println("< _FLUSH_ <- "+shortString()+" @ "+getThreadName()); + System.err.println("< _FLUSH_ <- "+getPerfString()+" @ "+getThreadName()); } int processedBufferCount = 0; al.alSourcei(alSource.getID(), ALConstants.AL_BUFFER, 0); // explicit force zero buffer! @@ -914,7 +887,7 @@ public final class ALAudioSink implements AudioSink { lastBufferedPTS = TimeFrameI.INVALID_PTS; playingPTS = TimeFrameI.INVALID_PTS; if(DEBUG_TRACE) { - System.err.println("<< _FLUSH_ [al "+processedBufferCount+", err "+toHexString(alErr)+"] <- "+shortString()+" @ "+getThreadName()); + System.err.println("<< _FLUSH_ [al "+processedBufferCount+", err "+toHexString(alErr)+"] <- "+getPerfString()+" @ "+getThreadName()); ExceptionUtils.dumpStack(System.err); } } @@ -931,12 +904,12 @@ public final class ALAudioSink implements AudioSink { // start continuous playback. makeCurrent(true /* throw */); try { + final int sourceState0 = DEBUG ? getSourceState(false) : 0; final float neededDuration = chosenFormat.getBytesDuration(byteCount); // [s] @SuppressWarnings("unused") int dequeuedBufferCount = 0; int enqueuedBuffers = alFramesPlaying.size(); final int queueLimitBuffers; - final int latencyBuffers; final char avgUpdateC; // 1) SOFT dequeue w/o wait @@ -950,12 +923,11 @@ public final class ALAudioSink implements AudioSink { } else { avgUpdateC = '_'; } - latencyBuffers = Math.max(1, Math.round(latency / avgFrameDuration)); queueLimitBuffers = Math.max(1, Math.round(queueSize/1000f / avgFrameDuration)); if( emptyFreeFrames || enqueuedBuffers >= queueLimitBuffers * 2 / 3 ) { if( DEBUG ) { - System.err.printf("%s: ALAudioSink.DequeuSoft"+avgUpdateC+": %.2f ms, soft-dequeue, latencyBuffs %d, queued %d/%d, %s%n", - getThreadName(), 1000f*neededDuration, latencyBuffers, enqueuedBuffers, queueLimitBuffers, getPerfString()); + System.err.printf("%s: ALAudioSink.DequeuSoft"+avgUpdateC+": %.2f ms, queued %d/%d, %s%n", + getThreadName(), 1000f*neededDuration, enqueuedBuffers, queueLimitBuffers, getPerfString()); } dequeuedBufferCount = dequeueBuffer( false /* wait */, 1, false /* ignoreBufferInconsistency */ ); } @@ -966,9 +938,9 @@ public final class ALAudioSink implements AudioSink { // 2) HARD dequeue with wait if( 0 == availFrames && isPlayingImpl() ) { // possible if grow failed or already exceeds it's limit - only possible if playing .. - final int releaseBuffersHardReq = Math.max(latencyBuffers, enqueuedBuffers / 3 ); // [latencyBuffers .. enqueuedBuffers / 3] + final int releaseBuffersHardReq = Math.max(1, enqueuedBuffers / 3 ); // [1 .. enqueuedBuffers / 3] if( DEBUG ) { - System.err.printf("%s: ALAudioSink.DequeuHard"+avgUpdateC+": %.2f ms, hard-dequeue %d, queued %d/%d, %s%n", + System.err.printf("%s: ALAudioSink.DequeuHard"+avgUpdateC+": %.2f ms, req %d, queued %d/%d, %s%n", getThreadName(), 1000f*neededDuration, releaseBuffersHardReq, enqueuedBuffers, queueLimitBuffers, getPerfString()); } dequeuedBufferCount += dequeueBuffer( true /* wait */, releaseBuffersHardReq, false /* ignoreBufferInconsistency */ ); @@ -1010,19 +982,28 @@ public final class ALAudioSink implements AudioSink { al.alBufferData(alFrame.alBuffer, alFormat, bytes, byteCount, chosenFormat.sampleRate); } - if(DEBUG_TRACE) { - System.err.println("> "+alFrame.alBuffer+" -> "+shortString()+" @ "+getThreadName()); - } - alSource.queueBuffers(alBufferNames); alBufferBytesQueued += byteCount; enqueuedFrameCount++; // safe: only written-to while locked! if(DEBUG_TRACE) { - System.err.println(">> "+alFrame.alBuffer+" -> "+shortString()+" @ "+getThreadName()); + System.err.println(">> "+alFrame.alBuffer+" -> "+getPerfString()+" @ "+getThreadName()); + } + if( DEBUG ) { + final int sourceState1 = getSourceState(false); + playImpl(); // continue playing, fixes issue where we ran out of enqueued data! + final int sourceState2 = getSourceState(false); + if( sourceState0 != sourceState1 || sourceState0 != sourceState2 || sourceState1 != sourceState2 ) { + System.err.printf("%s: ALAudioSink.Enqueued : %.2f ms, %s, state* %s -> %s -> %s%n", + getThreadName(), 1000f*neededDuration, getPerfString(), + ALHelpers.alSourceStateString(sourceState0), ALHelpers.alSourceStateString(sourceState1), ALHelpers.alSourceStateString(sourceState2)); + } else { + System.err.printf("%s: ALAudioSink.Enqueued : %.2f ms, %s, state %s%n", + getThreadName(), 1000f*neededDuration, getPerfString(), ALHelpers.alSourceStateString(sourceState2)); + } + } else { + playImpl(); // continue playing, fixes issue where we ran out of enqueued data! } - - playImpl(); // continue playing, fixes issue where we ran out of enqueued data! } finally { release(true /* throw */); } @@ -1090,7 +1071,7 @@ public final class ALAudioSink implements AudioSink { try { playImpl(); if( DEBUG ) { - System.err.println(getThreadName()+": ALAudioSink: PLAY playImpl "+(ALConstants.AL_PLAYING == getSourceState(false))+", "+this); + System.err.println(getThreadName()+": ALAudioSink: play, state "+ALHelpers.alSourceStateString(getSourceState(false))+", "+this); } } finally { release(true /* throw */); @@ -1113,7 +1094,7 @@ public final class ALAudioSink implements AudioSink { try { pauseImpl(); if( DEBUG ) { - System.err.println(getThreadName()+": ALAudioSink: PAUSE playImpl "+(ALConstants.AL_PLAYING == getSourceState(false))+", "+this); + System.err.println(getThreadName()+": ALAudioSink: pause, state "+ALHelpers.alSourceStateString(getSourceState(false))+", "+this); } } finally { release(true /* throw */); @@ -1214,7 +1195,7 @@ public final class ALAudioSink implements AudioSink { throw new InternalError("XXX: "+this); } if( DEBUG ) { - System.err.println(getThreadName()+": ALAudioSink: FLUSH playImpl "+(ALConstants.AL_PLAYING == getSourceState(false))+", "+this); + System.err.println(getThreadName()+": ALAudioSink: flush, state "+ALHelpers.alSourceStateString(getSourceState(false))+", "+this); } } finally { release(true /* throw */); diff --git a/src/java/com/jogamp/openal/util/ALHelpers.java b/src/java/com/jogamp/openal/util/ALHelpers.java index fe48aa9..93dfa6e 100644 --- a/src/java/com/jogamp/openal/util/ALHelpers.java +++ b/src/java/com/jogamp/openal/util/ALHelpers.java @@ -588,4 +588,91 @@ public class ALHelpers { public static final int bytesToSampleCount(final int byteCount, final int alChannelLayout, final int alSampleType) { return byteCount / samplesToByteCount(1, alChannelLayout, alSampleType); } + + /** Returns given {@link ALConstants#AL_SOURCE_STATE} {@link AL#alGetSourcei(int, int, int[], int)}} value as a string. */ + public static final String alSourceStateString(final int sourceState) { + switch( sourceState ) { + case AL_INITIAL: return "initial"; + case AL_PLAYING: return "playing"; + case AL_PAUSED: return "paused"; + case AL_STOPPED: return "stopped"; + default: return "invalid"; + } + } + + /** + public static final String alConstantString(final int state) { + switch(state) { + case AL_ILLEGAL_COMMAND: return ""; + case AL_PROCESSED: return ""; + case AL_FREQUENCY: return ""; + case AL_NO_ERROR: return ""; + case AL_VENDOR: return ""; + case AL_STATIC: return ""; + // case AL_INVALID_ENUM: return ""; + case AL_MAX_DISTANCE: return ""; + case AL_ROLLOFF_FACTOR: return ""; + case AL_GAIN: return ""; + case AL_SIZE: return ""; + case AL_DISTANCE_MODEL: return ""; + case AL_BYTE_OFFSET: return ""; + case AL_SOURCE_STATE: return ""; + case AL_STOPPED: return ""; + case AL_REFERENCE_DISTANCE: return ""; + case AL_MIN_GAIN: return ""; + case AL_PLAYING: return ""; + case AL_INVERSE_DISTANCE_CLAMPED: return ""; + case AL_PITCH: return ""; + case AL_OUT_OF_MEMORY: return ""; + case AL_FORMAT_MONO8: return ""; + case AL_TRUE: return ""; + case AL_LINEAR_DISTANCE: return ""; + case AL_LOOPING: return ""; + case AL_STREAMING: return ""; + case AL_EXPONENT_DISTANCE_CLAMPED: return ""; + case AL_CHANNELS: return ""; + case AL_PAUSED: return ""; + case AL_CONE_OUTER_GAIN: return ""; + case AL_INVERSE_DISTANCE: return ""; + case AL_ILLEGAL_ENUM: return ""; + case AL_DIRECTION: return ""; + // case AL_INVALID_OPERATION: return ""; + case AL_ORIENTATION: return ""; + case AL_FORMAT_STEREO8: return ""; + case AL_CONE_OUTER_ANGLE: return ""; + case AL_DOPPLER_VELOCITY: return ""; + case AL_RENDERER: return ""; + case AL_SAMPLE_OFFSET: return ""; + case AL_FORMAT_STEREO16: return ""; + case AL_SEC_OFFSET: return ""; + case AL_POSITION: return ""; + case AL_PENDING: return ""; + case AL_UNUSED: return ""; + case AL_INVALID_VALUE: return ""; + // case AL_NONE: return ""; + case AL_BUFFER: return ""; + case AL_BUFFERS_PROCESSED: return ""; + case AL_VELOCITY: return ""; + case AL_DOPPLER_FACTOR: return ""; + case AL_MAX_GAIN: return ""; + case AL_SPEED_OF_SOUND: return ""; + case AL_UNDETERMINED: return ""; + case AL_EXTENSIONS: return ""; + case AL_EXPONENT_DISTANCE: return ""; + case AL_INVALID: return ""; + case AL_VERSION: return ""; + case AL_INITIAL: return ""; + case AL_BUFFERS_QUEUED: return ""; + case AL_BITS: return ""; + case AL_CONE_INNER_ANGLE: return ""; + case AL_SOURCE_RELATIVE: return ""; + case AL_SOURCE_TYPE: return ""; + case AL_LINEAR_DISTANCE_CLAMPED: return ""; + case AL_FORMAT_MONO16: return ""; + // case AL_FALSE: return ""; + case AL_INVALID_NAME: return ""; + default: return "0x"+Integer.toHexString(state); + } + } */ + } -- cgit v1.2.3