diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsSustainedSendOutcomesInteropTest.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsSustainedSendOutcomesInteropTest.kt index 4a81cc3f8..266de6e6a 100644 --- a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsSustainedSendOutcomesInteropTest.kt +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsSustainedSendOutcomesInteropTest.kt @@ -300,6 +300,13 @@ class NostrNestsSustainedSendOutcomesInteropTest { Scenario(frameCount = 100, cadenceMs = 20L, framesPerGroup = 5), ) + @Test + fun harness_sweep_frames_per_group_10() = + runHarnessScenarioOrSkip( + "h-fpg10", + Scenario(frameCount = 100, cadenceMs = 20L, framesPerGroup = 10), + ) + @Test fun harness_sweep_frames_per_group_20() = runHarnessScenarioOrSkip( @@ -307,6 +314,15 @@ class NostrNestsSustainedSendOutcomesInteropTest { Scenario(frameCount = 100, cadenceMs = 20L, framesPerGroup = 20), ) + // Production default — see the matching note in + // NostrnestsProdAudioTransmissionTest.sweep_frames_per_group_50. + @Test + fun harness_sweep_frames_per_group_50_production_default() = + runHarnessScenarioOrSkip( + "h-fpg50", + Scenario(frameCount = 100, cadenceMs = 20L, framesPerGroup = 50), + ) + @Test fun harness_sweep_frames_per_group_all() = runHarnessScenarioOrSkip( diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrnestsProdAudioTransmissionTest.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrnestsProdAudioTransmissionTest.kt index 67feda78e..61c3841c0 100644 --- a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrnestsProdAudioTransmissionTest.kt +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrnestsProdAudioTransmissionTest.kt @@ -842,6 +842,13 @@ class NostrnestsProdAudioTransmissionTest { Scenario(frameCount = 100, cadenceMs = 20L, framesPerGroup = 5), ) + @Test + fun sweep_frames_per_group_10() = + runProdScenarioOrSkip( + "sweep-fpg10", + Scenario(frameCount = 100, cadenceMs = 20L, framesPerGroup = 10), + ) + @Test fun sweep_frames_per_group_20() = runProdScenarioOrSkip( @@ -849,6 +856,19 @@ class NostrnestsProdAudioTransmissionTest { Scenario(frameCount = 100, cadenceMs = 20L, framesPerGroup = 20), ) + // The production default. With a 20 ms cadence this batches a full + // second of audio into one uni stream — so the e2e-latency line for + // this scenario is the direct measurement of the send delay the + // production app exhibits today. Compare its timeToFirstFrame / + // p50 against sweep_frames_per_group_5 and the framesPerGroup=1 + // baseline to read the batching-vs-latency tradeoff curve. + @Test + fun sweep_frames_per_group_50_production_default() = + runProdScenarioOrSkip( + "sweep-fpg50", + Scenario(frameCount = 100, cadenceMs = 20L, framesPerGroup = 50), + ) + @Test fun sweep_frames_per_group_all() = runProdScenarioOrSkip( diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/SendTraceScenario.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/SendTraceScenario.kt index e3008a2b5..b9ffbea6e 100644 --- a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/SendTraceScenario.kt +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/SendTraceScenario.kt @@ -130,6 +130,13 @@ data class ScenarioResult( val scenario: Scenario, val sendOutcomes: BooleanArray, val sendDurationsMicros: LongArray, + /** + * Wall-clock time each frame was handed to [MoqLitePublisherHandle.send], + * relative to [collectStartedAtMs] (so it's on the same clock as + * [FrameArrival.wallMs]). Indexed by send order. `-1` for frames + * that were never sent (e.g. the run aborted early). + */ + val sendWallMsByIndex: LongArray, val endGroupErrors: Array, val arrivalsPerSubscriber: List>, val pumpStartedAtMs: Long, @@ -139,6 +146,36 @@ data class ScenarioResult( val sendTrueCount: Int get() = sendOutcomes.count { it } val firstFalseSendIndex: Int get() = sendOutcomes.indexOfFirst { !it } + /** + * Sorted end-to-end send→arrival latencies (ms) for every frame + * that reached [subscriberIndex]. This is the number that + * quantifies the "audio feels delayed" symptom: with + * `framesPerGroup > 1` the first frame of a group is sent + * immediately but the relay only forwards it once the group's uni + * stream is closed at the group boundary, so that frame's latency + * carries the whole batching window (≈ `framesPerGroup * cadenceMs`). + */ + fun e2eLatenciesMsFor(subscriberIndex: Int): LongArray = + arrivalIndexPerSubscriber[subscriberIndex] + .values + .mapNotNull { a -> + val sentAt = sendWallMsByIndex.getOrElse(a.objectId.toInt()) { -1L } + if (sentAt < 0) null else a.wallMs - sentAt + }.sorted() + .toLongArray() + + /** + * Latency (ms) of the first frame to arrive at [subscriberIndex] — + * the "time to first audio" a listener perceives when the speaker + * starts talking. `-1` if nothing arrived or its send time is + * unknown. + */ + fun timeToFirstFrameMsFor(subscriberIndex: Int): Long { + val first = arrivalsPerSubscriber[subscriberIndex].minByOrNull { it.wallMs } ?: return -1L + val sentAt = sendWallMsByIndex.getOrElse(first.objectId.toInt()) { -1L } + return if (sentAt < 0) -1L else first.wallMs - sentAt + } + /** * Per subscriber: `{objectId -> arrival}`. We index by objectId * (the per-session monotonic counter from @@ -232,6 +269,10 @@ object SendTraceScenario { val sendOutcomes = BooleanArray(scenario.frameCount) val sendDurationsMicros = LongArray(scenario.frameCount) + // Wall-clock send time per frame, on the same clock as + // FrameArrival.wallMs, so reportAndAssert can derive the true + // end-to-end send→arrival latency the listener perceives. + val sendWallMsByIndex = LongArray(scenario.frameCount) { -1L } val endGroupErrors = arrayOfNulls(scenario.frameCount) // Pre-sized synchronized ArrayList per subscriber. // CopyOnWriteArrayList (the previous choice) is O(N) per add — @@ -299,6 +340,7 @@ object SendTraceScenario { } val payload = payloadPrefix + byteArrayOf(i.toByte()) + sendWallMsByIndex[i] = System.currentTimeMillis() - collectStart val sendStartedNs = System.nanoTime() sendOutcomes[i] = publisher.send(payload) val sendElapsedNs = System.nanoTime() - sendStartedNs @@ -362,6 +404,7 @@ object SendTraceScenario { scenario = scenario, sendOutcomes = sendOutcomes, sendDurationsMicros = sendDurationsMicros, + sendWallMsByIndex = sendWallMsByIndex, endGroupErrors = endGroupErrors, // Snapshot under lock — synchronizedList iteration must // be guarded explicitly per the JDK contract. @@ -493,6 +536,24 @@ object SendTraceScenario { "firstSentButLost=$firstSentButLost " + "missing=${runs(missing)}", ) + + // End-to-end send→arrival latency. This is the line that + // answers "does audio feel delayed?" — with framesPerGroup + // > 1 the per-frame latency floor rises by roughly the + // batching window (framesPerGroup * cadenceMs) because the + // relay only forwards a group once its uni stream closes. + val latencies = result.e2eLatenciesMsFor(subscriberIndex) + if (latencies.isNotEmpty()) { + val p50 = latencies[latencies.size / 2] + val p99 = latencies[(latencies.size * 99 / 100).coerceAtMost(latencies.size - 1)] + InteropDebug.checkpoint( + scope, + "sub[$subscriberIndex] e2e latency (send→arrival): " + + "timeToFirstFrame=${result.timeToFirstFrameMsFor(subscriberIndex)}ms " + + "p50=${p50}ms p99=${p99}ms min=${latencies.first()}ms max=${latencies.last()}ms " + + "(framesPerGroup=${s.framesPerGroup}, cadence=${s.cadenceMs}ms)", + ) + } } // Average / min / max / p99 send latency, plus count of sends