jeka/utun2
1
0 Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Trace stream startup decoding and presentation delays

Browse Source
This commit is contained in:
evgeny committed 2026-10-20 21:34:24 +02:00
1 parent f38aa3b08d
commit 1b036e4ea9
3 files changed
+90 -20
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

src/stream/stream_playback_clock.c
+6 -2
View File
@@ -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;
tools/chatgui-android/app/src/main/java/com/utun/chat/data/StreamPlayerEngine.kt
+48 -8
View File
@@ -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<Int> = 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<Frame>(
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)
}
tools/chatgui/src/streamplayer_window.cpp
+36 -10
View File
@@ -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<bool> running{true}, audioAvailable{false};
std::atomic<bool> complete{false}, failed{false};
std::atomic<float> 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<Playback>()) {
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<std::mutex> guard(p.lock);
int64_t clock = p.clock(nowUs());
@@ -177,14 +181,22 @@ void StreamPlayerWindow::tick() {
p.videoBytes -= static_cast<size_t>(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<std::mutex> 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;
}
}