Permalink
Browse files

Changed mdone to mSeeking

  • Loading branch information...
1 parent 060ce86 commit 5959ca4581b8cc0bb9ad80e2b55478a09847e46a @paxchristos committed May 19, 2012
@@ -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);
@@ -1435,11 +1491,12 @@ status_t AwesomePlayer::initVideoDecoder(uint32_t flags) {
// (mSurface->getFlags() & ISurfaceComposer::eProtectedByApp))
// will be true, but that part is already handled by SurfaceFlinger.
+ char value[PROPERTY_VALUE_MAX];
+
#ifdef DEBUG_HDCP
// For debugging, we allow a system property to control the protected usage.
// In case of uninitialized or unexpected property, we default to "DRM only".
bool setProtectionBit = false;
- char value[PROPERTY_VALUE_MAX];
if (property_get("persist.sys.hdcp_checking", value, NULL)) {
if (!strcmp(value, "never")) {
// nop
@@ -1470,6 +1527,13 @@ status_t AwesomePlayer::initVideoDecoder(uint32_t flags) {
flags |= OMXCodec::kEnableGrallocUsageProtected;
}
#endif
+
+ property_get("sys.media.vdec.sw", value, "0");
+ if (atoi(value)) {
+ LOGW("Software Codec is preferred for Video");
+ flags |= OMXCodec::kPreferSoftwareCodecs;
+ }
+
LOGV("initVideoDecoder flags=0x%x", flags);
mVideoSource = OMXCodec::Create(
mClient.interface(), mVideoTrack->getFormat(),
@@ -1558,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() {
@@ -1701,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);
@@ -1722,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
@@ -1762,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();
@@ -1771,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;
}
@@ -1787,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();
@@ -2361,4 +2468,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
@@ -297,6 +297,17 @@ struct AwesomePlayer {
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 @@ struct AwesomePlayer {
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 &);
Oops, something went wrong.

0 comments on commit 5959ca4

Please sign in to comment.