diff options
author | Chong Zhang <chz@google.com> | 2015-04-08 10:57:04 -0700 |
---|---|---|
committer | Chong Zhang <chz@google.com> | 2015-04-08 12:30:57 -0700 |
commit | 25f82752942b1c78aec8ee303d61afff85cff9d1 (patch) | |
tree | a3f9a36f9d55a95d96c4c008f027312ed5257031 | |
parent | 6dc4dc4ad23dc82eca9af3112292f3e6d5b17b15 (diff) | |
download | frameworks_av-25f82752942b1c78aec8ee303d61afff85cff9d1.zip frameworks_av-25f82752942b1c78aec8ee303d61afff85cff9d1.tar.gz frameworks_av-25f82752942b1c78aec8ee303d61afff85cff9d1.tar.bz2 |
HLS: traces in LiveSession and PlaylistFetcher for easier debugging
bug: 19567254
Change-Id: I4305d37cb74279ccd435f99483231cd1dcf42fc9
-rw-r--r-- | media/libstagefright/httplive/LiveSession.cpp | 122 | ||||
-rw-r--r-- | media/libstagefright/httplive/LiveSession.h | 1 | ||||
-rw-r--r-- | media/libstagefright/httplive/PlaylistFetcher.cpp | 98 | ||||
-rw-r--r-- | media/libstagefright/httplive/PlaylistFetcher.h | 5 | ||||
-rw-r--r-- | media/libstagefright/mpeg2ts/AnotherPacketSource.cpp | 4 |
5 files changed, 172 insertions, 58 deletions
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<AMessage> ¬ify, uint32_t flags, const sp<IMediaHTTPService> &httpService) @@ -192,7 +207,11 @@ status_t LiveSession::dequeueAccessUnit( status_t finalResult = OK; sp<AnotherPacketSource> 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<AMessage> &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<AMessage> &msg) { if (--mContinuationCounter == 0) { mContinuation->post(); } + ALOGV("%zu fetcher(s) left", mContinuationCounter); } break; } @@ -636,6 +647,9 @@ void LiveSession::onMessageReceived(const sp<AMessage> &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<AMessage> &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<AMessage> &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<AMessage> &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<PlaylistFetcher> 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<PlaylistFetcher> &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<AMessage> &msg) { + ALOGV("onChangeConfiguration"); + if (!mReconfigurationInProgress) { int32_t pickTrack = 0; msg->findInt32("pickTrack", &pickTrack); @@ -1536,6 +1568,8 @@ void LiveSession::onChangeConfiguration(const sp<AMessage> &msg) { } void LiveSession::onChangeConfiguration2(const sp<AMessage> &msg) { + ALOGV("onChangeConfiguration2"); + mContinuation.clear(); // All fetchers are either suspended or have been removed now. @@ -1670,6 +1704,11 @@ void LiveSession::onChangeConfiguration3(const sp<AMessage> &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<AMessage> &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<AMessage> &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<AMessage> &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<AMessage> &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<AnotherPacketSource> &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 */)) { diff --git a/media/libstagefright/httplive/LiveSession.h b/media/libstagefright/httplive/LiveSession.h index b5e31c9..e4f1b97 100644 --- a/media/libstagefright/httplive/LiveSession.h +++ b/media/libstagefright/httplive/LiveSession.h @@ -91,6 +91,7 @@ struct LiveSession : public AHandler { bool hasDynamicDuration() const; static const char *getKeyForStream(StreamType type); + static const char *getNameForStream(StreamType type); enum { kWhatStreamsChanged, diff --git a/media/libstagefright/httplive/PlaylistFetcher.cpp b/media/libstagefright/httplive/PlaylistFetcher.cpp index 368612d..ce79cc2 100644 --- a/media/libstagefright/httplive/PlaylistFetcher.cpp +++ b/media/libstagefright/httplive/PlaylistFetcher.cpp @@ -45,6 +45,10 @@ #include <openssl/aes.h> #include <openssl/md5.h> +#define FLOGV(fmt, ...) ALOGV("[fetcher-%d] " fmt, mFetcherID, ##__VA_ARGS__) +#define FSLOGV(stream, fmt, ...) ALOGV("[fetcher-%d] [%s] " fmt, mFetcherID, \ + LiveSession::getNameForStream(stream), ##__VA_ARGS__) + namespace android { // static @@ -143,10 +147,12 @@ PlaylistFetcher::PlaylistFetcher( const sp<AMessage> ¬ify, const sp<LiveSession> &session, const char *uri, + int32_t id, int32_t subtitleGeneration) : mNotify(notify), mSession(session), mURI(uri), + mFetcherID(id), mStreamTypeMask(0), mStartTimeUs(-1ll), mSegmentStartTimeUs(-1ll), @@ -176,6 +182,10 @@ PlaylistFetcher::PlaylistFetcher( PlaylistFetcher::~PlaylistFetcher() { } +int32_t PlaylistFetcher::getFetcherID() const { + return mFetcherID; +} + int64_t PlaylistFetcher::getSegmentStartTimeUs(int32_t seqNumber) const { CHECK(mPlaylist != NULL); @@ -436,7 +446,7 @@ void PlaylistFetcher::postMonitorQueue(int64_t delayUs, int64_t minDelayUs) { maxDelayUs = minDelayUs; } if (delayUs > maxDelayUs) { - ALOGV("Need to refresh playlist in %" PRId64 , maxDelayUs); + FLOGV("Need to refresh playlist in %lld", (long long)maxDelayUs); delayUs = maxDelayUs; } sp<AMessage> msg = new AMessage(kWhatMonitorQueue, this); @@ -507,6 +517,8 @@ void PlaylistFetcher::stopAsync(bool clear) { } void PlaylistFetcher::resumeUntilAsync(const sp<AMessage> ¶ms) { + FLOGV("resumeUntilAsync: params=%s", params->debugString().c_str()); + AMessage* msg = new AMessage(kWhatResumeUntil, this); msg->setMessage("params", params); msg->post(); @@ -763,8 +775,9 @@ void PlaylistFetcher::onMonitorQueue() { int64_t bufferedStreamDurationUs = mPacketSources.valueAt(i)->getBufferedDurationUs(&finalResult); - ALOGV("buffered %" PRId64 " for stream %d", - bufferedStreamDurationUs, mPacketSources.keyAt(i)); + + FSLOGV(mPacketSources.keyAt(i), "buffered %lld", (long long)bufferedStreamDurationUs); + if (bufferedDurationUs == -1ll || bufferedStreamDurationUs < bufferedDurationUs) { bufferedDurationUs = bufferedStreamDurationUs; @@ -776,8 +789,9 @@ void PlaylistFetcher::onMonitorQueue() { } if (finalResult == OK && bufferedDurationUs < kMinBufferedDurationUs) { - ALOGV("monitoring, buffered=%" PRId64 " < %" PRId64 "", - bufferedDurationUs, kMinBufferedDurationUs); + FLOGV("monitoring, buffered=%lld < %lld", + (long long)bufferedDurationUs, (long long)kMinBufferedDurationUs); + // delay the next download slightly; hopefully this gives other concurrent fetchers // a better chance to run. // onDownloadNext(); @@ -792,8 +806,12 @@ void PlaylistFetcher::onMonitorQueue() { if (delayUs > targetDurationUs / 2) { delayUs = targetDurationUs / 2; } - ALOGV("pausing for %" PRId64 ", buffered=%" PRId64 " > %" PRId64 "", - delayUs, bufferedDurationUs, kMinBufferedDurationUs); + + FLOGV("pausing for %lld, buffered=%lld > %lld", + (long long)delayUs, + (long long)bufferedDurationUs, + (long long)kMinBufferedDurationUs); + postMonitorQueue(delayUs); } } @@ -891,6 +909,12 @@ bool PlaylistFetcher::shouldPauseDownload() { } } lastEnqueueUs -= mSegmentFirstPTS; + + FLOGV("%spausing now, thresholdUs %lld, remaining %lld", + targetDurationUs - lastEnqueueUs > thresholdUs ? "" : "not ", + (long long)thresholdUs, + (long long)(targetDurationUs - lastEnqueueUs)); + if (targetDurationUs - lastEnqueueUs > thresholdUs) { return true; } @@ -940,8 +964,8 @@ bool PlaylistFetcher::initDownloadState( mStartTimeUs -= getSegmentStartTimeUs(mSeqNumber); } mStartTimeUsRelative = true; - ALOGV("Initial sequence number for time %" PRId64 " is %d from (%d .. %d)", - mStartTimeUs, mSeqNumber, firstSeqNumberInPlaylist, + FLOGV("Initial sequence number for time %lld is %d from (%d .. %d)", + (long long)mStartTimeUs, mSeqNumber, firstSeqNumberInPlaylist, lastSeqNumberInPlaylist); } else { // When adapting or track switching, mSegmentStartTimeUs (relative @@ -966,7 +990,7 @@ bool PlaylistFetcher::initDownloadState( if (mSeqNumber > lastSeqNumberInPlaylist) { mSeqNumber = lastSeqNumberInPlaylist; } - ALOGV("Initial sequence number for live event %d from (%d .. %d)", + FLOGV("Initial sequence number is %d from (%d .. %d)", mSeqNumber, firstSeqNumberInPlaylist, lastSeqNumberInPlaylist); } @@ -995,10 +1019,10 @@ bool PlaylistFetcher::initDownloadState( if (delayUs > kMaxMonitorDelayUs) { delayUs = kMaxMonitorDelayUs; } - ALOGV("sequence number high: %d from (%d .. %d), " - "monitor in %" PRId64 " (retry=%d)", + FLOGV("sequence number high: %d from (%d .. %d), " + "monitor in %lld (retry=%d)", mSeqNumber, firstSeqNumberInPlaylist, - lastSeqNumberInPlaylist, delayUs, mNumRetries); + lastSeqNumberInPlaylist, (long long)delayUs, mNumRetries); postMonitorQueue(delayUs); return false; } @@ -1067,9 +1091,9 @@ bool PlaylistFetcher::initDownloadState( // Seek jumped to a new discontinuity sequence. We need to signal // a format change to decoder. Decoder needs to shutdown and be // created again if seamless format change is unsupported. - ALOGV("saw discontinuity: mStartup %d, mLastDiscontinuitySeq %d, " + FLOGV("saw discontinuity: mStartup %d, mLastDiscontinuitySeq %d, " "mDiscontinuitySeq %d, mStartTimeUs %lld", - mStartup, mLastDiscontinuitySeq, mDiscontinuitySeq, (long long)mStartTimeUs); + mStartup, mLastDiscontinuitySeq, mDiscontinuitySeq, (long long)mStartTimeUs); discontinuity = true; } mLastDiscontinuitySeq = -1; @@ -1134,7 +1158,7 @@ bool PlaylistFetcher::initDownloadState( } } - ALOGV("fetching segment %d from (%d .. %d)", + FLOGV("fetching segment %d from (%d .. %d)", mSeqNumber, firstSeqNumberInPlaylist, lastSeqNumberInPlaylist); return true; } @@ -1157,7 +1181,7 @@ void PlaylistFetcher::onDownloadNext() { firstSeqNumberInPlaylist, lastSeqNumberInPlaylist); connectHTTP = false; - ALOGV("resuming: '%s'", uri.c_str()); + FLOGV("resuming: '%s'", uri.c_str()); } else { if (!initDownloadState( uri, @@ -1166,7 +1190,7 @@ void PlaylistFetcher::onDownloadNext() { lastSeqNumberInPlaylist)) { return; } - ALOGV("fetching: '%s'", uri.c_str()); + FLOGV("fetching: '%s'", uri.c_str()); } int64_t range_offset, range_length; @@ -1196,6 +1220,11 @@ void PlaylistFetcher::onDownloadNext() { | LiveSession::STREAMTYPE_VIDEO))) { int64_t delayUs = ALooper::GetNowUs() - startUs; mSession->addBandwidthMeasurement(bytesRead, delayUs); + + if (delayUs > 2000000ll) { + FLOGV("bytesRead %zd took %.2f seconds - abnormal bandwidth dip", + bytesRead, (double)delayUs / 1.0e6); + } } connectHTTP = false; @@ -1584,6 +1613,16 @@ status_t PlaylistFetcher::extractAndQueueAccessUnitsFromTs(const sp<ABuffer> &bu // (newSeqNumber), start at least 1 segment prior. int32_t newSeqNumber = getSeqNumberWithAnchorTime( timeUs, targetDiffUs); + + FLOGV("guessed wrong seq number: timeUs=%lld, mStartTimeUs=%lld, " + "targetDurationUs=%lld, mSeqNumber=%d, newSeq=%d, firstSeq=%d", + (long long)timeUs, + (long long)mStartTimeUs, + (long long)targetDurationUs, + mSeqNumber, + newSeqNumber, + firstSeqNumberInPlaylist); + if (newSeqNumber >= mSeqNumber) { --mSeqNumber; } else { @@ -1604,8 +1643,13 @@ status_t PlaylistFetcher::extractAndQueueAccessUnitsFromTs(const sp<ABuffer> &bu } bool startTimeReached = true; if (mStartTimeUsRelative) { + FLOGV("startTimeUsRelative, timeUs (%lld) - %lld = %lld", + (long long)timeUs, + (long long)mFirstTimeUs, + (long long)(timeUs - mFirstTimeUs)); timeUs -= mFirstTimeUs; if (timeUs < 0) { + FLOGV("clamp negative timeUs to 0"); timeUs = 0; } startTimeReached = (timeUs >= mStartTimeUs); @@ -1614,13 +1658,17 @@ status_t PlaylistFetcher::extractAndQueueAccessUnitsFromTs(const sp<ABuffer> &bu if (!startTimeReached || (isAvc && !mIDRFound)) { // buffer up to the closest preceding IDR frame in the next segement, // or the closest succeeding IDR frame after the exact position + FSLOGV(stream, "timeUs=%lld, mStartTimeUs=%lld, mIDRFound=%d", + (long long)timeUs, (long long)mStartTimeUs, mIDRFound); if (isAvc) { if (IsIDR(accessUnit)) { mVideoBuffer->clear(); + FSLOGV(stream, "found IDR, clear mVideoBuffer"); mIDRFound = true; } if (mIDRFound && mStartTimeUsRelative && !startTimeReached) { mVideoBuffer->queueAccessUnit(accessUnit); + FSLOGV(stream, "saving AVC video AccessUnit"); } } if (!startTimeReached || (isAvc && !mIDRFound)) { @@ -1635,15 +1683,17 @@ status_t PlaylistFetcher::extractAndQueueAccessUnitsFromTs(const sp<ABuffer> &bu if (!(streamMask & mPacketSources.keyAt(i))) { streamMask |= mPacketSources.keyAt(i); mStartTimeUsNotify->setInt32("streamMask", streamMask); + FSLOGV(stream, "found start point, timeUs=%lld, streamMask becomes %x", + (long long)timeUs, streamMask); if (streamMask == mStreamTypeMask) { + FLOGV("found start point for all streams"); mStartup = false; } } } if (mStopParams != NULL) { - // Queue discontinuity in original stream. int32_t discontinuitySeq; int64_t stopTimeUs; if (!mStopParams->findInt32("discontinuitySeq", &discontinuitySeq) @@ -1651,13 +1701,13 @@ status_t PlaylistFetcher::extractAndQueueAccessUnitsFromTs(const sp<ABuffer> &bu || !mStopParams->findInt64(key, &stopTimeUs) || (discontinuitySeq == mDiscontinuitySeq && timeUs >= stopTimeUs)) { + FSLOGV(stream, "reached stop point, timeUs=%lld", (long long)timeUs); mStreamTypeMask &= ~stream; mPacketSources.removeItemsAt(i); break; } } - // Note that we do NOT dequeue any discontinuities except for format change. if (stream == LiveSession::STREAMTYPE_VIDEO) { const bool discard = true; status_t status; @@ -1666,11 +1716,16 @@ status_t PlaylistFetcher::extractAndQueueAccessUnitsFromTs(const sp<ABuffer> &bu mVideoBuffer->dequeueAccessUnit(&videoBuffer); setAccessUnitProperties(videoBuffer, source, discard); packetSource->queueAccessUnit(videoBuffer); + int64_t bufferTimeUs; + CHECK(videoBuffer->meta()->findInt64("timeUs", &bufferTimeUs)); + FSLOGV(stream, "queueAccessUnit (saved), timeUs=%lld", + (long long)bufferTimeUs); } } setAccessUnitProperties(accessUnit, source); packetSource->queueAccessUnit(accessUnit); + FSLOGV(stream, "queueAccessUnit, timeUs=%lld", (long long)timeUs); } if (err != OK) { @@ -1688,7 +1743,7 @@ status_t PlaylistFetcher::extractAndQueueAccessUnitsFromTs(const sp<ABuffer> &bu if (!mStreamTypeMask) { // Signal gap is filled between original and new stream. - ALOGV("ERROR OUT OF RANGE"); + FLOGV("reached stop point for all streams"); return ERROR_OUT_OF_RANGE; } @@ -1918,7 +1973,6 @@ status_t PlaylistFetcher::extractAndQueueAccessUnits( } if (mStopParams != NULL) { - // Queue discontinuity in original stream. int32_t discontinuitySeq; int64_t stopTimeUs; if (!mStopParams->findInt32("discontinuitySeq", &discontinuitySeq) diff --git a/media/libstagefright/httplive/PlaylistFetcher.h b/media/libstagefright/httplive/PlaylistFetcher.h index dab56df..f64d160 100644 --- a/media/libstagefright/httplive/PlaylistFetcher.h +++ b/media/libstagefright/httplive/PlaylistFetcher.h @@ -55,8 +55,11 @@ struct PlaylistFetcher : public AHandler { const sp<AMessage> ¬ify, const sp<LiveSession> &session, const char *uri, + int32_t id, int32_t subtitleGeneration); + int32_t getFetcherID() const; + sp<DataSource> getDataSource(); void startAsync( @@ -113,6 +116,8 @@ private: sp<LiveSession> mSession; AString mURI; + int32_t mFetcherID; + uint32_t mStreamTypeMask; int64_t mStartTimeUs; diff --git a/media/libstagefright/mpeg2ts/AnotherPacketSource.cpp b/media/libstagefright/mpeg2ts/AnotherPacketSource.cpp index c5bb41b..0676a33 100644 --- a/media/libstagefright/mpeg2ts/AnotherPacketSource.cpp +++ b/media/libstagefright/mpeg2ts/AnotherPacketSource.cpp @@ -514,7 +514,7 @@ void AnotherPacketSource::trimBuffersAfterMeta( } HLSTime stopTime(meta); - ALOGV("trimBuffersAfterMeta: discontinuitySeq %zu, timeUs %lld", + ALOGV("trimBuffersAfterMeta: discontinuitySeq %d, timeUs %lld", stopTime.mSeq, (long long)stopTime.mTimeUs); List<sp<ABuffer> >::iterator it; @@ -554,7 +554,7 @@ void AnotherPacketSource::trimBuffersAfterMeta( sp<AMessage> AnotherPacketSource::trimBuffersBeforeMeta( const sp<AMessage> &meta) { HLSTime startTime(meta); - ALOGV("trimBuffersBeforeMeta: discontinuitySeq %zu, timeUs %lld", + ALOGV("trimBuffersBeforeMeta: discontinuitySeq %d, timeUs %lld", startTime.mSeq, (long long)startTime.mTimeUs); sp<AMessage> firstMeta; |