HLS: traces in LiveSession and PlaylistFetcher for easier debugging

bug: 19567254
Change-Id: I4305d37cb74279ccd435f99483231cd1dcf42fc9

4 files changed, 170 insertions, 56 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> &notify, 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> &notify,
         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> &params) {
+    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> &notify,
             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;