From 25f82752942b1c78aec8ee303d61afff85cff9d1 Mon Sep 17 00:00:00 2001 From: Chong Zhang Date: Wed, 8 Apr 2015 10:57:04 -0700 Subject: HLS: traces in LiveSession and PlaylistFetcher for easier debugging bug: 19567254 Change-Id: I4305d37cb74279ccd435f99483231cd1dcf42fc9 --- media/libstagefright/httplive/LiveSession.cpp | 122 +++++++++++++++++++------- 1 file changed, 88 insertions(+), 34 deletions(-) (limited to 'media/libstagefright/httplive/LiveSession.cpp') diff --git a/media/libstagefright/httplive/LiveSession.cpp b/media/libstagefright/httplive/LiveSession.cpp index 2d93152..f7a4a0d 100644 --- a/media/libstagefright/httplive/LiveSession.cpp +++ b/media/libstagefright/httplive/LiveSession.cpp @@ -141,6 +141,21 @@ const char *LiveSession::getKeyForStream(StreamType type) { return NULL; } +//static +const char *LiveSession::getNameForStream(StreamType type) { + switch (type) { + case STREAMTYPE_VIDEO: + return "video"; + case STREAMTYPE_AUDIO: + return "audio"; + case STREAMTYPE_SUBTITLES: + return "subs"; + default: + break; + } + return "unknown"; +} + LiveSession::LiveSession( const sp ¬ify, uint32_t flags, const sp &httpService) @@ -192,7 +207,11 @@ status_t LiveSession::dequeueAccessUnit( status_t finalResult = OK; sp packetSource = mPacketSources.valueFor(stream); - ssize_t idx = typeToIndex(stream); + ssize_t streamIdx = typeToIndex(stream); + if (streamIdx < 0) { + return INVALID_VALUE; + } + const char *streamStr = getNameForStream(stream); // Do not let client pull data if we don't have data packets yet. // We might only have a format discontinuity queued without data. // When NuPlayerDecoder dequeues the format discontinuity, it will @@ -200,6 +219,9 @@ status_t LiveSession::dequeueAccessUnit( // thinks it can do seamless change, so will not shutdown decoder. // When the actual format arrives, it can't handle it and get stuck. if (!packetSource->hasDataBufferAvailable(&finalResult)) { + ALOGV("[%s] dequeueAccessUnit: no buffer available (finalResult=%d)", + streamStr, finalResult); + if (finalResult == OK) { return -EAGAIN; } else { @@ -212,25 +234,6 @@ status_t LiveSession::dequeueAccessUnit( status_t err = packetSource->dequeueAccessUnit(accessUnit); - size_t streamIdx; - const char *streamStr; - switch (stream) { - case STREAMTYPE_AUDIO: - streamIdx = kAudioIndex; - streamStr = "audio"; - break; - case STREAMTYPE_VIDEO: - streamIdx = kVideoIndex; - streamStr = "video"; - break; - case STREAMTYPE_SUBTITLES: - streamIdx = kSubtitleIndex; - streamStr = "subs"; - break; - default: - TRESPASS(); - } - StreamItem& strm = mStreams[streamIdx]; if (err == INFO_DISCONTINUITY) { // adaptive streaming, discontinuities in the playlist @@ -249,9 +252,10 @@ status_t LiveSession::dequeueAccessUnit( } else if (err == OK) { if (stream == STREAMTYPE_AUDIO || stream == STREAMTYPE_VIDEO) { - int64_t timeUs; + int64_t timeUs, originalTimeUs; int32_t discontinuitySeq = 0; CHECK((*accessUnit)->meta()->findInt64("timeUs", &timeUs)); + originalTimeUs = timeUs; (*accessUnit)->meta()->findInt32("discontinuitySeq", &discontinuitySeq); if (discontinuitySeq > (int32_t) strm.mCurDiscontinuitySeq) { int64_t offsetTimeUs; @@ -303,7 +307,8 @@ status_t LiveSession::dequeueAccessUnit( timeUs += mDiscontinuityOffsetTimesUs.valueFor(discontinuitySeq); } - ALOGV("[%s] read buffer at time %" PRId64 " us", streamStr, timeUs); + ALOGV("[%s] dequeueAccessUnit: time %lld us, original %lld us", + streamStr, (long long)timeUs, (long long)originalTimeUs); (*accessUnit)->meta()->setInt64("timeUs", timeUs); mLastDequeuedTimeUs = timeUs; mRealTimeBaseUs = ALooper::GetNowUs() - timeUs; @@ -409,7 +414,7 @@ bool LiveSession::checkSwitchProgress( if (lastDequeueMeta == NULL) { // this means we don't have enough cushion, try again later ALOGV("[%s] up switching failed due to insufficient buffer", - stream == STREAMTYPE_AUDIO ? "audio" : "video"); + getNameForStream(stream)); return false; } } else { @@ -428,7 +433,7 @@ bool LiveSession::checkSwitchProgress( if (firstNewMeta[i] == NULL) { HLSTime dequeueTime(lastDequeueMeta); ALOGV("[%s] dequeue time (%d, %lld) past start time", - stream == STREAMTYPE_AUDIO ? "audio" : "video", + getNameForStream(stream), dequeueTime.mSeq, (long long) dequeueTime.mTimeUs); return false; } @@ -525,6 +530,11 @@ void LiveSession::onMessageReceived(const sp &msg) { break; } + ALOGV("fetcher-%d %s", + mFetcherInfos[index].mFetcher->getFetcherID(), + what == PlaylistFetcher::kWhatPaused ? + "paused" : "stopped"); + if (what == PlaylistFetcher::kWhatStopped) { mFetcherLooper->unregisterHandler( mFetcherInfos[index].mFetcher->id()); @@ -544,6 +554,7 @@ void LiveSession::onMessageReceived(const sp &msg) { if (--mContinuationCounter == 0) { mContinuation->post(); } + ALOGV("%zu fetcher(s) left", mContinuationCounter); } break; } @@ -636,6 +647,9 @@ void LiveSession::onMessageReceived(const sp &msg) { int32_t switchGeneration; CHECK(msg->findInt32("switchGeneration", &switchGeneration)); + ALOGV("kWhatStartedAt: switchGen=%d, mSwitchGen=%d", + switchGeneration, mSwitchGeneration); + if (switchGeneration != mSwitchGeneration) { break; } @@ -667,6 +681,7 @@ void LiveSession::onMessageReceived(const sp &msg) { if (checkSwitchProgress(stopParams, delayUs, &needResumeUntil)) { // playback time hasn't passed startAt time if (!needResumeUntil) { + ALOGV("finish switch"); for (size_t i = 0; i < kMaxStreams; ++i) { if ((mSwapMask & indexToType(i)) && uri == mStreams[i].mNewUri) { @@ -682,6 +697,7 @@ void LiveSession::onMessageReceived(const sp &msg) { // Resume fetcher for the original variant; the resumed fetcher should // continue until the timestamps found in msg, which is stored by the // new fetcher to indicate where the new variant has started buffering. + ALOGV("finish switch with resumeUntilAsync"); for (size_t i = 0; i < mFetcherInfos.size(); i++) { const FetcherInfo &info = mFetcherInfos.valueAt(i); if (info.mToBeRemoved) { @@ -693,8 +709,10 @@ void LiveSession::onMessageReceived(const sp &msg) { // playback time passed startAt time if (switchUp) { // if switching up, cancel and retry if condition satisfies again + ALOGV("cancel up switch because we're too late"); cancelBandwidthSwitch(true /* resume */); } else { + ALOGV("retry down switch at next sample"); resumeFetcher(uri, mSwapMask, -1, true /* newUri */); } } @@ -933,7 +951,8 @@ sp LiveSession::addFetcher(const char *uri) { notify->setInt32("switchGeneration", mSwitchGeneration); FetcherInfo info; - info.mFetcher = new PlaylistFetcher(notify, this, uri, mSubtitleGeneration); + info.mFetcher = new PlaylistFetcher( + notify, this, uri, mCurBandwidthIndex, mSubtitleGeneration); info.mDurationUs = -1ll; info.mToBeRemoved = false; info.mToBeResumed = false; @@ -1167,9 +1186,13 @@ bool LiveSession::resumeFetcher( } if (resume) { - ALOGV("resuming fetcher %s, timeUs %lld", uri.c_str(), (long long)timeUs); + sp &fetcher = mFetcherInfos.editValueAt(index).mFetcher; SeekMode seekMode = newUri ? kSeekModeNextSample : kSeekModeExactPosition; - mFetcherInfos.editValueAt(index).mFetcher->startAsync( + + ALOGV("resuming fetcher-%d, timeUs=%lld, seekMode=%d", + fetcher->getFetcherID(), (long long)timeUs, seekMode); + + fetcher->startAsync( sources[kAudioIndex], sources[kVideoIndex], sources[kSubtitleIndex], @@ -1406,6 +1429,9 @@ status_t LiveSession::selectTrack(size_t index, bool select) { return INVALID_OPERATION; } + ALOGV("selectTrack: index=%zu, select=%d, mSubtitleGen=%d++", + index, select, mSubtitleGeneration); + ++mSubtitleGeneration; status_t err = mPlaylist->selectTrack(index, select); if (err == OK) { @@ -1426,6 +1452,9 @@ ssize_t LiveSession::getSelectedTrack(media_track_type type) const { void LiveSession::changeConfiguration( int64_t timeUs, ssize_t bandwidthIndex, bool pickTrack) { + ALOGV("changeConfiguration: timeUs=%lld us, bwIndex=%zd, pickTrack=%d", + (long long)timeUs, bandwidthIndex, pickTrack); + cancelBandwidthSwitch(); CHECK(!mReconfigurationInProgress); @@ -1478,6 +1507,7 @@ void LiveSession::changeConfiguration( } if (discardFetcher) { + ALOGV("discarding fetcher-%d", fetcher->getFetcherID()); fetcher->stopAsync(); } else { float threshold = -1.0f; // always finish fetching by default @@ -1490,8 +1520,8 @@ void LiveSession::changeConfiguration( mOrigBandwidthIndex, mCurBandwidthIndex); } - ALOGV("Pausing with threshold %.3f", threshold); - + ALOGV("pausing fetcher-%d, threshold=%.2f", + fetcher->getFetcherID(), threshold); fetcher->pauseAsync(threshold); } } @@ -1526,6 +1556,8 @@ void LiveSession::changeConfiguration( } void LiveSession::onChangeConfiguration(const sp &msg) { + ALOGV("onChangeConfiguration"); + if (!mReconfigurationInProgress) { int32_t pickTrack = 0; msg->findInt32("pickTrack", &pickTrack); @@ -1536,6 +1568,8 @@ void LiveSession::onChangeConfiguration(const sp &msg) { } void LiveSession::onChangeConfiguration2(const sp &msg) { + ALOGV("onChangeConfiguration2"); + mContinuation.clear(); // All fetchers are either suspended or have been removed now. @@ -1670,6 +1704,11 @@ void LiveSession::onChangeConfiguration3(const sp &msg) { mRealTimeBaseUs = ALooper::GetNowUs() - timeUs; } + ALOGV("onChangeConfiguration3: timeUs=%lld, switching=%d, pickTrack=%d, " + "mStreamMask=0x%x, mNewStreamMask=0x%x, mSwapMask=0x%x", + (long long)timeUs, switching, pickTrack, + mStreamMask, mNewStreamMask, mSwapMask); + for (size_t i = 0; i < kMaxStreams; ++i) { if (streamMask & indexToType(i)) { if (switching) { @@ -1687,6 +1726,9 @@ void LiveSession::onChangeConfiguration3(const sp &msg) { for (size_t i = 0; i < mFetcherInfos.size(); ++i) { const AString &uri = mFetcherInfos.keyAt(i); if (!resumeFetcher(uri, resumeMask, timeUs)) { + ALOGV("marking fetcher-%d to be removed", + mFetcherInfos[i].mFetcher->getFetcherID()); + mFetcherInfos.editValueAt(i).mToBeRemoved = true; } } @@ -1776,6 +1818,14 @@ void LiveSession::onChangeConfiguration3(const sp &msg) { } } + ALOGV("[fetcher-%d] startAsync: startTimeUs %lld mLastSeekTimeUs %lld " + "segmentStartTimeUs %lld seekMode %d", + fetcher->getFetcherID(), + (long long)startTime.mTimeUs, + (long long)mLastSeekTimeUs, + (long long)startTime.getSegmentTimeUs(true /* midpoint */), + seekMode); + // Set the target segment start time to the middle point of the // segment where the last sample was. // This gives a better guess if segments of the two variants are not @@ -1795,7 +1845,6 @@ void LiveSession::onChangeConfiguration3(const sp &msg) { // All fetchers have now been started, the configuration change // has completed. - ALOGV("XXX configuration change completed."); mReconfigurationInProgress = false; if (switching) { mSwitchInProgress = true; @@ -1804,13 +1853,16 @@ void LiveSession::onChangeConfiguration3(const sp &msg) { mOrigBandwidthIndex = mCurBandwidthIndex; } + ALOGV("onChangeConfiguration3: mSwitchInProgress %d, mStreamMask 0x%x", + mSwitchInProgress, mStreamMask); + if (mDisconnectReplyID != NULL) { finishDisconnect(); } } void LiveSession::swapPacketSource(StreamType stream) { - ALOGV("swapPacketSource: stream = %d", stream); + ALOGV("[%s] swapPacketSource", getNameForStream(stream)); // transfer packets from source2 to source sp &aps = mPacketSources.editValueFor(stream); @@ -1858,7 +1910,7 @@ void LiveSession::tryToFinishBandwidthSwitch(const AString &oldUri) { mFetcherInfos.editValueAt(index).mFetcher->stopAsync(false /* clear */); - ALOGV("tryToFinishBandwidthSwitch: mSwapMask=%x", mSwapMask); + ALOGV("tryToFinishBandwidthSwitch: mSwapMask=0x%x", mSwapMask); if (mSwapMask != 0) { return; } @@ -1983,7 +2035,7 @@ void LiveSession::cancelBandwidthSwitch(bool resume) { } ALOGI("#### Canceled Bandwidth Switch: %zd => %zd", - mCurBandwidthIndex, mOrigBandwidthIndex); + mOrigBandwidthIndex, mCurBandwidthIndex); mSwitchGeneration++; mSwitchInProgress = false; @@ -2022,7 +2074,9 @@ bool LiveSession::checkBuffering( int64_t bufferedDurationUs = mPacketSources[i]->getEstimatedDurationUs(); - ALOGV("source[%zu]: buffered %lld us", i, (long long)bufferedDurationUs); + ALOGV("[%s] buffered %lld us", + getNameForStream(mPacketSources.keyAt(i)), + (long long)bufferedDurationUs); if (durationUs >= 0) { int32_t percent; if (mPacketSources[i]->isFinished(0 /* duration */)) { -- cgit v1.1