commit 0d98c1809f2f763be0b68ffb1daff916d5ed0bb2
author Ray Essick <essick@google.com> Thu Nov 09 13:42:42 2017 -0800
committer Ray Essick <essick@google.com> Thu Nov 09 13:42:42 2017 -0800
tree 155f499e5c019f931eb9bd90f25fad3132a4cd07
parent dd97f52b3969ee8d6fb611e045ada26037e44e27

Improve tracking of 'playing time' metrics

Some field records sometimes showed non-zero frames played, but zero
playback time; a combination that should not be possible. Tracked to
alternate exit conditions that didn't go through the existing 'update
the stat here'.  Now managing time at some other identified possible
paths for playback exit.

Bug: 68273679
Test: manual video playback
Change-Id: I196120c49ec92d2e30d53a6e9eed9c60f1b8f2a7

media/libmediaplayerservice/nuplayer/NuPlayer.cpp

diff --git a/media/libmediaplayerservice/nuplayer/NuPlayer.cpp b/media/libmediaplayerservice/nuplayer/NuPlayer.cpp
index 2aa5c40..0f0f868 100644
--- a/media/libmediaplayerservice/nuplayer/NuPlayer.cpp
+++ b/media/libmediaplayerservice/nuplayer/NuPlayer.cpp
@@ -182,6 +182,7 @@
       mAudioDecoderGeneration(0),
       mVideoDecoderGeneration(0),
       mRendererGeneration(0),
+      mLastStartedPlayingTimeNs(0),
       mPreviousSeekTimeUs(0),
       mAudioEOS(false),
       mVideoEOS(false),
@@ -1309,6 +1310,7 @@
             ALOGV("kWhatReset");
 
             mResetting = true;
+            stopPlaybackTimer("kWhatReset");
 
             mDeferredActions.push_back(
                     new FlushDecoderAction(
@@ -1449,7 +1451,7 @@
         ALOGW("resume called when renderer is gone or not set");
     }
 
-    mLastStartedPlayingTimeNs = systemTime();
+    startPlaybackTimer("onresume");
 }
 
 status_t NuPlayer::onInstantiateSecureDecoders() {
@@ -1569,12 +1571,43 @@
         mAudioDecoder->setRenderer(mRenderer);
     }
 
-    mLastStartedPlayingTimeNs = systemTime();
+    startPlaybackTimer("onstart");
 
     postScanSources();
 }
 
+void NuPlayer::startPlaybackTimer(const char *where) {
+    Mutex::Autolock autoLock(mPlayingTimeLock);
+    if (mLastStartedPlayingTimeNs == 0) {
+        mLastStartedPlayingTimeNs = systemTime();
+        ALOGV("startPlaybackTimer() time %20" PRId64 " (%s)",  mLastStartedPlayingTimeNs, where);
+    }
+}
+
+void NuPlayer::stopPlaybackTimer(const char *where) {
+    Mutex::Autolock autoLock(mPlayingTimeLock);
+
+    ALOGV("stopPlaybackTimer()  time %20" PRId64 " (%s)", mLastStartedPlayingTimeNs, where);
+
+    if (mLastStartedPlayingTimeNs != 0) {
+        sp<NuPlayerDriver> driver = mDriver.promote();
+        if (driver != NULL) {
+            int64_t now = systemTime();
+            int64_t played = now - mLastStartedPlayingTimeNs;
+            ALOGV("stopPlaybackTimer()  log  %20" PRId64 "", played);
+
+            if (played > 0) {
+                driver->notifyMorePlayingTimeUs((played+500)/1000);
+            }
+        }
+        mLastStartedPlayingTimeNs = 0;
+    }
+}
+
 void NuPlayer::onPause() {
+
+    stopPlaybackTimer("onPause");
+
     if (mPaused) {
         return;
     }
@@ -1590,13 +1623,6 @@
         ALOGW("pause called when renderer is gone or not set");
     }
 
-    sp<NuPlayerDriver> driver = mDriver.promote();
-    if (driver != NULL) {
-        int64_t now = systemTime();
-        int64_t played = now - mLastStartedPlayingTimeNs;
-
-        driver->notifyMorePlayingTimeUs((played+500)/1000);
-    }
 }
 
 bool NuPlayer::audioDecoderStillNeeded() {
@@ -2223,6 +2249,8 @@
     CHECK(mAudioDecoder == NULL);
     CHECK(mVideoDecoder == NULL);
 
+    stopPlaybackTimer("performReset");
+
     cancelPollDuration();
 
     ++mScanSourcesGeneration;