Bug 1147555 - Implement logging for MediaTimer. r=mattwoodrow, a=lizzard
authorBobby Holley <bobbyholley@gmail.com>
Mon, 30 Mar 2015 15:17:04 -0700
changeset 265338 9a3865593e662e76a49e586f27a91f63f9428b92
parent 265337 c7b040ac1f4bfbca19a2058548f4270beaadb15f
child 265339 6adad6d402289163344db005d252152d7ec07343
push id4718
push userraliiev@mozilla.com
push dateMon, 11 May 2015 18:39:53 +0000
treeherdermozilla-beta@c20c4ef55f08 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmattwoodrow, lizzard
bugs1147555
milestone39.0a2
Bug 1147555 - Implement logging for MediaTimer. r=mattwoodrow, a=lizzard
dom/media/MediaTimer.cpp
dom/media/MediaTimer.h
--- a/dom/media/MediaTimer.cpp
+++ b/dom/media/MediaTimer.cpp
@@ -5,29 +5,42 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "MediaTimer.h"
 
 #include <math.h>
 
 #include "nsComponentManagerUtils.h"
 #include "nsThreadUtils.h"
+#include "mozilla/DebugOnly.h"
 #include "mozilla/RefPtr.h"
 #include "SharedThreadPool.h"
 
 namespace mozilla {
 
+PRLogModuleInfo* gMediaTimerLog;
+static void EnsureMediaTimerLog()
+{
+  if (!gMediaTimerLog) {
+    gMediaTimerLog = PR_NewLogModule("MediaTimer");
+  }
+}
+
 NS_IMPL_ADDREF(MediaTimer)
 NS_IMPL_RELEASE_WITH_DESTROY(MediaTimer, DispatchDestroy())
 
 MediaTimer::MediaTimer()
   : mMonitor("MediaTimer Monitor")
   , mTimer(do_CreateInstance("@mozilla.org/timer;1"))
+  , mCreationTimeStamp(TimeStamp::Now())
   , mUpdateScheduled(false)
 {
+  EnsureMediaTimerLog();
+  TIMER_LOG("MediaTimer::MediaTimer");
+
   // Use the SharedThreadPool to create an nsIThreadPool with a maximum of one
   // thread, which is equivalent to an nsIThread for our purposes.
   RefPtr<SharedThreadPool> threadPool(
     SharedThreadPool::Get(NS_LITERAL_CSTRING("MediaTimer"), 1));
   mThread = threadPool.get();
   mTimer->SetTarget(mThread);
 }
 
@@ -39,16 +52,17 @@ MediaTimer::DispatchDestroy()
   MOZ_DIAGNOSTIC_ASSERT(NS_SUCCEEDED(rv));
   (void) rv;
 }
 
 void
 MediaTimer::Destroy()
 {
   MOZ_ASSERT(OnMediaTimerThread());
+  TIMER_LOG("MediaTimer::Destroy");
 
   // Reject any outstanding entries. There's no need to acquire the monitor
   // here, because we're on the timer thread and all other references to us
   // must be gone.
   while (!mEntries.empty()) {
     mEntries.top().mPromise->Reject(false, __func__);
     mEntries.pop();
   }
@@ -66,16 +80,17 @@ MediaTimer::OnMediaTimerThread()
   mThread->IsOnCurrentThread(&rv);
   return rv;
 }
 
 nsRefPtr<MediaTimerPromise>
 MediaTimer::WaitUntil(const TimeStamp& aTimeStamp, const char* aCallSite)
 {
   MonitorAutoLock mon(mMonitor);
+  TIMER_LOG("MediaTimer::WaitUntil %lld", RelativeMicroseconds(aTimeStamp));
   Entry e(aTimeStamp, aCallSite);
   nsRefPtr<MediaTimerPromise> p = e.mPromise.get();
   mEntries.push(e);
   ScheduleUpdate();
   return p;
 }
 
 void
@@ -102,16 +117,18 @@ MediaTimer::Update()
 
 void
 MediaTimer::UpdateLocked()
 {
   MOZ_ASSERT(OnMediaTimerThread());
   mMonitor.AssertCurrentThreadOwns();
   mUpdateScheduled = false;
 
+  TIMER_LOG("MediaTimer::UpdateLocked");
+
   // Resolve all the promises whose time is up.
   TimeStamp now = TimeStamp::Now();
   while (!mEntries.empty() && mEntries.top().mTimeStamp <= now) {
     mEntries.top().mPromise->Resolve(true, __func__);
     DebugOnly<TimeStamp> poppedTimeStamp = mEntries.top().mTimeStamp;
     mEntries.pop();
     MOZ_ASSERT_IF(!mEntries.empty(), *&poppedTimeStamp <= mEntries.top().mTimeStamp);
   }
@@ -155,15 +172,16 @@ void
 MediaTimer::ArmTimer(const TimeStamp& aTarget, const TimeStamp& aNow)
 {
   MOZ_DIAGNOSTIC_ASSERT(!TimerIsArmed());
   MOZ_DIAGNOSTIC_ASSERT(aTarget > aNow);
 
   // XPCOM timer resolution is in milliseconds. It's important to never resolve
   // a timer when mTarget might compare < now (even if very close), so round up.
   unsigned long delay = std::ceil((aTarget - aNow).ToMilliseconds());
+  TIMER_LOG("MediaTimer::ArmTimer delay=%lu", delay);
   mCurrentTimerTarget = aTarget;
   nsresult rv = mTimer->InitWithFuncCallback(&TimerCallback, this, delay, nsITimer::TYPE_ONE_SHOT);
   MOZ_DIAGNOSTIC_ASSERT(NS_SUCCEEDED(rv));
   (void) rv;
 }
 
 } // namespace mozilla
--- a/dom/media/MediaTimer.h
+++ b/dom/media/MediaTimer.h
@@ -14,16 +14,23 @@
 #include "nsITimer.h"
 #include "nsRefPtr.h"
 
 #include "mozilla/Monitor.h"
 #include "mozilla/TimeStamp.h"
 
 namespace mozilla {
 
+extern PRLogModuleInfo* gMediaTimerLog;
+
+#define TIMER_LOG(x, ...) \
+  MOZ_ASSERT(gMediaTimerLog); \
+  PR_LOG(gMediaTimerLog, PR_LOG_DEBUG, ("[MediaTimer=%p relative_t=%lld]" x, this, \
+                                        RelativeMicroseconds(TimeStamp::Now()), ##__VA_ARGS__))
+
 // This promise type is only exclusive because so far there isn't a reason for
 // it not to be. Feel free to change that.
 typedef MediaPromise<bool, bool, /* IsExclusive = */ true> MediaTimerPromise;
 
 // Timers only know how to fire at a given thread, which creates an impedence
 // mismatch with code that operates with MediaTaskQueues. This class solves
 // that mismatch with a dedicated (but shared) thread and a nice MediaPromise-y
 // interface.
@@ -57,16 +64,17 @@ private:
   {
     return !mCurrentTimerTarget.IsNull();
   }
 
   void CancelTimerIfArmed()
   {
     MOZ_ASSERT(OnMediaTimerThread());
     if (TimerIsArmed()) {
+      TIMER_LOG("MediaTimer::CancelTimerIfArmed canceling timer");
       mTimer->Cancel();
       mCurrentTimerTarget = TimeStamp();
     }
   }
 
 
   struct Entry
   {
@@ -89,14 +97,23 @@ private:
 
   ThreadSafeAutoRefCnt mRefCnt;
   NS_DECL_OWNINGTHREAD
   nsCOMPtr<nsIEventTarget> mThread;
   std::priority_queue<Entry> mEntries;
   Monitor mMonitor;
   nsCOMPtr<nsITimer> mTimer;
   TimeStamp mCurrentTimerTarget;
+
+  // Timestamps only have relative meaning, so we need a base timestamp for
+  // logging purposes.
+  TimeStamp mCreationTimeStamp;
+  int64_t RelativeMicroseconds(const TimeStamp& aTimeStamp)
+  {
+    return (int64_t) (aTimeStamp - mCreationTimeStamp).ToMicroseconds();
+  }
+
   bool mUpdateScheduled;
 };
 
 } // namespace mozilla
 
 #endif