diff --git a/src/stream/stream_playback_clock.c b/src/stream/stream_playback_clock.c index 29eea7dd..90f04a11 100644 --- a/src/stream/stream_playback_clock.c +++ b/src/stream/stream_playback_clock.c @@ -90,12 +90,16 @@ int stream_playback_clock_update(struct stream_playback_clock *c, int64_t now, i .correction_us = c->correction_us, .stable_us = stable, .removable_us = removable, .tempo_milli = c->tempo_milli, .waiting = c->waiting, .history_ready = complete}; if (!c->report_us || now - c->report_us >= 1000000) { + const char *reason = c->waiting ? "starved" : !complete ? "history" : stable < 60000000 ? "cooldown" + : removable <= braking ? "reserve" : "catchup"; DEBUG_DEBUG(DEBUG_CATEGORY_STREAM, "playback reserve id=%llu pts=%lld ready=%lld reserve=%lld minimum=%lld correction=%lld " - "stable_ms=%lld history=%u tempo=%d pending_gain=%lld waiting=%d", + "stable_ms=%lld history=%u tempo=%d pending_gain=%lld waiting=%d " + "guard_us=%lld removable_us=%lld braking_us=%lld reason=%s", (unsigned long long)c->id, (long long)position, (long long)ready, (long long)reserve, (long long)minimum, (long long)c->correction_us, (long long)(stable / 1000), samples, - c->tempo_milli, (long long)pending_gain, c->waiting); + c->tempo_milli, (long long)pending_gain, c->waiting, + (long long)guard, (long long)removable, (long long)braking, reason); c->report_us = now; } c->last_us = now; c->last_position_us = position; *state = result; diff --git a/tools/chatgui-android/app/src/main/java/com/utun/chat/data/StreamPlayerEngine.kt b/tools/chatgui-android/app/src/main/java/com/utun/chat/data/StreamPlayerEngine.kt index 48071025..78a1347d 100644 --- a/tools/chatgui-android/app/src/main/java/com/utun/chat/data/StreamPlayerEngine.kt +++ b/tools/chatgui-android/app/src/main/java/com/utun/chat/data/StreamPlayerEngine.kt @@ -51,6 +51,7 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv private val mutableStatus = MutableStateFlow(R.string.stream_connecting) val status: StateFlow = mutableStatus private val id = StreamController.nextId() + private var requestedAtUs = 0L @Volatile private var running = false @Volatile var drainTimeoutMs = 2000L private set @@ -67,6 +68,9 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv return } players.add(this); mutableViewing.value = true + requestedAtUs = System.nanoTime() / 1000 + LogManager.addLog("INFO", "stream", "android viewer requested id=$id source=${source.toULong().toString(16)} " + + "epoch=${epoch.toULong().toString(16)}") running = true worker = Thread({ try { if (running) play(surface) } @@ -111,10 +115,14 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv var deadline = System.nanoTime() + 10_000_000_000 val info = MediaCodec.BufferInfo() var clockState: LongArray? = null + var firstInputAtUs = 0L + var firstShown = false + var lastShownPts = -1L fun createVideoPump() = StreamDecodePump( submit = { frame -> if (decoder == null) { + val openingAtUs = System.nanoTime() / 1000 check(frame.key) val format = frame.codec.decoderFormat(frame.width, frame.height, frame.rotation, frame.config) val codecs = MediaCodecList(MediaCodecList.REGULAR_CODECS) @@ -133,8 +141,23 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv if (Build.VERSION.SDK_INT >= 30) format.setInteger(MediaFormat.KEY_LOW_LATENCY, if (lowLatency) 1 else 0) attempt = MediaCodec.createByCodecName(candidate.name) attempt.configure(format, surface, null, 0); attempt.start(); decoder = attempt + var firstRendered = true + val codecRevision = frame.revision + try { + attempt.setOnFrameRenderedListener({ _, pts, renderedNs -> + if (firstRendered) { + firstRendered = false + LogManager.addLog("INFO", "stream", "android first surface frame id=$id revision=$codecRevision " + + "PTS=$pts elapsedUs=${renderedNs / 1000 - requestedAtUs} " + + "callbackDelayUs=${System.nanoTime() / 1000 - renderedNs / 1000}") + } + }, main) + } catch (e: Exception) { + LogManager.addLog("WARN", "stream", "viewer presentation diagnostics unavailable id=$id: ${e.message}") + } LogManager.addLog("INFO", "video", "viewer codec id=$id type=${frame.codec.label} decoder=${candidate.name} " + - "config=${frame.config.size} lowLatency=$lowLatency revision=$videoRevision") + "config=${frame.config.size} lowLatency=$lowLatency revision=$videoRevision " + + "elapsedUs=${System.nanoTime() / 1000 - requestedAtUs} openUs=${System.nanoTime() / 1000 - openingAtUs}") break } catch (e: Exception) { failure = e @@ -153,7 +176,9 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv if (index < 0) false else { val input = decoder!!.getInputBuffer(index) ?: error("Missing decoder input") check(frame.data.size <= input.capacity()) { "Decoder input is too small: ${input.capacity()}/${frame.data.size}" } - input.clear(); input.put(frame.data); decoder!!.queueInputBuffer(index, 0, frame.data.size, frame.pts, 0); true + input.clear(); input.put(frame.data) + if (firstInputAtUs == 0L) firstInputAtUs = System.nanoTime() / 1000 + decoder!!.queueInputBuffer(index, 0, frame.data.size, frame.pts, 0); true } }, receive = { @@ -177,7 +202,17 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv }, release = { output, render -> decoder!!.releaseOutputBuffer(output.index, render) - if (render) mutableStatus.value = R.string.stream_live + if (render) { + lastShownPts = output.pts + if (!firstShown) { + firstShown = true + LogManager.addLog("INFO", "stream", "android first frame id=$id stage=display_submit " + + "elapsedUs=${System.nanoTime() / 1000 - requestedAtUs} PTS=${output.pts} clockUs=$position " + + "readyUs=$ready readyAheadUs=${ready - output.pts} avUs=${output.pts - position} " + + "deviceLeadUs=${playback?.leadUs}") + } + mutableStatus.value = R.string.stream_live + } } ) @@ -188,13 +223,15 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv audioEnabled = meta[5] and 2 != 0L playback = StreamMixedPlayback(id, meta[3], audioEnabled) position = meta[3]; generation = meta[4] - LogManager.addLog("INFO", "stream", "playback starts id=$id PTS=$position generation=$generation fixedPrefill=0") + LogManager.addLog("INFO", "stream", "playback starts id=$id PTS=$position generation=$generation fixedPrefill=0 " + + "elapsedUs=${System.nanoTime() / 1000 - requestedAtUs} readyUs=$ready videoUs=${meta[1]} audioUs=${meta[2]} " + + "initialReserveUs=${ready - position} audio=$audioEnabled") } fun resetVideo() { try { decoder?.stop(); decoder?.release() } catch (e: Exception) { LogManager.addLog("WARN", "video", "decoder reset id=$id: ${e.message}") } - decoder = null; video = createVideoPump() + decoder = null; video = createVideoPump(); firstInputAtUs = 0 waitingKey = true; eosQueued = false mutableStatus.value = R.string.stream_waiting_key } @@ -243,7 +280,8 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv waitingKey = false mutableAspect.value = if (broadcastRotation % 180 == 0) width.toFloat() / height else height.toFloat() / width mutableStatus.value = R.string.stream_waiting_decoder - LogManager.addLog("INFO", "video", "viewer KEY accepted id=$id revision=$revision PTS=$pts bytes=$size") + LogManager.addLog("INFO", "video", "viewer KEY accepted id=$id revision=$revision PTS=$pts bytes=$size " + + "elapsedUs=${System.nanoTime() / 1000 - requestedAtUs} readyAheadUs=${ready - pts}") } video.offer(Frame(pts, key, width, height, broadcastRotation, revision, codec, access.first, access.second), System.nanoTime() / 1000) @@ -272,7 +310,8 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv if (!playbackStarted && video.firstOutputPts != null) { playbackStarted = true LogManager.addLog("INFO", "video", "viewer first decoded frame id=$id revision=$videoRevision " + - "PTS=${video.firstOutputPts} inputs=${video.inputCount} decoderLeadUs=${video.decoderLeadUs}") + "PTS=${video.firstOutputPts} inputs=${video.inputCount} decoderLeadUs=${video.decoderLeadUs} " + + "elapsedUs=${System.nanoTime() / 1000 - requestedAtUs} decodeUs=${System.nanoTime() / 1000 - firstInputAtUs}") } if (playbackStarted && playback != null && ready >= 0) { val lateVideo = !video.ended && (video.firstOutputPts == null @@ -305,7 +344,8 @@ class StreamPlayerEngine(private val group: Long, private val source: Long, priv "output=${video.output?.pts} inflight=${video.inflight} decoderLeadUs=${video.decoderLeadUs} " + "clock=$position ready=$ready audio=$audioEnabled audioInputs=$audioInputs audioPTS=$lastAudioPts needsAudio=$needsAudio " + "reserve=${clockState?.get(1)} minimum=${clockState?.get(2)} " + - "tempo=${clockState?.get(3)} ${playback?.description} waitingKey=$waitingKey") + "tempo=${clockState?.get(3)} ${playback?.description} waitingKey=$waitingKey " + + "shownPTS=$lastShownPts displayLagUs=${if (lastShownPts >= 0) position - lastShownPts else -1}") } Thread.sleep(5) } diff --git a/tools/chatgui/src/streamplayer_window.cpp b/tools/chatgui/src/streamplayer_window.cpp index c30a7e4a..23016652 100644 --- a/tools/chatgui/src/streamplayer_window.cpp +++ b/tools/chatgui/src/streamplayer_window.cpp @@ -49,6 +49,7 @@ struct StreamPlayerWindow::Playback { bool held = false; } audioGap; uint64_t id = ++nextId, group = 0, source = 0, epoch = 0; + int64_t createdAt = nowUs(), firstInputAt = 0; std::atomic running{true}, audioAvailable{false}; std::atomic complete{false}, failed{false}; std::atomic volume{1.0f}; @@ -90,6 +91,8 @@ struct StreamPlayerWindow::Playback { StreamPlayerWindow::StreamPlayerWindow(uint64_t group, uint64_t source, uint64_t epoch, const QString& name, QWidget* parent, bool embedded) : QWidget(parent), m_playback(std::make_unique()) { m_playback->group = group; m_playback->source = source; m_playback->epoch = epoch; + DEBUG_INFO(DEBUG_CATEGORY_STREAM, "desktop viewer requested id=%llu source=%llx epoch=%llx", + (unsigned long long)m_playback->id, (unsigned long long)source, (unsigned long long)epoch); setWindowTitle(text("Live stream: %1").arg(name)); resize(800, 500); setObjectName(QStringLiteral("streamPlayer_%1").arg(source)); auto* layout = new QVBoxLayout(this); auto* title = new QLabel(name, this); layout->addWidget(title); @@ -170,6 +173,7 @@ void StreamPlayerWindow::tick() { auto& p = *m_playback; if (!SoundManager::instance()->outputAvailable()) p.audioAvailable = false; QImage image; bool finished = false, first = false; + int64_t shownPts = -1, readyPts = -1, mediaPosition = -1, deviceLead = 0; { std::lock_guard guard(p.lock); int64_t clock = p.clock(nowUs()); @@ -177,14 +181,22 @@ void StreamPlayerWindow::tick() { p.videoBytes -= static_cast(p.videos.front().image.sizeInBytes()); p.lastShownPts = p.videos.front().pts; image = std::move(p.videos.front().image); p.videos.pop_front(); } - if (!image.isNull()) first = p.shown++ == 0; + if (!image.isNull()) { + first = p.shown++ == 0; + shownPts = p.lastShownPts; readyPts = p.ready; mediaPosition = clock; deviceLead = p.deviceLead; + } bool audioDone = !p.activeAudio || !p.audioAvailable || (p.endFrames != UINT64_MAX && p.played(nowUs()) >= p.endFrames); finished = p.ended && p.videoEnded && p.videos.empty() && audioDone; } if (!image.isNull()) { m_render->setFrame(image); m_status->setText(text("Live")); - if (first) DEBUG_INFO(DEBUG_CATEGORY_STREAM, "desktop first frame id=%llu %dx%d RGB_stride=%lld", - (unsigned long long)p.id, image.width(), image.height(), (long long)image.bytesPerLine()); + if (first) DEBUG_INFO(DEBUG_CATEGORY_STREAM, + "desktop first frame id=%llu source=%llx epoch=%llx %dx%d RGB_stride=%lld stage=display_submit " + "elapsed_us=%lld pts=%lld clock_us=%lld ready_us=%lld ready_ahead_us=%lld av_us=%lld device_lead_us=%lld", + (unsigned long long)p.id, (unsigned long long)p.source, (unsigned long long)p.epoch, + image.width(), image.height(), (long long)image.bytesPerLine(), (long long)(nowUs() - p.createdAt), + (long long)shownPts, (long long)mediaPosition, (long long)readyPts, (long long)(readyPts - shownPts), + (long long)(shownPts - mediaPosition), (long long)deviceLead); emit framePresented(); } if (finished || p.failed) { @@ -259,8 +271,12 @@ void StreamPlayerWindow::decode() { if (p.activeAudio && !p.sound) { p.running = false; return; } p.position = status.start_us; p.clockAt = nowUs(); p.started = true; stream_playback_clock_reset(&p.adaptation, p.id); - DEBUG_INFO(DEBUG_CATEGORY_STREAM, "desktop playback starts id=%llu pts=%lld fixed_prefill=0", - (unsigned long long)p.id, (long long)p.position); + DEBUG_INFO(DEBUG_CATEGORY_STREAM, + "desktop playback starts id=%llu pts=%lld fixed_prefill=0 elapsed_us=%lld " + "ready_us=%lld video_us=%lld audio_us=%lld initial_reserve_us=%lld audio=%d", + (unsigned long long)p.id, (long long)p.position, (long long)(nowUs() - p.createdAt), + (long long)status.ready_us, (long long)status.video_us, (long long)status.audio_us, + (long long)((p.activeAudio ? status.ready_us : status.video_us) - p.position), p.activeAudio); } p.ready = p.activeAudio ? status.ready_us : status.video_us; }; @@ -291,8 +307,10 @@ void StreamPlayerWindow::decode() { pts = frame->best_effort_timestamp == AV_NOPTS_VALUE ? p.lastInputPts : frame->best_effort_timestamp; p.decoderLead = std::max(p.decoderLead, p.lastInputPts - pts); p.lastDecodedPts = pts; p.videoReady = true; if (!p.presenting) { p.presenting = true; p.clockAt = nowUs(); - DEBUG_INFO(DEBUG_CATEGORY_VIDEO, "desktop first decoded frame id=%llu pts=%lld decoder_lead=%lld", - (unsigned long long)p.id, (long long)pts, (long long)p.decoderLead); } + DEBUG_INFO(DEBUG_CATEGORY_VIDEO, + "desktop first decoded frame id=%llu pts=%lld decoder_lead=%lld elapsed_us=%lld decode_us=%lld ready_ahead_us=%lld", + (unsigned long long)p.id, (long long)pts, (long long)p.decoderLead, (long long)(nowUs() - p.createdAt), + (long long)(p.firstInputAt ? nowUs() - p.firstInputAt : -1), (long long)(p.ready - pts)); } if (pts < p.clock(nowUs()) - 100000) { discarded++; continue; } } converter = sws_getCachedContext(converter, frame->width, frame->height, (AVPixelFormat)frame->format, frame->width, frame->height, AV_PIX_FMT_RGB24, SWS_BILINEAR, nullptr, nullptr, nullptr); @@ -425,6 +443,7 @@ void StreamPlayerWindow::decode() { } } if (!decoder) { + int64_t openingAt = nowUs(); AVCodecID codecId = record.format.video_codec == STREAM_MEDIA_H264 ? AV_CODEC_ID_H264 : record.format.video_codec == STREAM_MEDIA_H265 ? AV_CODEC_ID_HEVC : record.format.video_codec == STREAM_MEDIA_VP9 ? AV_CODEC_ID_VP9 @@ -449,8 +468,12 @@ void StreamPlayerWindow::decode() { record.format.video_codec, codec ? codec->name : "unavailable", configurationSize, openResult); fail(text("Stream video decoder failed")); break; } - DEBUG_INFO(DEBUG_CATEGORY_STREAM, "desktop decoder codec=%u name=%s config=%zu", record.format.video_codec, codec->name, configurationSize); + DEBUG_INFO(DEBUG_CATEGORY_STREAM, + "desktop decoder id=%llu codec=%u name=%s config=%zu elapsed_us=%lld open_us=%lld key_pts=%llu", + (unsigned long long)p.id, record.format.video_codec, codec->name, configurationSize, + (long long)(nowUs() - p.createdAt), (long long)(nowUs() - openingAt), (unsigned long long)record.pts); decoder->pkt_timebase = AVRational{1, 1000000}; waitKey = false; + p.firstInputAt = nowUs(); } av_packet_unref(packet); if (av_new_packet(packet, (int)size) < 0) { fail(text("Stream decoder allocation failed")); break; } @@ -462,11 +485,14 @@ void StreamPlayerWindow::decode() { std::lock_guard guard(p.lock); DEBUG_DEBUG(DEBUG_CATEGORY_STREAM, "desktop viewer id=%llu decoded=%llu discarded=%llu shown=%llu showFps=%.1f videoQ=%zu " - "clock=%lld reserve_us=%lld minimum_us=%lld tempo=%d lead_us=%lld underruns=%llu", + "clock=%lld reserve_us=%lld minimum_us=%lld tempo=%d lead_us=%lld underruns=%llu " + "ready_us=%lld shown_pts=%lld display_lag_us=%lld decoder_lead_us=%lld hold=%d", (unsigned long long)p.id, (unsigned long long)decoded, (unsigned long long)discarded, (unsigned long long)p.shown, (p.shown - reportedShown) / seconds, p.videos.size(), (long long)p.position, (long long)p.timing.reserve_us, (long long)p.timing.minimum_us, p.timing.tempo_milli, - (long long)p.deviceLead, (unsigned long long)p.underruns); + (long long)p.deviceLead, (unsigned long long)p.underruns, (long long)p.ready, + (long long)p.lastShownPts, (long long)(p.lastShownPts >= 0 ? p.position - p.lastShownPts : -1), + (long long)p.decoderLead, p.holdAudio); reportedShown = p.shown; } }