Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit ae1a9554 authored by Eric Ho's avatar Eric Ho Committed by Ricardo Cerqueira
Browse files

frameworks/base: Add rendering statistics to Stagefright (Adapted) 

- this is an adaptation of change 514 (I88dd988c9) from HC to ICS
- functionality is the same as the forementioned patch
- added all statistics properties for AwesomePlayer into
  Google's Stats struct
- acquire locking before modifying/accessing mStats values
- moved mStatistics check in AwesomePlayer to inside the log functions

Change-Id: I553823b22403a0e5e9fc3998a27a54fec9e1b5c4
parent b210c2aa

media/libstagefright/AwesomePlayer.cpp

+189 −9
Original line number Diff line number Diff line
@@ -211,6 +211,28 @@ AwesomePlayer::AwesomePlayer() 


    mAudioStatusEventPending = false;



    // for qualcomm statistics profiling

    char value[PROPERTY_VALUE_MAX];

    mStatistics = false;

    property_get("persist.debug.sf.statistics", value, "0");

    if(atoi(value)) mStatistics = true;

    {

        Mutex::Autolock autoLock(mStatsLock);

        mStats.mNumVideoFramesDecoded = 0;

        mStats.mNumVideoFramesDropped = 0;



        mStats.mConsecutiveFramesDropped = 0;

        mStats.mCatchupTimeStart = 0;

        mStats.mNumTimesSyncLoss = 0;

        mStats.mMaxEarlyDelta = 0;

        mStats.mMaxLateDelta = 0;

        mStats.mMaxTimeSyncLoss = 0;

        mStats.mTotalFrames = 0;

        mStats.mLastFrame = 0;

        mStats.mLastFrameUs = 0;

        mStats.mStatisticsFrames = 0;

        mStats.mFPSSumUs = 0;

    }

    reset();

}
@@ -219,6 +241,13 @@ AwesomePlayer::~AwesomePlayer() { 
        mQueue.stop();

    }



    if (mStatistics) {

        Mutex::Autolock autoLock(mStatsLock);

        LOGW("=========================================================");

        LOGW("Average Frames Per Second: %.4f", mStats.mFPSSumUs/((double)mStats.mStatisticsFrames));

        LOGW("========================================================");

    }



    reset();



    mClient.disconnect();
@@ -499,6 +528,11 @@ void AwesomePlayer::reset_l() { 
    }



    cancelPlayerEvents();

    if(mStatistics && mVideoSource != NULL){

        Mutex::Autolock autolock(mStatsLock);

        logStatistics();

        logSyncLoss();

    }



    mWVMExtractor.clear();

    mCachedSource.clear();
@@ -520,8 +554,8 @@ void AwesomePlayer::reset_l() { 
    mAudioSource.clear();



    mTimeSource = NULL;



    delete mAudioPlayer;



    mAudioPlayer = NULL;



    if (mTextPlayer != NULL) {
@@ -560,8 +594,6 @@ void AwesomePlayer::reset_l() { 
        mStats.mBitrate = -1;

        mStats.mAudioTrackIndex = -1;

        mStats.mVideoTrackIndex = -1;

        mStats.mNumVideoFramesDecoded = 0;

        mStats.mNumVideoFramesDropped = 0;

        mStats.mVideoWidth = -1;

        mStats.mVideoHeight = -1;

        mStats.mFlags = 0;
@@ -818,6 +850,13 @@ void AwesomePlayer::onStreamDone() { 


        if (mVideoSource != NULL) {

            postVideoEvent_l();



            if(mStatistics)

            {

                Mutex::Autolock autolock(mStatsLock);

                logStatistics();

                logSyncLoss();

            }

        }

    } else {

        LOGV("MEDIA_PLAYBACK_COMPLETE");
@@ -907,6 +946,12 @@ status_t AwesomePlayer::play_l() { 
        mTimeSource = &mSystemTimeSource;

    }



    if(mStatistics) {

        Mutex::Autolock autoLock(mStatsLock);

        mStats.mFirstFrameLatencyStartUs = getTimeOfDayUs();

        mStats.mVeryFirstFrame = true;

    }



    if (mVideoSource != NULL) {

        // Kick off video playback

        postVideoEvent_l();
@@ -1123,6 +1168,11 @@ status_t AwesomePlayer::pause_l(bool at_eos) { 
                Playback::PAUSE, 0);

    }



    if(mStatistics && !(mFlags & AT_EOS)){

        Mutex::Autolock autoLock(mStatsLock);

        logPause();

    }



    uint32_t params = IMediaPlayerService::kBatteryDataTrackDecoder;

    if ((mAudioSource != NULL) && (mAudioSource != mAudioTrack)) {

        params |= IMediaPlayerService::kBatteryDataTrackAudio;
@@ -1306,6 +1356,12 @@ status_t AwesomePlayer::seekTo_l(int64_t timeUs) { 
    }



    mSeeking = SEEK;



    if(mStatistics)

    {

        Mutex::Autolock autoLock(mStatsLock);

        mStats.mFirstFrameLatencyStartUs = getTimeOfDayUs();

    }

    mSeekNotificationSent = false;

    mSeekTimeUs = timeUs;

    modifyFlags((AT_EOS | AUDIO_AT_EOS | VIDEO_AT_EOS), CLEAR);
@@ -1566,6 +1622,11 @@ void AwesomePlayer::finishSeekIfNecessary(int64_t videoTimeUs) { 
        mDrmManagerClient->setPlaybackStatus(mDecryptHandle,

                Playback::START, videoTimeUs / 1000);

    }



    if (mStatistics){

        Mutex::Autolock autoLock(mStatsLock);

        logSeek();

    }

}



void AwesomePlayer::onVideoEvent() {
@@ -1709,18 +1770,25 @@ void AwesomePlayer::onVideoEvent() { 
        modifyFlags(FIRST_FRAME, CLEAR);

        mSinceLastDropped = 0;

        mTimeSourceDeltaUs = ts->getRealTimeUs() - timeUs;



        if(mStatistics)

        {

            Mutex::Autolock autoLock(mStatsLock);

            if(mStats.mVeryFirstFrame)

                logFirstFrame();

        }

    }



    int64_t realTimeUs, mediaTimeUs;

    int64_t realTimeUs, mediaTimeUs, nowUs = 0, latenessUs = 0;

    if (!(mFlags & AUDIO_AT_EOS) && mAudioPlayer != NULL

        && mAudioPlayer->getMediaTimeMapping(&realTimeUs, &mediaTimeUs)) {

        mTimeSourceDeltaUs = realTimeUs - mediaTimeUs;

    }



    if (wasSeeking == SEEK_VIDEO_ONLY) {

        int64_t nowUs = ts->getRealTimeUs() - mTimeSourceDeltaUs;

        nowUs = ts->getRealTimeUs() - mTimeSourceDeltaUs;



        int64_t latenessUs = nowUs - timeUs;

        latenessUs = nowUs - timeUs;



        if (latenessUs > 0) {

            LOGI("after SEEK_VIDEO_ONLY we're late by %.2f secs", latenessUs / 1E6);
@@ -1730,9 +1798,9 @@ void AwesomePlayer::onVideoEvent() { 
    if (wasSeeking == NO_SEEK) {

        // Let's display the first frame after seeking right away.



        int64_t nowUs = ts->getRealTimeUs() - mTimeSourceDeltaUs;

        nowUs = ts->getRealTimeUs() - mTimeSourceDeltaUs;



        int64_t latenessUs = nowUs - timeUs;

        latenessUs = nowUs - timeUs;



        if (latenessUs > 500000ll

                && mAudioPlayer != NULL
@@ -1770,6 +1838,14 @@ void AwesomePlayer::onVideoEvent() { 
                {

                    Mutex::Autolock autoLock(mStatsLock);

                    ++mStats.mNumVideoFramesDropped;

                    if(mStatistics) {

                        mStats.mConsecutiveFramesDropped++;

                        if (mStats.mConsecutiveFramesDropped == 1){

                            mStats.mCatchupTimeStart = mTimeSource->getRealTimeUs();

                        }



                        if(!(mFlags & AT_EOS)) logLate(timeUs,nowUs,latenessUs);

                    }

                }



                postVideoEvent_l();
@@ -1779,7 +1855,11 @@ void AwesomePlayer::onVideoEvent() { 


        if (latenessUs < -10000) {

            // We're more than 10ms early.



            logOnTime(timeUs,nowUs,latenessUs);

            {

                Mutex::Autolock autoLock(mStatsLock);

                mStats.mConsecutiveFramesDropped = 0;

            }

            postVideoEvent_l(10000);

            return;

        }
@@ -1795,6 +1875,25 @@ void AwesomePlayer::onVideoEvent() { 
    if (mVideoRenderer != NULL) {

        mSinceLastDropped++;

        mVideoRenderer->render(mVideoBuffer);



        if(mStatistics) {

            Mutex::Autolock autoLock(mStatsLock);

            logOnTime(timeUs,nowUs,latenessUs);

            mStats.mTotalFrames++;

            mStats.mConsecutiveFramesDropped = 0;



            int64_t now = getTimeOfDayUs(),

            diff = now - mStats.mLastFrameUs;

            if (diff > 250000) {

                float fps =((mStats.mTotalFrames - mStats.mLastFrame) * 1E6)/diff;

                LOGW("Frames per second: %.4f", fps);



                mStats.mFPSSumUs += fps;

                mStats.mLastFrameUs = now;

                mStats.mLastFrame = mStats.mTotalFrames;

                ++mStats.mStatisticsFrames;

            }

        }

    }



    mVideoBuffer->release();
@@ -2365,4 +2464,85 @@ void AwesomePlayer::modifyFlags(unsigned value, FlagMode mode) { 
    }

}



//Statistics profiling

void AwesomePlayer::logStatistics() {

    const char *mime;

    mVideoTrack->getFormat()->findCString(kKeyMIMEType, &mime);

    LOGW("=====================================================");

    if (mFlags & LOOPING) {LOGW("Looping Update");}

    LOGW("Mime Type: %s",mime);

    LOGW("Number of frames dropped: %lld",mStats.mNumVideoFramesDropped);

    LOGW("Number of frames rendered: %u",mStats.mTotalFrames);

    LOGW("=====================================================");

}



inline void AwesomePlayer::logFirstFrame() {

    LOGW("=====================================================");

    LOGW("First frame latency: %lld ms",(getTimeOfDayUs()-mStats.mFirstFrameLatencyStartUs)/1000);

    LOGW("=====================================================");

    mStats.mVeryFirstFrame = false;

}



inline void AwesomePlayer::logSeek() {

    LOGW("=====================================================");

    LOGW("Seek position: %lld ms",mSeekTimeUs/1000);

    LOGW("Seek latency: %lld ms",(getTimeOfDayUs()-mStats.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 (mStats.mConsecutiveFramesDropped > 0) {

        mStats.mNumTimesSyncLoss++;

        if (mStats.mMaxTimeSyncLoss < (clock - mStats.mCatchupTimeStart) && clock > 0 && ts > 0) {

            mStats.mMaxTimeSyncLoss = clock - mStats.mCatchupTimeStart;

        }

    }

}



inline void AwesomePlayer::logLate(int64_t ts, int64_t clock, int64_t delta)

{

    if (mStats.mMaxLateDelta < delta && clock > 0 && ts > 0) {

        mStats.mMaxLateDelta = delta;

    }

}



inline void AwesomePlayer::logOnTime(int64_t ts, int64_t clock, int64_t delta)

{

    bool needLogLate = false;

    logCatchUp(ts, clock, delta);

    if (delta <= 0) {

        if ((-delta) > (-mStats.mMaxEarlyDelta) && clock > 0 && ts > 0) {

            mStats.mMaxEarlyDelta = delta;

        }

    }

    else {

        needLogLate = true;

    }



    if(needLogLate) logLate(ts, clock, delta);

}



void AwesomePlayer::logSyncLoss()

{

    LOGW("=====================================================");

    LOGW("Number of times AV Sync Losses = %u", mStats.mNumTimesSyncLoss);

    LOGW("Max Video Ahead time delta = %u", -mStats.mMaxEarlyDelta/1000);

    LOGW("Max Video Behind time delta = %u", mStats.mMaxLateDelta/1000);

    LOGW("Max Time sync loss = %u",mStats.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

media/libstagefright/MPEG4Extractor.cpp

+55 −1
Original line number Diff line number Diff line
@@ -39,6 +39,7 @@ 
#include <media/stagefright/MetaData.h>

#include <media/stagefright/Utils.h>

#include <utils/String8.h>

#include <cutils/properties.h>



namespace android {
@@ -83,6 +84,12 @@ private: 


    uint8_t *mSrcBuffer;



    //For statistics profiling

    uint32_t mNumSamplesReadError;

    bool mStatistics;

    void logExpectedFrames();

    void logTrackStatistics();



    size_t parseNALSize(const uint8_t *data) const;



    MPEG4Source(const MPEG4Source &);
@@ -1897,11 +1904,18 @@ 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) {
@@ -1918,6 +1932,8 @@ 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() {
@@ -1931,6 +1947,9 @@ status_t MPEG4Source::start(MetaData *params) { 


    CHECK(!mStarted);



    if (mStatistics)

        logTrackStatistics();



    int32_t val;

    if (params && params->findInt32(kKeyWantsNALFragments, &val)

        && val != 0) {
@@ -2104,6 +2123,7 @@ status_t MPEG4Source::read( 
                    mCurrentSampleIndex, &offset, &size, &cts, &isSyncSample);



        if (err != OK) {

            if (mStatistics) mNumSamplesReadError++;

            return err;

        }
@@ -2111,6 +2131,7 @@ status_t MPEG4Source::read( 


        if (err != OK) {

            CHECK(mBuffer == NULL);

            if (mStatistics) mNumSamplesReadError++;

            return err;

        }

    }
@@ -2124,6 +2145,7 @@ status_t MPEG4Source::read( 
                mBuffer->release();

                mBuffer = NULL;



                if (mStatistics) mNumSamplesReadError++;

                return ERROR_IO;

            }
@@ -2167,6 +2189,7 @@ status_t MPEG4Source::read( 
            mBuffer->release();

            mBuffer = NULL;



            if (mStatistics) mNumSamplesReadError++;

            return ERROR_MALFORMED;

        }
@@ -2204,6 +2227,7 @@ status_t MPEG4Source::read( 
            mBuffer->release();

            mBuffer = NULL;



            if (mStatistics) mNumSamplesReadError++;

            return ERROR_IO;

        }
@@ -2229,6 +2253,8 @@ status_t MPEG4Source::read( 
                    LOGE("Video is malformed");

                    mBuffer->release();

                    mBuffer = NULL;



                    if (mStatistics) mNumSamplesReadError++;

                    return ERROR_MALFORMED;

                }
@@ -2476,5 +2502,33 @@ bool SniffMPEG4( 
    return false;

}



void MPEG4Source::logTrackStatistics()

{

    const char *mime;

    mFormat->findCString(kKeyMIMEType, &mime);

    LOGW("=====================================================");

    LOGW("Mime Type: %s",mime);

    LOGW("Total number of samples in track: %u",mSampleTable->countSamples());

    LOGW("Number of key samples: %u",mSampleTable->getNumSyncSamples());

    LOGW("Number of corrupt samples: %u",mNumSamplesReadError ?

           mNumSamplesReadError-1 : mNumSamplesReadError); //last sample reads error for EOS

    LOGW("=====================================================");

}



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: %u",mSampleTable->countSamples());

    LOGW("Expected frames per second: %.2f",((float)mSampleTable->countSamples()*1000)/((float)durationUs/1000));

    LOGW("=====================================================");

}





}  // namespace android

media/libstagefright/SampleTable.cpp

+4 −0
Original line number Diff line number Diff line
@@ -814,5 +814,9 @@ uint32_t SampleTable::getCompositionTimeOffset(uint32_t sampleIndex) { 
    return mCompositionDeltaLookup->getCompositionTimeOffset(sampleIndex);

}



uint32_t SampleTable::getNumSyncSamples()

{

    return mNumSyncSamples;

}

}  // namespace android

media/libstagefright/include/AwesomePlayer.h

+26 −0
Original line number Diff line number Diff line
@@ -297,6 +297,17 @@ private: 
        ASSIGN

    };

    void modifyFlags(unsigned value, FlagMode mode);

    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();

    bool mVeryFirstFrame;

    bool mStatistics;



    struct TrackStat {

        String8 mMIME;
@@ -316,6 +327,21 @@ private: 
        int32_t mVideoHeight;

        uint32_t mFlags;

        Vector<TrackStat> mTracks;



        int64_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

        int64_t mLastFrame;

        int64_t mLastFrameUs;

        int64_t mFPSSumUs;

        int64_t mStatisticsFrames;

        bool mVeryFirstFrame;



    } mStats;



    AwesomePlayer(const AwesomePlayer &);

media/libstagefright/include/SampleTable.h

+1 −1
Original line number Diff line number Diff line
@@ -81,7 +81,7 @@ public: 
            uint32_t flags);



    status_t findThumbnailSample(uint32_t *sample_index);



    uint32_t getNumSyncSamples();

protected:

    ~SampleTable();