Merge "frameworks/base: Add rendering statistics to Stagefright" into froyo

5 files changed, 208 insertions, 2 deletions

diff --git a/media/libstagefright/AwesomePlayer.cpp b/media/libstagefright/AwesomePlayer.cpp
index 274dad9..46e47dc 100644
--- a/media/libstagefright/AwesomePlayer.cpp
+++ b/media/libstagefright/AwesomePlayer.cpp
@@ -17,6 +17,7 @@
 //#define LOG_NDEBUG 0
 #define LOG_TAG "AwesomePlayer"
 #include <utils/Log.h>
+#include <cutils/properties.h>
 
 #include <dlfcn.h>
 
@@ -187,6 +188,14 @@ AwesomePlayer::AwesomePlayer()
       mExtractorFlags(0),
       mLastVideoBuffer(NULL),
       mVideoBuffer(NULL),
+      mFramesDropped(0),
+      mConsecutiveFramesDropped(0),
+      mCatchupTimeStart(0),
+      mNumTimesSyncLoss(0),
+      mMaxEarlyDelta(0),
+      mMaxLateDelta(0),
+      mMaxTimeSyncLoss(0),
+      mTotalFrames(0),
       mSuspensionState(NULL) {
     CHECK_EQ(mClient.connect(), OK);
 
@@ -204,6 +213,12 @@ AwesomePlayer::AwesomePlayer()
 
     mAudioStatusEventPending = false;
 
+    //for statistics profiling
+    char value[PROPERTY_VALUE_MAX];
+    mStatistics = false;
+    property_get("persist.debug.sf.statistics", value, "0");
+    if(atoi(value)) mStatistics = true;
+
     reset();
 }
 
@@ -551,6 +566,11 @@ status_t AwesomePlayer::play_l() {
         mTimeSource = new SystemTimeSource;
     }
 
+    if (mStatistics) {
+        mFirstFrameLatencyStartUs = getTimeOfDayUs();
+        mVeryFirstFrame = true;
+    }
+
     if (mVideoSource != NULL) {
         // Kick off video playback
         postVideoEvent_l();
@@ -631,6 +651,7 @@ status_t AwesomePlayer::pause_l() {
 
     mFlags &= ~PLAYING;
 
+    if(mStatistics && !(mFlags & AT_EOS)) logPause();
     return OK;
 }
 
@@ -703,6 +724,7 @@ status_t AwesomePlayer::seekTo(int64_t timeUs) {
 
 status_t AwesomePlayer::seekTo_l(int64_t timeUs) {
     mSeeking = true;
+    if (mStatistics) mFirstFrameLatencyStartUs = getTimeOfDayUs();
     mSeekNotificationSent = false;
     mSeekTimeUs = timeUs;
     mFlags &= ~AT_EOS;
@@ -919,12 +941,14 @@ void AwesomePlayer::onVideoEvent() {
         mFlags |= FIRST_FRAME;
         mSeeking = false;
         mSeekNotificationSent = false;
+        if (mStatistics) logSeek();
     }
 
     if (mFlags & FIRST_FRAME) {
         mFlags &= ~FIRST_FRAME;
 
         mTimeSourceDeltaUs = mTimeSource->getRealTimeUs() - timeUs;
+        if (mStatistics && mVeryFirstFrame) logFirstFrame();
     }
 
     int64_t realTimeUs, mediaTimeUs;
@@ -944,13 +968,24 @@ void AwesomePlayer::onVideoEvent() {
         mVideoBuffer->release();
         mVideoBuffer = NULL;
 
+        if (mStatistics) {
+            mFramesDropped++;
+            mConsecutiveFramesDropped++;
+            if (mConsecutiveFramesDropped == 1) {
+                mCatchupTimeStart = mTimeSource->getRealTimeUs();
+            }
+            if (!(mFlags & AT_EOS)) logLate(timeUs,nowUs,latenessUs);
+        }
         postVideoEvent_l();
         return;
     }
 
     if (latenessUs < -10000) {
         // We're more than 10ms early.
-
+        if (mStatistics) {
+            logOnTime(timeUs,nowUs,latenessUs);
+            mConsecutiveFramesDropped = 0;
+        }
         postVideoEvent_l(10000);
         return;
     }
@@ -963,6 +998,11 @@ void AwesomePlayer::onVideoEvent() {
 
     if (mVideoRenderer != NULL) {
         mVideoRenderer->render(mVideoBuffer);
+        if (mStatistics) {
+            mTotalFrames++;
+            logOnTime(timeUs,nowUs,latenessUs);
+            mConsecutiveFramesDropped = 0;
+        }
     }
 
     if (mLastVideoBuffer) {
@@ -1261,6 +1301,10 @@ void AwesomePlayer::onPrepareAsyncEvent() {
 status_t AwesomePlayer::suspend() {
     LOGV("suspend");
     Mutex::Autolock autoLock(mLock);
+    if (mStatistics) {
+        logStatistics();
+        logSyncLoss();
+    }
 
     if (mSuspensionState != NULL) {
         if (mLastVideoBuffer == NULL) {
@@ -1390,5 +1434,89 @@ uint32_t AwesomePlayer::flags() const {
     return mExtractorFlags;
 }
 
+
+//Statistics profiling
+void AwesomePlayer::logStatistics() {
+    String8 mimeType;
+    float confidence;
+    if (mFileSource!=NULL) mFileSource->sniff(&mimeType, &confidence);
+    LOGW("=====================================================");
+    LOGW("MimeType: %s",mimeType.string());
+    LOGW("Clip duration: %lld ms",mDurationUs/1000);
+    if (mVideoTrack!=NULL) mVideoTrack->logTrackStatistics();
+    LOGW("Number of frames dropped: %lu",mFramesDropped);
+    LOGW("Number of frames rendered: %lu",mTotalFrames);
+    LOGW("=====================================================");
+}
+
+inline void AwesomePlayer::logFirstFrame() {
+    LOGW("=====================================================");
+    LOGW("First frame latency: %lld ms",(getTimeOfDayUs()-mFirstFrameLatencyStartUs)/1000);
+    LOGW("=====================================================");
+    mVeryFirstFrame = false;
+}
+
+inline void AwesomePlayer::logSeek() {
+    LOGW("=====================================================");
+    LOGW("Seek position: %lld ms",mSeekTimeUs/1000);
+    LOGW("Seek latency: %lld ms",(getTimeOfDayUs()-mFirstFrameLatencyStartUs)/1000);
+    LOGW("=====================================================");
+}
+
+inline void AwesomePlayer::logPause() {
+    LOGW("=====================================================");
+    LOGW("Pause position: %lld ms",mVideoTimeUs/1000);
+    LOGW("=====================================================");
+}
+
+inline void AwesomePlayer::logCatchUp(int64_t ts, int64_t clock, int64_t delta)
+{
+    if (mConsecutiveFramesDropped > 0) {
+        LOGW("Frames dropped before catching up: %lu, Timestamp: %lld, Clock: %lld, Delta: %lld", mConsecutiveFramesDropped, ts/1000, clock/1000, delta/1000);
+        mNumTimesSyncLoss++;
+        if (mMaxTimeSyncLoss < (clock - mCatchupTimeStart) && clock > 0 && ts > 0) {
+            mMaxTimeSyncLoss = clock - mCatchupTimeStart;
+        }
+    }
+}
+
+inline void AwesomePlayer::logLate(int64_t ts, int64_t clock, int64_t delta)
+{
+    LOGW("Video behind. Timestamp: %lld, Clock: %lld, Delta: %lld",ts/1000,clock/1000,delta/1000);
+    if (mMaxLateDelta < delta && clock > 0 && ts > 0) {
+        mMaxLateDelta = delta;
+    }
+}
+
+inline void AwesomePlayer::logOnTime(int64_t ts, int64_t clock, int64_t delta)
+{
+    logCatchUp(ts, clock, delta);
+    if (delta <= 0) {
+        LOGW("Video ahead. Timestamp: %lld, Clock: %lld, Delta: %lld",ts/1000,clock/1000,-delta/1000);
+        if ((-delta) > (-mMaxEarlyDelta) && clock > 0 && ts > 0) {
+            mMaxEarlyDelta = delta;
+        }
+    }
+    else logLate(ts, clock, delta);
+}
+
+void AwesomePlayer::logSyncLoss()
+{
+    LOGW("=====================================================");
+    LOGW("Number of times AV Sync Losses = %lu", mNumTimesSyncLoss);
+    LOGW("Max Video Ahead time delta = %lu", -mMaxEarlyDelta/1000);
+    LOGW("Max Video Behind time delta = %lu", mMaxLateDelta/1000);
+    LOGW("Max Time sync loss = %lu",mMaxTimeSyncLoss/1000);
+    LOGW("=====================================================");
+
+}
+
+inline int64_t AwesomePlayer::getTimeOfDayUs() {
+    struct timeval tv;
+    gettimeofday(&tv, NULL);
+
+    return (int64_t)tv.tv_sec * 1000000 + tv.tv_usec;
+}
+
 }  // namespace android
 
diff --git a/media/libstagefright/MPEG4Extractor.cpp b/media/libstagefright/MPEG4Extractor.cpp
index a41b2f4..8ddf268 100644
--- a/media/libstagefright/MPEG4Extractor.cpp
+++ b/media/libstagefright/MPEG4Extractor.cpp
@@ -38,6 +38,8 @@
 #include <media/stagefright/Utils.h>
 #include <utils/String8.h>
 
+#include <cutils/properties.h>
+
 namespace android {
 
 class MPEG4Source : public MediaSource {
@@ -56,6 +58,8 @@ public:
     virtual status_t read(
             MediaBuffer **buffer, const ReadOptions *options = NULL);
 
+    virtual void logTrackStatistics();
+
 protected:
     virtual ~MPEG4Source();
 
@@ -81,6 +85,11 @@ private:
 
     uint8_t *mSrcBuffer;
 
+    //For statistics profiling
+    uint32_t mNumSamplesReadError;
+    bool mStatistics;
+    void logExpectedFrames();
+
     size_t parseNALSize(const uint8_t *data) const;
 
     MPEG4Source(const MPEG4Source &);
@@ -1349,11 +1358,19 @@ MPEG4Source::MPEG4Source(
       mGroup(NULL),
       mBuffer(NULL),
       mWantsNALFragments(false),
-      mSrcBuffer(NULL) {
+      mSrcBuffer(NULL),
+      mNumSamplesReadError(0) {
     const char *mime;
     bool success = mFormat->findCString(kKeyMIMEType, &mime);
     CHECK(success);
 
+
+    //for statistics profiling
+    char value[PROPERTY_VALUE_MAX];
+    mStatistics = false;
+    property_get("persist.debug.sf.statistics", value, "0");
+    if(atoi(value)) mStatistics = true;
+
     mIsAVC = !strcasecmp(mime, MEDIA_MIMETYPE_VIDEO_AVC);
 
     if (mIsAVC) {
@@ -1370,6 +1387,7 @@ MPEG4Source::MPEG4Source(
         // The number of bytes used to encode the length of a NAL unit.
         mNALLengthSize = 1 + (ptr[4] & 3);
     }
+    if (mStatistics) logExpectedFrames();
 }
 
 MPEG4Source::~MPEG4Source() {
@@ -1500,6 +1518,7 @@ status_t MPEG4Source::read(
                     mCurrentSampleIndex, &offset, &size, &dts);
 
         if (err != OK) {
+            if (mStatistics) mNumSamplesReadError++;
             return err;
         }
 
@@ -1507,6 +1526,7 @@ status_t MPEG4Source::read(
 
         if (err != OK) {
             CHECK_EQ(mBuffer, NULL);
+            if (mStatistics) mNumSamplesReadError++;
             return err;
         }
     }
@@ -1520,6 +1540,7 @@ status_t MPEG4Source::read(
                 mBuffer->release();
                 mBuffer = NULL;
 
+                if (mStatistics) mNumSamplesReadError++;
                 return ERROR_IO;
             }
 
@@ -1553,6 +1574,7 @@ status_t MPEG4Source::read(
             mBuffer->release();
             mBuffer = NULL;
 
+            if (mStatistics) mNumSamplesReadError++;
             return ERROR_MALFORMED;
         }
 
@@ -1584,6 +1606,7 @@ status_t MPEG4Source::read(
             mBuffer->release();
             mBuffer = NULL;
 
+            if (mStatistics) mNumSamplesReadError++;
             return ERROR_IO;
         }
 
@@ -1600,6 +1623,7 @@ status_t MPEG4Source::read(
                 mBuffer->release();
                 mBuffer = NULL;
 
+                if (mStatistics) mNumSamplesReadError++;
                 return ERROR_MALFORMED;
             }
 
@@ -1633,6 +1657,29 @@ status_t MPEG4Source::read(
     }
 }
 
+void MPEG4Source::logTrackStatistics()
+{
+    LOGW("Total number of samples in track: %lu",mSampleTable->countSamples());
+    LOGW("Number of key samples: %lu",mSampleTable->getNumSyncSamples());
+    LOGW("Number of corrupt samples: %lu",mNumSamplesReadError ?
+           mNumSamplesReadError-1 : mNumSamplesReadError); //last sample reads error for EOS
+}
+
+
+void MPEG4Source::logExpectedFrames()
+{
+    const char *mime;
+    mFormat->findCString(kKeyMIMEType, &mime);
+    int64_t durationUs;
+    getFormat()->findInt64(kKeyDuration, &durationUs);
+    LOGW("=====================================================");
+    LOGW("Mime type: %s",mime);
+    LOGW("Track duration: %lld",durationUs/1000);
+    LOGW("Total number of samples in track: %lu",mSampleTable->countSamples());
+    LOGW("Expected frames per second: %.2f",((float)mSampleTable->countSamples()*1000)/((float)durationUs/1000));
+    LOGW("=====================================================");
+}
+
 bool SniffMPEG4(
         const sp<DataSource> &source, String8 *mimeType, float *confidence) {
     uint8_t header[8];
diff --git a/media/libstagefright/SampleTable.cpp b/media/libstagefright/SampleTable.cpp
index 89a522e..aa7d5f7 100644
--- a/media/libstagefright/SampleTable.cpp
+++ b/media/libstagefright/SampleTable.cpp
@@ -471,5 +471,10 @@ status_t SampleTable::getMetaDataForSample(
     return OK;
 }
 
+uint32_t SampleTable::getNumSyncSamples()
+{
+    return mNumSyncSamples;
+}
+
 }  // namespace android
 
diff --git a/media/libstagefright/include/AwesomePlayer.h b/media/libstagefright/include/AwesomePlayer.h
index 9455743..c0be52b 100644
--- a/media/libstagefright/include/AwesomePlayer.h
+++ b/media/libstagefright/include/AwesomePlayer.h
@@ -169,6 +169,19 @@ private:
     sp<Prefetcher> mPrefetcher;
     sp<HTTPDataSource> mConnectingDataSource;
 
+    //Statistics profiling
+    uint32_t mFramesDropped;
+    uint32_t mConsecutiveFramesDropped;
+    uint32_t mCatchupTimeStart;
+    uint32_t mNumTimesSyncLoss;
+    uint32_t mMaxEarlyDelta;
+    uint32_t mMaxLateDelta;
+    uint32_t mMaxTimeSyncLoss;
+    uint32_t mTotalFrames;
+    int64_t mFirstFrameLatencyStartUs; //first frame latency start
+    bool mVeryFirstFrame;
+    bool mStatistics;
+
     struct SuspensionState {
         String8 mUri;
         KeyedVector<String8, String8> mUriHeaders;
@@ -229,6 +242,17 @@ private:
 
     static bool ContinuePreparation(void *cookie);
 
+    //Statistics Profiling
+    void logStatistics();
+    void logFirstFrame();
+    void logSeek();
+    void logPause();
+    void logCatchUp(int64_t ts, int64_t clock, int64_t delta);
+    void logLate(int64_t ts, int64_t clock, int64_t delta);
+    void logOnTime(int64_t ts, int64_t clock, int64_t delta);
+    void logSyncLoss();
+    int64_t getTimeOfDayUs();
+
     AwesomePlayer(const AwesomePlayer &);
     AwesomePlayer &operator=(const AwesomePlayer &);
 };
diff --git a/media/libstagefright/include/SampleTable.h b/media/libstagefright/include/SampleTable.h
index 533ce84..32ed5b1 100644
--- a/media/libstagefright/include/SampleTable.h
+++ b/media/libstagefright/include/SampleTable.h
@@ -70,6 +70,8 @@ public:
 
     status_t findThumbnailSample(uint32_t *sample_index);
 
+    uint32_t getNumSyncSamples();
+
 protected:
     ~SampleTable();