Bug 1275492 - Add logs for TextTrackManager. r=jwwang draft
authorbechen <bechen@mozilla.com>
Thu, 25 Aug 2016 10:58:49 +0800
changeset 405217 1332a79a3a83670aeac6f57ed9431e0ecebb5d73
parent 402505 a106fdd536bf0dbcb558dffac092ebe993e2e5d7
child 529391 cf6f729726de33aa5656f7680c38157671242a0f
push id27435
push userbechen@mozilla.com
push dateThu, 25 Aug 2016 03:04:09 +0000
reviewersjwwang
bugs1275492
milestone51.0a1
Bug 1275492 - Add logs for TextTrackManager. r=jwwang MozReview-Commit-ID: LyNTDhjj0fR
dom/html/TextTrackManager.cpp
--- a/dom/html/TextTrackManager.cpp
+++ b/dom/html/TextTrackManager.cpp
@@ -15,16 +15,21 @@
 #include "mozilla/Telemetry.h"
 #include "nsComponentManagerUtils.h"
 #include "nsVariant.h"
 #include "nsVideoFrame.h"
 #include "nsIFrame.h"
 #include "nsTArrayHelpers.h"
 #include "nsIWebVTTParserWrapper.h"
 
+
+static mozilla::LazyLogModule gTextTrackLog("TextTrackManager");
+#define WEBVTT_LOG(...)  MOZ_LOG(gTextTrackLog, LogLevel::Debug, (__VA_ARGS__))
+#define WEBVTT_LOGV(...) MOZ_LOG(gTextTrackLog, LogLevel::Verbose, (__VA_ARGS__))
+
 namespace mozilla {
 namespace dom {
 
 NS_IMPL_ISUPPORTS(TextTrackManager::ShutdownObserverProxy, nsIObserver);
 
 CompareTextTracks::CompareTextTracks(HTMLMediaElement* aMediaElement)
 {
   mMediaElement = aMediaElement;
@@ -99,17 +104,17 @@ TextTrackManager::TextTrackManager(HTMLM
   , performedTrackSelection(false)
   , mCueTelemetryReported(false)
   , mShutdown(false)
 {
   nsISupports* parentObject =
     mMediaElement->OwnerDoc()->GetParentObject();
 
   NS_ENSURE_TRUE_VOID(parentObject);
-
+  WEBVTT_LOG("%p Create TextTrackManager",this);
   nsCOMPtr<nsPIDOMWindowInner> window = do_QueryInterface(parentObject);
   mNewCues = new TextTrackCueList(window);
   mLastActiveCues = new TextTrackCueList(window);
   mTextTracks = new TextTrackList(window, this);
   mPendingTextTracks = new TextTrackList(window, this);
 
   if (!sParserWrapper) {
     nsCOMPtr<nsIWebVTTParserWrapper> parserWrapper =
@@ -117,16 +122,17 @@ TextTrackManager::TextTrackManager(HTMLM
     sParserWrapper = parserWrapper;
     ClearOnShutdown(&sParserWrapper);
   }
   mShutdownProxy = new ShutdownObserverProxy(this);
 }
 
 TextTrackManager::~TextTrackManager()
 {
+  WEBVTT_LOG("%p ~TextTrackManager",this);
   nsContentUtils::UnregisterShutdownObserver(mShutdownProxy);
 }
 
 TextTrackList*
 TextTrackManager::GetTextTracks() const
 {
   return mTextTracks;
 }
@@ -136,16 +142,19 @@ TextTrackManager::AddTextTrack(TextTrack
                                const nsAString& aLanguage,
                                TextTrackMode aMode,
                                TextTrackReadyState aReadyState,
                                TextTrackSource aTextTrackSource)
 {
   if (!mMediaElement || !mTextTracks) {
     return nullptr;
   }
+  WEBVTT_LOG("%p AddTextTrack",this);
+  WEBVTT_LOGV("AddTextTrack kind %d Label %s Language %s",aKind,
+    NS_ConvertUTF16toUTF8(aLabel).get(), NS_ConvertUTF16toUTF8(aLanguage).get());
   RefPtr<TextTrack> track =
     mTextTracks->AddTextTrack(aKind, aLabel, aLanguage, aMode, aReadyState,
                               aTextTrackSource, CompareTextTracks(mMediaElement));
   AddCues(track);
   ReportTelemetryForTrack(track);
 
   if (aTextTrackSource == TextTrackSource::Track) {
     NS_DispatchToMainThread(NewRunnableMethod(this, &TextTrackManager::HonorUserPreferencesForTrackSelection));
@@ -155,80 +164,88 @@ TextTrackManager::AddTextTrack(TextTrack
 }
 
 void
 TextTrackManager::AddTextTrack(TextTrack* aTextTrack)
 {
   if (!mMediaElement || !mTextTracks) {
     return;
   }
+  WEBVTT_LOG("%p AddTextTrack TextTrack %p",this, aTextTrack);
   mTextTracks->AddTextTrack(aTextTrack, CompareTextTracks(mMediaElement));
   AddCues(aTextTrack);
   ReportTelemetryForTrack(aTextTrack);
 
   if (aTextTrack->GetTextTrackSource() == TextTrackSource::Track) {
     NS_DispatchToMainThread(NewRunnableMethod(this, &TextTrackManager::HonorUserPreferencesForTrackSelection));
   }
 }
 
 void
 TextTrackManager::AddCues(TextTrack* aTextTrack)
 {
   if (!mNewCues) {
+    WEBVTT_LOG("AddCues mNewCues is null");
     return;
   }
 
   TextTrackCueList* cueList = aTextTrack->GetCues();
   if (cueList) {
     bool dummy;
+    WEBVTT_LOGV("AddCues cueList->Length() %d",cueList->Length());
     for (uint32_t i = 0; i < cueList->Length(); ++i) {
       mNewCues->AddCue(*cueList->IndexedGetter(i, dummy));
     }
     DispatchTimeMarchesOn();
   }
 }
 
 void
 TextTrackManager::RemoveTextTrack(TextTrack* aTextTrack, bool aPendingListOnly)
 {
   if (!mPendingTextTracks || !mTextTracks) {
     return;
   }
 
+  WEBVTT_LOG("%p RemoveTextTrack TextTrack %p", this, aTextTrack);
   mPendingTextTracks->RemoveTextTrack(aTextTrack);
   if (aPendingListOnly) {
     return;
   }
 
   mTextTracks->RemoveTextTrack(aTextTrack);
   // Remove the cues in mNewCues belong to aTextTrack.
   TextTrackCueList* removeCueList = aTextTrack->GetCues();
   if (removeCueList) {
+    WEBVTT_LOGV("RemoveTextTrack removeCueList->Length() %d", removeCueList->Length());
     for (uint32_t i = 0; i < removeCueList->Length(); ++i) {
       mNewCues->RemoveCue(*((*removeCueList)[i]));
     }
     DispatchTimeMarchesOn();
   }
 }
 
 void
 TextTrackManager::DidSeek()
 {
+  WEBVTT_LOG("%p DidSeek",this);
   if (mTextTracks) {
     mTextTracks->DidSeek();
   }
   if (mMediaElement) {
     mLastTimeMarchesOnCalled = mMediaElement->CurrentTime();
+    WEBVTT_LOGV("DidSeek set mLastTimeMarchesOnCalled %lf",mLastTimeMarchesOnCalled);
   }
   mHasSeeked = true;
 }
 
 void
 TextTrackManager::UpdateCueDisplay()
 {
+  WEBVTT_LOG("UpdateCueDisplay");
   mUpdateCueDisplayDispatched = false;
 
   if (!mMediaElement || !mTextTracks) {
     return;
   }
 
   nsIFrame* frame = mMediaElement->GetPrimaryFrame();
   nsVideoFrame* videoFrame = do_QueryFrame(frame);
@@ -241,44 +258,49 @@ TextTrackManager::UpdateCueDisplay()
   if (!overlay) {
     return;
   }
 
   nsTArray<RefPtr<TextTrackCue> > activeCues;
   mTextTracks->GetShowingCues(activeCues);
 
   if (activeCues.Length() > 0) {
+    WEBVTT_LOG("UpdateCueDisplay ProcessCues");
+    WEBVTT_LOGV("UpdateCueDisplay activeCues.Length() %d",activeCues.Length());
     RefPtr<nsVariantCC> jsCues = new nsVariantCC();
 
     jsCues->SetAsArray(nsIDataType::VTYPE_INTERFACE,
                        &NS_GET_IID(nsIDOMEventTarget),
                        activeCues.Length(),
                        static_cast<void*>(activeCues.Elements()));
     nsPIDOMWindowInner* window = mMediaElement->OwnerDoc()->GetInnerWindow();
     if (window) {
       sParserWrapper->ProcessCues(window, jsCues, overlay, controls);
     }
   } else if (overlay->Length() > 0) {
+    WEBVTT_LOG("UpdateCueDisplay EmptyString");
     nsContentUtils::SetNodeTextContent(overlay, EmptyString(), true);
   }
 }
 
 void
 TextTrackManager::NotifyCueAdded(TextTrackCue& aCue)
 {
+  WEBVTT_LOG("NotifyCueAdded");
   if (mNewCues) {
     mNewCues->AddCue(aCue);
   }
   DispatchTimeMarchesOn();
   ReportTelemetryForCue();
 }
 
 void
 TextTrackManager::NotifyCueRemoved(TextTrackCue& aCue)
 {
+  WEBVTT_LOG("NotifyCueRemoved");
   if (mNewCues) {
     mNewCues->RemoveCue(aCue);
   }
   DispatchTimeMarchesOn();
   if (aCue.GetActive()) {
     // We remove an active cue, need to update the display.
     DispatchUpdateCueDisplay();
   }
@@ -316,17 +338,17 @@ TextTrackManager::AddListeners()
 }
 
 void
 TextTrackManager::HonorUserPreferencesForTrackSelection()
 {
   if (performedTrackSelection || !mTextTracks) {
     return;
   }
-
+  WEBVTT_LOG("HonorUserPreferencesForTrackSelection");
   TextTrackKind ttKinds[] = { TextTrackKind::Captions,
                               TextTrackKind::Subtitles };
 
   // Steps 1 - 3: Perform automatic track selection for different TextTrack
   // Kinds.
   PerformTrackSelection(ttKinds, ArrayLength(ttKinds));
   PerformTrackSelection(TextTrackKind::Descriptions);
   PerformTrackSelection(TextTrackKind::Chapters);
@@ -366,27 +388,29 @@ TextTrackManager::PerformTrackSelection(
                                         uint32_t size)
 {
   nsTArray<TextTrack*> candidates;
   GetTextTracksOfKinds(aTextTrackKinds, size, candidates);
 
   // Step 3: If any TextTracks in candidates are showing then abort these steps.
   for (uint32_t i = 0; i < candidates.Length(); i++) {
     if (candidates[i]->Mode() == TextTrackMode::Showing) {
+      WEBVTT_LOGV("PerformTrackSelection Showing return kind %d",candidates[i]->Kind());
       return;
     }
   }
 
   // Step 4: Honor user preferences for track selection, otherwise, set the
   // first TextTrack in candidates with a default attribute to showing.
   // TODO: Bug 981691 - Honor user preferences for text track selection.
   for (uint32_t i = 0; i < candidates.Length(); i++) {
     if (TrackIsDefault(candidates[i]) &&
         candidates[i]->Mode() == TextTrackMode::Disabled) {
       candidates[i]->SetMode(TextTrackMode::Showing);
+      WEBVTT_LOGV("PerformTrackSelection set Showing kind %d", candidates[i]->Kind());
       return;
     }
   }
 }
 
 void
 TextTrackManager::GetTextTracksOfKinds(TextTrackKind aTextTrackKinds[],
                                        uint32_t size,
@@ -444,16 +468,18 @@ public:
                        TextTrack* aTrack, TextTrackCue* aCue)
   : mName(aEventName),
     mTime(aTime),
     mTrack(aTrack),
     mCue(aCue)
   {}
 
   NS_IMETHOD Run() {
+    WEBVTT_LOGV("SimpleTextTrackEvent cue %p mName %s mTime %lf",
+      mCue.get(), NS_ConvertUTF16toUTF8(mName).get(), mTime);
     mCue->DispatchTrustedEvent(mName);
     return NS_OK;
   }
 
 private:
   nsString mName;
   double mTime;
   TextTrack* mTrack;
@@ -528,64 +554,69 @@ private:
   nsTArray<RefPtr<TextTrack>> mTextTracks;
 };
 
 void
 TextTrackManager::DispatchUpdateCueDisplay()
 {
   if (!mUpdateCueDisplayDispatched && !mShutdown &&
       (mMediaElement->GetHasUserInteraction() || mMediaElement->IsCurrentlyPlaying())) {
+    WEBVTT_LOG("DispatchUpdateCueDisplay");
     NS_DispatchToMainThread(NewRunnableMethod(this, &TextTrackManager::UpdateCueDisplay));
     mUpdateCueDisplayDispatched = true;
   }
 }
 
 void
 TextTrackManager::DispatchTimeMarchesOn()
 {
   // Run the algorithm if no previous instance is still running, otherwise
   // enqueue the current playback position and whether only that changed
   // through its usual monotonic increase during normal playback; current
   // executing call upon completion will check queue for further 'work'.
   if (!mTimeMarchesOnDispatched && !mShutdown &&
       (mMediaElement->GetHasUserInteraction() || mMediaElement->IsCurrentlyPlaying())) {
+    WEBVTT_LOG("DispatchTimeMarchesOn");
     NS_DispatchToMainThread(NewRunnableMethod(this, &TextTrackManager::TimeMarchesOn));
     mTimeMarchesOnDispatched = true;
   }
 }
 
 // https://html.spec.whatwg.org/multipage/embedded-content.html#time-marches-on
 void
 TextTrackManager::TimeMarchesOn()
 {
   NS_ASSERTION(NS_IsMainThread(), "Wrong thread!");
-
+  WEBVTT_LOG("TimeMarchesOn");
   mTimeMarchesOnDispatched = false;
 
   // Early return if we don't have any TextTracks.
   if (!mTextTracks || mTextTracks->Length() == 0) {
     return;
   }
 
   nsISupports* parentObject =
     mMediaElement->OwnerDoc()->GetParentObject();
   if (NS_WARN_IF(!parentObject)) {
     return;
   }
   nsCOMPtr<nsPIDOMWindowInner> window = do_QueryInterface(parentObject);
 
   if (mMediaElement &&
       (!(mMediaElement->GetPlayedOrSeeked()) || mMediaElement->Seeking())) {
+    WEBVTT_LOG("TimeMarchesOn seeking or post return");
     return;
   }
 
   // Step 3.
   double currentPlaybackTime = mMediaElement->CurrentTime();
   bool hasNormalPlayback = !mHasSeeked;
   mHasSeeked = false;
+  WEBVTT_LOG("TimeMarchesOn mLastTimeMarchesOnCalled %lf currentPlaybackTime %lf hasNormalPlayback %d"
+      , mLastTimeMarchesOnCalled, currentPlaybackTime, hasNormalPlayback);
 
   // Step 1, 2.
   RefPtr<TextTrackCueList> currentCues =
     new TextTrackCueList(window);
   RefPtr<TextTrackCueList> otherCues =
     new TextTrackCueList(window);
   bool dummy;
   for (uint32_t index = 0; index < mTextTracks->Length(); ++index) {
@@ -596,16 +627,17 @@ TextTrackManager::TimeMarchesOn()
       TextTrackCueList* activeCueList = ttrack->GetActiveCues();
       if (activeCueList) {
         for (uint32_t i = 0; i < activeCueList->Length(); ++i) {
           currentCues->AddCue(*((*activeCueList)[i]));
         }
       }
     }
   }
+  WEBVTT_LOGV("TimeMarchesOn currentCues %d", currentCues->Length());
   // Populate otherCues with 'non-active" cues.
   if (hasNormalPlayback) {
     if (currentPlaybackTime < mLastTimeMarchesOnCalled) {
       // TODO: Add log and find the root cause why the
       // playback position goes backward.
       mLastTimeMarchesOnCalled = currentPlaybackTime;
     }
     media::Interval<double> interval(mLastTimeMarchesOnCalled,
@@ -614,29 +646,29 @@ TextTrackManager::TimeMarchesOn()
   } else {
     // Seek case. Put the mLastActiveCues into otherCues.
     otherCues = mLastActiveCues;
   }
   for (uint32_t i = 0; i < currentCues->Length(); ++i) {
     TextTrackCue* cue = (*currentCues)[i];
     otherCues->RemoveCue(*cue);
   }
-
+  WEBVTT_LOGV("TimeMarchesOn otherCues %d", otherCues->Length());
   // Step 4.
   RefPtr<TextTrackCueList> missedCues = new TextTrackCueList(window);
   if (hasNormalPlayback) {
     for (uint32_t i = 0; i < otherCues->Length(); ++i) {
       TextTrackCue* cue = (*otherCues)[i];
       if (cue->StartTime() >= mLastTimeMarchesOnCalled &&
           cue->EndTime() <= currentPlaybackTime) {
         missedCues->AddCue(*cue);
       }
     }
   }
-
+  WEBVTT_LOGV("TimeMarchesOn missedCues %d", missedCues->Length());
   // Step 5. Empty now.
   // TODO: Step 6: fire timeupdate?
 
   // Step 7. Abort steps if condition 1, 2, 3 are satisfied.
   // 1. All of the cues in current cues have their active flag set.
   // 2. None of the cues in other cues have their active flag set.
   // 3. Missed cues is empty.
   bool c1 = true;
@@ -651,31 +683,34 @@ TextTrackManager::TimeMarchesOn()
     if ((*otherCues)[i]->GetActive()) {
       c2 = false;
       break;
     }
   }
   bool c3 = (missedCues->Length() == 0);
   if (c1 && c2 && c3) {
     mLastTimeMarchesOnCalled = currentPlaybackTime;
+    WEBVTT_LOG("TimeMarchesOn step 7 return, mLastTimeMarchesOnCalled %lf", mLastTimeMarchesOnCalled);
     return;
   }
 
   // Step 8. Respect PauseOnExit flag if not seek.
   if (hasNormalPlayback) {
     for (uint32_t i = 0; i < otherCues->Length(); ++i) {
       TextTrackCue* cue = (*otherCues)[i];
       if (cue && cue->PauseOnExit() && cue->GetActive()) {
+        WEBVTT_LOG("TimeMarchesOn pause the MediaElement");
         mMediaElement->Pause();
         break;
       }
     }
     for (uint32_t i = 0; i < missedCues->Length(); ++i) {
       TextTrackCue* cue = (*missedCues)[i];
       if (cue && cue->PauseOnExit()) {
+        WEBVTT_LOG("TimeMarchesOn pause the MediaElement");
         mMediaElement->Pause();
         break;
       }
     }
   }
 
   // Step 15.
   // Sort text tracks in the same order as the text tracks appear
@@ -754,22 +789,24 @@ TextTrackManager::TimeMarchesOn()
   // Step 18.
   UpdateCueDisplay();
 }
 
 void
 TextTrackManager::NotifyCueUpdated(TextTrackCue *aCue)
 {
   // TODO: Add/Reorder the cue to mNewCues if we have some optimization?
+  WEBVTT_LOG("NotifyCueUpdated");
   DispatchTimeMarchesOn();
 }
 
 void
 TextTrackManager::NotifyReset()
 {
+  WEBVTT_LOG("NotifyReset");
   mLastTimeMarchesOnCalled = 0.0;
 }
 
 void
 TextTrackManager::ReportTelemetryForTrack(TextTrack* aTextTrack) const
 {
   MOZ_ASSERT(NS_IsMainThread());
   MOZ_ASSERT(aTextTrack);