NuPlyaer AV Sync Log 初步分析
现象：播放某MP4视频一段时间后出现画面卡住，声音还在继续播放
怀疑点分析： 1、可能是video 没有送数据，不过粗略看了下没有eos，排除这个方向
2、decoder 没有解出数据来，看了omx的打印其实是有数据的，这个方向也排除
3、怀疑是否player 没有消耗decoder 后的数据或者av sync 卡住了，所以即使前面有送数据和解数据，那么可能送的数据是时间戳不对
如下是平台属性打印打开
su
setenforce 0
mount -o remount /data
chmod 777 /data
logcat -G 150M
setprop vendor.media.acodec.verbose.log 1
setprop vendor.media.mediacodec.dbg 1
setprop media.acodec.verbose.log 1
setprop vendor.ms.adec.log_on 99
setprop vendor.media.nuplayer.verbose.log 1
然后在Nuplayer Render中也将打印打开
抓到一份av.no.sync.log，从这份log也比较容易看到出问题点的时候了，video 滞后了 107s
12-27 16:09:46.735 3171 7201 V NuPlayerRenderer: video late by 107302037 us (107.30 secs)
这个打印是在
void NuPlayer::Renderer::onDrainVideoQueue() {
// 获取解码后buffer的时间戳
if (mFlags & FLAG_REAL_TIME) {
CHECK(entry->mBuffer->meta()->findInt64("timeUs", &realTimeUs));
} else {
CHECK(entry->mBuffer->meta()->findInt64("timeUs", &mediaTimeUs));
realTimeUs = getRealTimeUs(mediaTimeUs, nowUs);
}
// ...
// 用这个v_pts 跟 a_pts 比较，如果认为差值 > 4s，视频就不显示了，第一帧除外
tooLate = (mVideoLateByUs > 40000);
if (tooLate) {
ALOGI("video late by %lld us (%.2f secs)",
(long long)mVideoLateByUs, mVideoLateByUs / 1E6);
}
// ...
// Always render the first video frame while keeping stats on A/V sync.
if (!mVideoSampleReceived) {
realTimeUs = nowUs;
tooLate = false; // 第一帧除外
}
entry->mNotifyConsumed->setInt64("timestampNs", realTimeUs * 1000ll);
entry->mNotifyConsumed->setInt32("render", !tooLate); // render确认是否显示
entry->mNotifyConsumed->post();
}
可以看到上面的代码不管是否为 FLAG_REAL_TIME ，其都是根据 buffer "timeUs"来计算的，具体还有一个根据mediaclock 计算的方法，这个下次有机会再分析...
我遇到的问题其实都是 buffer "timeUs" 有问题，具体可以看如下打印
我们以591588 这个pts 来看
12-27 16:09:46.725 3171 7202 D MediaCodec: +Q in PTS = 591588
12-27 16:09:46.725 3171 7206 V ACodec : [OMX.MS.AVC.Decoder] calling emptyBuffer 4 w/ time 591588 us
12-27 16:09:46.725 3200 6142 D MS_OMX_BASEPORT: OMX.MS.AVC.Decoder ETB: 591588 3042
12-27 16:09:46.725 3171 7202 D MediaCodec: -Q in PTS = 591588
12-27 16:09:46.803 3200 7218 D MSTAR_VDEC_API: [0] Push: 591588 be2
12-27 16:09:46.803 3200 7218 D MS_OMX_VDEC: [OMX.MS.AVC.Decoder] EmptyThisBufferDone-in: PTS[591588]
12-27 16:09:46.872 3200 7217 D MSTAR_VDEC_API: [0] Get: 591588 0 0 2
12-27 16:09:46.872 3200 7217 D MS_OMX_VDEC: [OMX.MS.AVC.Decoder] FillThisBufferDone-in: PTS[591588] FLAG[10] LEN[848]
12-27 16:09:46.872 3171 7206 V ACodec : [OMX.MS.AVC.Decoder] onOMXFillBufferDone 19 time 591588 us, flags = 0x00000010
12-27 16:09:46.873 3171 7202 V NuPlayerDecoder: int64_t timeUs = 591588
12-27 16:09:46.874 3171 7206 D ACodec : [OMX.MS.AVC.Decoder] frame-drop PTS = 591588
12-27 16:09:46.874 3200 4062 D MSTAR_VDEC_API: [0] Free: 591588 0 0 ret = 1
12-27 16:09:46.874 3200 4062 D MS_OMX_BASEPORT: OMX.MS.AVC.Decoder FTB: 591588
1、MediaCodec/ACodec 往OMX 送 buffer，
725ms
ACodec: emptyBuffer 4 w/ time 591588 us
OMX:ETB: 591588
2、OMX内部推送buffer 解码，
803ms
Push: 591588
3、OMX 解码完成，通知ACodec 获取填充好的buffer
872ms
OMX: Get: 591588 0 0 2
ACodec: onOMXFillBufferDone 19 time 591588 us
Note:如果设置了surface 给mediacodec的话，其实这个时候返回的只是buffer index，然后将buffer index 传给surface 去消耗
4、使用完buffer 释放
874ms
ACodec : [OMX.MS.AVC.Decoder] frame-drop PTS = 591588
OMX: [0] Free: 591588 0 0 ret = 1
而这里的打印可以看到ACodec 将buffer drop 掉了， 而这里drop 受前面的 render 控制
12-27 16:09:46.874 3171 7206 D ACodec : [OMX.MS.AVC.Decoder] frame-drop PTS = 591588
void ACodec::BaseState::onOutputBufferDrained(const sp<AMessage> &msg) {
// ....
info->mData = buffer;
int32_t render;
if (mCodec->mNativeWindow != NULL
&& msg->findInt32("render", &render) && render != 0
&& !discarded && buffer->size() != 0) {
ATRACE_NAME("render");
// ...
} else {
if (mCodec->mNativeWindow != NULL && (discarded || buffer->size() != 0)) {
// move read fence into write fence to avoid clobbering
info->mIsReadFence = false;
ATRACE_NAME("frame-drop");
if (sVerboseLog)
{
int64_t timeUs = 0;
info->mData->meta()->findInt64("timeUs", &timeUs);
ALOGD("[%s] frame-drop PTS = %" PRId64 "", mCodec->mComponentName.c_str(), timeUs);
}
}
info->mStatus = BufferInfo::OWNED_BY_US;
}
经过上述的分析，可以看到其实就是进decoder pts有问题，那么其实就是demux出来的pts有问题，
这个可以通过这个打印来确认
status_t NuPlayer::Decoder::fetchInputData(sp<AMessage> &reply) {
#if 1
int64_t mediaTimeUs = -1;
accessUnit->meta()->findInt64("timeUs", &mediaTimeUs);
ALOGV("[%s] feeding input buffer at media time %.3f",
mIsAudio ? "audio" : "video",
mediaTimeUs / 1E6);
#endif
}
这里也可以直接确认这个 timeUs 是哪里设置的，这个是在Source read extractor pts的时候设置的
sp<ABuffer> NuPlayer::GenericSource::mediaBufferToABuffer(
MediaBufferBase* mb,
media_track_type trackType) {
int64_t timeUs;
CHECK(mb->meta_data().findInt64(kKeyTime, &timeUs));
meta->setInt64("timeUs", timeUs);
}
因为我这里是mp4 extractor，所以直接去extractor 中 看kKeyTime的相关逻辑，最终其实是一个数据类型溢出的问题，具体数据类型溢出的分析即情况后续再结合MP4 extractor 来分析
网友评论