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

Commit 64878922 authored by Eric Ho's avatar Eric Ho Committed by Steve Kondik
Browse files

frameworks/av: rendering statistics for Stagefright 

- this adds extra fps statisticis
- report via dumpsys
 - prints statistics before reset at the end of playback onto
   logcat
 - add resume latency, from play_l to render
 - add seek latency, from seek_l to render
 - enabled using persist.debug.sf.statistics 1

 - print all statistics when seek or resume is issued.

Change-Id: Ia34611b89fbc580481f37c921d862711ffb24434
parent 702b9476

media/libstagefright/AwesomePlayer.cpp

+203 −9
Original line number Diff line number Diff line
@@ -260,6 +260,46 @@ AwesomePlayer::~AwesomePlayer() { 
    mClient.disconnect();

}



void AwesomePlayer::printStats() {

    char value[PROPERTY_VALUE_MAX];

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

    if (atoi(value) && mVideoSource != NULL) {

        ALOGE("===========================\n"

            "   videoDimensions(%d x %d)\n"

            "   Total Video Frames Decoded(%lld)\n"

            "   Total Video Frames Rendered(%lld)\n"

            "   Total Playback Duration(%lld ms)\n"

            "   numVideoFramesDropped(%lld)\n"

            "   Average Frames Per Second(%.4f)\n"

            "   Last Seek To Time(%lld ms)\n"

            "   Last Paused Time(%lld ms)\n"

            "   First Frame Latency (%lld ms)\n"

            "   Number of times AV Sync Lost(%u)\n"

            "   Max Video Ahead Time Delta(%u)\n"

            "   Max Video Behind Time Delta(%u)\n"

            "   Max Time Sync Loss(%u)\n"

            "   EOS(%d)\n"

            "   PLAYING(%d)\n"

            "===========================\n\n",

            mStats.mVideoWidth,

            mStats.mVideoHeight,

            mStats.mNumVideoFramesDecoded,

            mStats.mTotalFrames,

            mStats.mTotalTimeUs/1000,

            mStats.mNumVideoFramesDropped,

            mStats.mTotalTimeUs > 0 ? ((double)(mStats.mTotalFrames)*1E6)/((double)mStats.mTotalTimeUs) : 0,

            mStats.mLastSeekToTimeMs,

            mStats.mLastPausedTimeMs,

            mStats.mFirstFrameLatencyUs/1000,

            mStats.mNumTimesSyncLoss,

            -mStats.mMaxEarlyDelta/1000,

            mStats.mMaxLateDelta/1000,

            mStats.mMaxTimeSyncLoss/1000,

            (mFlags & VIDEO_AT_EOS) > 0,

            (mFlags & PLAYING) > 0);

    }

}



void AwesomePlayer::cancelPlayerEvents(bool keepNotifications) {

    mQueue.cancelEvent(mVideoEvent->eventID());

    mVideoEventPending = false;
@@ -595,6 +635,8 @@ void AwesomePlayer::reset_l() { 


    mVideoRenderer.clear();



    modifyFlags(PLAYING, CLEAR);

    printStats();

    if (mVideoSource != NULL) {

        shutdownVideoDecoder_l();

    }
@@ -630,6 +672,21 @@ void AwesomePlayer::reset_l() { 
        mStats.mVideoHeight = -1;

        mStats.mFlags = 0;

        mStats.mTracks.clear();

        mStats.mConsecutiveFramesDropped = 0;

        mStats.mCatchupTimeStart = 0;

        mStats.mNumTimesSyncLoss = 0;

        mStats.mMaxEarlyDelta = 0;

        mStats.mMaxLateDelta = 0;

        mStats.mMaxTimeSyncLoss = 0;

        mStats.mTotalFrames = 0;

        mStats.mLastFrameUs = 0;

        mStats.mTotalTimeUs = 0;

        mStats.mVeryFirstFrame = true;

        mStats.mFirstFrameLatencyUs = 0;

        mStats.mLastPausedTimeMs = 0;

        mStats.mLastSeekToTimeMs = 0;

        mStats.mResumeDelayStartUs = -1;

        mStats.mSeekDelayStartUs = -1;

    }



    mWatchForAudioSeekComplete = false;
@@ -1085,6 +1142,15 @@ status_t AwesomePlayer::play_l() { 
        mTimeSource = &mSystemTimeSource;

    }



    {

        Mutex::Autolock autoLock(mStatsLock);

        if (mStats.mVeryFirstFrame) {

            mStats.mFirstFrameLatencyStartUs = getTimeOfDayUs();

        } else {

            mStats.mResumeDelayStartUs = getTimeOfDayUs();

        }

    }



    if (mVideoSource != NULL) {

        // Kick off video playback

        postVideoEvent_l();
@@ -1309,6 +1375,12 @@ status_t AwesomePlayer::pause_l(bool at_eos) { 
                Playback::PAUSE, 0);

    }



    if(!(mFlags & VIDEO_AT_EOS)){

        Mutex::Autolock autoLock(mStatsLock);

        mStats.mLastPausedTimeMs = mVideoTimeUs/1000;

        printStats();

    }



    uint32_t params = IMediaPlayerService::kBatteryDataTrackDecoder;

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

        params |= IMediaPlayerService::kBatteryDataTrackAudio;
@@ -1469,6 +1541,11 @@ status_t AwesomePlayer::seekTo_l(int64_t timeUs) { 
    }



    mSeeking = SEEK;



    {

        Mutex::Autolock autoLock(mStatsLock);

        mStats.mSeekDelayStartUs = getTimeOfDayUs();

    }

    mSeekNotificationSent = false;

    mSeekTimeUs = timeUs;

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

                Playback::START, videoTimeUs / 1000);

    }



    {

        Mutex::Autolock autoLock(mStatsLock);

        mStats.mLastSeekToTimeMs = mSeekTimeUs/1000;

        printStats();

    }

}



void AwesomePlayer::onVideoEvent() {
@@ -1855,6 +1938,14 @@ void AwesomePlayer::onVideoEvent() { 
    }

    mVideoEventPending = false;



    {

        Mutex::Autolock autoLock(mStatsLock);

        if(!mStats.mVeryFirstFrame && mSeeking == NO_SEEK){

            mStats.mTotalTimeUs += getTimeOfDayUs() - mStats.mLastFrameUs;

        }

        mStats.mLastFrameUs = getTimeOfDayUs();

    }



    if (mSeeking != NO_SEEK) {

        if (mVideoBuffer) {

            mVideoBuffer->release();
@@ -1992,18 +2083,27 @@ void AwesomePlayer::onVideoEvent() { 
        modifyFlags(FIRST_FRAME, CLEAR);

        mSinceLastDropped = 0;

        mTimeSourceDeltaUs = ts->getRealTimeUs() - timeUs;



        {

            Mutex::Autolock autoLock(mStatsLock);

            if(mStats.mVeryFirstFrame){

                logFirstFrame();

                printStats();

                mStats.mLastFrameUs = getTimeOfDayUs();

            }

        }

    }



    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;



        ATRACE_INT("Video Lateness (ms)", latenessUs / 1E3);
@@ -2015,9 +2115,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;



        ATRACE_INT("Video Lateness (ms)", latenessUs / 1E3);
@@ -2064,6 +2164,11 @@ void AwesomePlayer::onVideoEvent() { 
                {

                    Mutex::Autolock autoLock(mStatsLock);

                    ++mStats.mNumVideoFramesDropped;

                    mStats.mConsecutiveFramesDropped++;

                    if (mStats.mConsecutiveFramesDropped == 1){

                        mStats.mCatchupTimeStart = mTimeSource->getRealTimeUs();

                    }

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

                }

                int64_t eventDurationUs = mSystemTimeSource.getRealTimeUs() - eventStartTimeUs;

                int64_t delayUs = mFrameDurationUs - eventDurationUs - latenessUs - earlyGapUs;
@@ -2075,6 +2180,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;

        }
@@ -2095,6 +2205,26 @@ void AwesomePlayer::onVideoEvent() { 
            notifyListener_l(MEDIA_INFO, MEDIA_INFO_RENDERING_START);

        }



        {

            Mutex::Autolock autoLock(mStatsLock);

            logOnTime(timeUs,nowUs,latenessUs);

            mStats.mTotalFrames++;

            mStats.mConsecutiveFramesDropped = 0;

            char value[PROPERTY_VALUE_MAX];

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

            if (atoi(value) && mVideoSource != NULL) {

                if (mStats.mResumeDelayStartUs > 0) {

                    printStats();

                    ALOGE("Resume Latency = %lld us", getTimeOfDayUs() - mStats.mResumeDelayStartUs);

                    mStats.mResumeDelayStartUs = -1;

                }

                if (mStats.mSeekDelayStartUs > 0) {

                    printStats();

                    ALOGE("Seek Latency = %lld us", getTimeOfDayUs() - mStats.mSeekDelayStartUs);

                    mStats.mSeekDelayStartUs = -1;

                }

            }

        }

    }



    mVideoBuffer->release();
@@ -2916,13 +3046,33 @@ status_t AwesomePlayer::dump(int fd, const Vector<String16> &args) const { 


        if ((ssize_t)i == mStats.mVideoTrackIndex) {

            fprintf(out,

                    "   videoDimensions(%d x %d), "

                    "numVideoFramesDecoded(%lld), "

                    "numVideoFramesDropped(%lld)\n",

                    "   videoDimensions(%d x %d)\n"

                    "   Total Video Frames Decoded(%lld)\n"

                    "   Total Video Frames Rendered(%lld)\n"

                    "   Total Playback Duration(%lld ms)\n"

                    "   numVideoFramesDropped(%lld)\n"

                    "   Average Frames Per Second(%.4f)\n"

                    "   First Frame Latency (%lld ms)\n"

                    "   Number of times AV Sync Lost(%u)\n"

                    "   Max Video Ahead Time Delta(%u)\n"

                    "   Max Video Behind Time Delta(%u)\n"

                    "   Max Time Sync Loss(%u)\n"

                    "   EOS(%d)\n"

                    "   PLAYING(%d)\n",

                    mStats.mVideoWidth,

                    mStats.mVideoHeight,

                    mStats.mNumVideoFramesDecoded,

                    mStats.mNumVideoFramesDropped);

                    mStats.mTotalFrames,

                    mStats.mTotalTimeUs/1000,

                    mStats.mNumVideoFramesDropped,

                    ((double)(mStats.mTotalFrames)*1E6)/((double)mStats.mTotalTimeUs),

                    mStats.mFirstFrameLatencyUs/1000,

                    mStats.mNumTimesSyncLoss,

                    -mStats.mMaxEarlyDelta/1000,

                    mStats.mMaxLateDelta/1000,

                    mStats.mMaxTimeSyncLoss/1000,

                    (mFlags & AT_EOS) > 0,

                    (mFlags & PLAYING) > 0);

        }

    }
@@ -3047,4 +3197,48 @@ void AwesomePlayer::checkTunnelExceptions() 
}

#endif



inline void AwesomePlayer::logFirstFrame() {

    mStats.mFirstFrameLatencyUs = getTimeOfDayUs()-mStats.mFirstFrameLatencyStartUs;

    mStats.mVeryFirstFrame = false;

}



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

}



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/include/AwesomePlayer.h

+24 −0
Original line number Diff line number Diff line
@@ -309,6 +309,13 @@ private: 
#ifdef USE_TUNNEL_MODE

    void checkTunnelExceptions();

#endif

    void logFirstFrame();

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

    int64_t getTimeOfDayUs();

    bool mStatistics;



    struct TrackStat {

        String8 mMIME;
@@ -334,6 +341,23 @@ 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;

        uint64_t mTotalFrames;

        int64_t mFirstFrameLatencyStartUs; //first frame latency start

        int64_t mFirstFrameLatencyUs;

        int64_t mLastFrameUs;

        bool mVeryFirstFrame;

        int64_t mTotalTimeUs;

        int64_t mLastPausedTimeMs;

        int64_t mLastSeekToTimeMs;

        int64_t mResumeDelayStartUs;

        int64_t mSeekDelayStartUs;

    } mStats;



    status_t setVideoScalingMode(int32_t mode);