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

Commit 035102c5 authored by Juan Escamilla's avatar Juan Escamilla Committed by Steve Kondik
Browse files

frameworks/base: Add rendering statistics to Stagefright 

Rendering statistics can be enabled by setting the property setprop
persist.debug.sf.statistics to 1. To disable, set the property to 0.

This adds the following logs:
-Clip type and duration
-Number of frames read by parser
-Number of key frames read by parser
-Number of frames dropped
-Number of frames rendered
-First frame latency
-Seek position and latency after seek
-Pause position
-Expected frames per second
-Real time delta of video if it's ahead or behind
-Maximum time delta of video if it's ahead or behind
-Number of occurrences of A/V sync loss
-Maximum time of A/V sync loss

Change-Id: I3eb9abffb71d3325a88f4bdbbef3f78bd675b056
parent e1237a90

include/media/stagefright/MediaSource.h

+3 −0
Original line number Diff line number Diff line
@@ -45,6 +45,9 @@ struct MediaSource : public RefBase { 
    // Returns the format of the data output by this media source.

    virtual sp<MetaData> getFormat() = 0;



    //Logs statistics profiling

    virtual void logTrackStatistics() {};



    struct ReadOptions;



    // Returns a new buffer of data. Call blocks until a

media/libstagefright/AwesomePlayer.cpp

+129 −1
Original line number Diff line number Diff line
@@ -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

media/libstagefright/MPEG4Extractor.cpp

+48 −1
Original line number Diff line number Diff line
@@ -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];

media/libstagefright/SampleTable.cpp

+5 −0
Original line number Diff line number Diff line
@@ -471,5 +471,10 @@ status_t SampleTable::getMetaDataForSample( 
    return OK;

}



uint32_t SampleTable::getNumSyncSamples()

{

    return mNumSyncSamples;

}



}  // namespace android

media/libstagefright/include/AwesomePlayer.h

+24 −0
Original line number Diff line number Diff line
@@ -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 &);

};