Bug 1221674 - Add telemetry probe in the content process to measure the time between refresh driver ticks. r=avih, a=ritu
authorMason Chang <mchang@mozilla.com>
Fri, 06 Nov 2015 08:20:58 -0800
changeset 297675 8f0b0f852ca1e6cde52ae6ecb62cf9b02d094fe3
parent 297672 722c66ce28ff0da90c0df24e79215f6687498741
child 297693 575d3aa376b1c8e7507d94833f7b74bf963127cb
push idunknown
push userunknown
push dateunknown
reviewersavih, ritu
bugs1221674
milestone44.0a2
Bug 1221674 - Add telemetry probe in the content process to measure the time between refresh driver ticks. r=avih, a=ritu
gfx/thebes/SoftwareVsyncSource.cpp
gfx/thebes/SoftwareVsyncSource.h
gfx/thebes/VsyncSource.cpp
gfx/thebes/VsyncSource.h
gfx/thebes/gfxPlatformMac.cpp
gfx/thebes/gfxWindowsPlatform.cpp
layout/base/nsRefreshDriver.cpp
layout/ipc/PVsync.ipdl
layout/ipc/VsyncChild.cpp
layout/ipc/VsyncChild.h
layout/ipc/VsyncParent.cpp
layout/ipc/VsyncParent.h
toolkit/components/telemetry/Histograms.json
--- a/gfx/thebes/SoftwareVsyncSource.cpp
+++ b/gfx/thebes/SoftwareVsyncSource.cpp
@@ -107,16 +107,22 @@ SoftwareDisplay::NotifyVsync(mozilla::Ti
 
   Display::NotifyVsync(displayVsyncTime);
 
   // Prevent skew by still scheduling based on the original
   // vsync timestamp
   ScheduleNextVsync(aVsyncTimestamp);
 }
 
+mozilla::TimeDuration
+SoftwareDisplay::GetVsyncRate()
+{
+  return mVsyncRate;
+}
+
 void
 SoftwareDisplay::ScheduleNextVsync(mozilla::TimeStamp aVsyncTimestamp)
 {
   MOZ_ASSERT(IsInSoftwareVsyncThread());
   mozilla::TimeStamp nextVsync = aVsyncTimestamp + mVsyncRate;
   mozilla::TimeDuration delay = nextVsync - mozilla::TimeStamp::Now();
   if (delay.ToMilliseconds() < 0) {
     delay = mozilla::TimeDuration::FromMilliseconds(0);
--- a/gfx/thebes/SoftwareVsyncSource.h
+++ b/gfx/thebes/SoftwareVsyncSource.h
@@ -22,16 +22,17 @@ class SoftwareDisplay final : public moz
 
 public:
   SoftwareDisplay();
   virtual void EnableVsync() override;
   virtual void DisableVsync() override;
   virtual bool IsVsyncEnabled() override;
   bool IsInSoftwareVsyncThread();
   virtual void NotifyVsync(mozilla::TimeStamp aVsyncTimestamp) override;
+  virtual mozilla::TimeDuration GetVsyncRate() override;
   void ScheduleNextVsync(mozilla::TimeStamp aVsyncTimestamp);
   void Shutdown();
 
 protected:
   ~SoftwareDisplay();
 
 private:
   mozilla::TimeDuration mVsyncRate;
--- a/gfx/thebes/VsyncSource.cpp
+++ b/gfx/thebes/VsyncSource.cpp
@@ -63,16 +63,23 @@ VsyncSource::Display::NotifyVsync(TimeSt
 
   for (size_t i = 0; i < mCompositorVsyncDispatchers.Length(); i++) {
     mCompositorVsyncDispatchers[i]->NotifyVsync(aVsyncTimestamp);
   }
 
   mRefreshTimerVsyncDispatcher->NotifyVsync(aVsyncTimestamp);
 }
 
+TimeDuration
+VsyncSource::Display::GetVsyncRate()
+{
+  // If hardware queries fail / are unsupported, we have to just guess.
+  return TimeDuration::FromMilliseconds(1000.0 / 60.0);
+}
+
 void
 VsyncSource::Display::AddCompositorVsyncDispatcher(CompositorVsyncDispatcher* aCompositorVsyncDispatcher)
 {
   MOZ_ASSERT(NS_IsMainThread());
   MOZ_ASSERT(aCompositorVsyncDispatcher);
   { // scope lock
     MutexAutoLock lock(mDispatcherLock);
     if (!mCompositorVsyncDispatchers.Contains(aCompositorVsyncDispatcher)) {
--- a/gfx/thebes/VsyncSource.h
+++ b/gfx/thebes/VsyncSource.h
@@ -34,27 +34,28 @@ public:
       Display();
       virtual ~Display();
 
       // Notified when this display's vsync occurs, on the vsync thread
       // The aVsyncTimestamp should normalize to the Vsync time that just occured
       // However, different platforms give different vsync notification times.
       // b2g - The vsync timestamp of the previous frame that was just displayed
       // OSX - The vsync timestamp of the upcoming frame, in the future
-      // TODO: Windows / Linux. DOCUMENT THIS WHEN IMPLEMENTING ON THOSE PLATFORMS
+      // Windows: It's messy, see gfxWindowsPlatform.
       // Android: TODO
       // All platforms should normalize to the vsync that just occured.
       // Large parts of Gecko assume TimeStamps should not be in the future such as animations
       virtual void NotifyVsync(TimeStamp aVsyncTimestamp);
 
       RefPtr<RefreshTimerVsyncDispatcher> GetRefreshTimerVsyncDispatcher();
 
       void AddCompositorVsyncDispatcher(CompositorVsyncDispatcher* aCompositorVsyncDispatcher);
       void RemoveCompositorVsyncDispatcher(CompositorVsyncDispatcher* aCompositorVsyncDispatcher);
       void NotifyRefreshTimerVsyncStatus(bool aEnable);
+      virtual TimeDuration GetVsyncRate();
 
       // These should all only be called on the main thread
       virtual void EnableVsync() = 0;
       virtual void DisableVsync() = 0;
       virtual bool IsVsyncEnabled() = 0;
 
     private:
       void UpdateVsyncStatus();
--- a/gfx/thebes/gfxPlatformMac.cpp
+++ b/gfx/thebes/gfxPlatformMac.cpp
@@ -537,16 +537,28 @@ public:
       }
 
       mPreviousTimestamp = TimeStamp::Now();
       if (CVDisplayLinkStart(mDisplayLink) != kCVReturnSuccess) {
         NS_WARNING("Could not activate the display link");
         CVDisplayLinkRelease(mDisplayLink);
         mDisplayLink = nullptr;
       }
+
+      CVTime vsyncRate = CVDisplayLinkGetNominalOutputVideoRefreshPeriod(mDisplayLink);
+      if (vsyncRate.flags & kCVTimeIsIndefinite) {
+        NS_WARNING("Could not get vsync rate, setting to 60.");
+        mVsyncRate = TimeDuration::FromMilliseconds(1000.0 / 60.0);
+      } else {
+        int64_t timeValue = vsyncRate.timeValue;
+        int64_t timeScale = vsyncRate.timeScale;
+        const int milliseconds = 1000;
+        float rateInMs = ((double) timeValue / (double) timeScale) * milliseconds;
+        mVsyncRate = TimeDuration::FromMilliseconds(rateInMs);
+      }
     }
 
     virtual void DisableVsync() override
     {
       MOZ_ASSERT(NS_IsMainThread());
       if (!IsVsyncEnabled()) {
         return;
       }
@@ -559,27 +571,33 @@ public:
     }
 
     virtual bool IsVsyncEnabled() override
     {
       MOZ_ASSERT(NS_IsMainThread());
       return mDisplayLink != nullptr;
     }
 
+    virtual TimeDuration GetVsyncRate() override
+    {
+      return mVsyncRate;
+    }
+
     // The vsync timestamps given by the CVDisplayLinkCallback are
     // in the future for the NEXT frame. Large parts of Gecko, such
     // as animations assume a timestamp at either now or in the past.
     // Normalize the timestamps given to the VsyncDispatchers to the vsync
     // that just occured, not the vsync that is upcoming.
     TimeStamp mPreviousTimestamp;
 
   private:
     // Manages the display link render thread
     CVDisplayLinkRef   mDisplayLink;
     RefPtr<nsITimer> mTimer;
+    TimeDuration mVsyncRate;
   }; // OSXDisplay
 
 private:
   virtual ~OSXVsyncSource()
   {
   }
 
   OSXDisplay mGlobalDisplay;
--- a/gfx/thebes/gfxWindowsPlatform.cpp
+++ b/gfx/thebes/gfxWindowsPlatform.cpp
@@ -2694,16 +2694,39 @@ public:
         : mVsyncEnabledLock("D3DVsyncEnabledLock")
         , mPrevVsync(TimeStamp::Now())
         , mVsyncEnabled(false)
       {
         mVsyncThread = new base::Thread("WindowsVsyncThread");
         const double rate = 1000 / 60.0;
         mSoftwareVsyncRate = TimeDuration::FromMilliseconds(rate);
         MOZ_RELEASE_ASSERT(mVsyncThread->Start(), "Could not start Windows vsync thread");
+        SetVsyncRate();
+      }
+
+      void SetVsyncRate()
+      {
+        if (!DwmCompositionEnabled()) {
+          mVsyncRate = TimeDuration::FromMilliseconds(1000.0 / 60.0);
+          return;
+        }
+
+        DWM_TIMING_INFO vblankTime;
+        // Make sure to init the cbSize, otherwise GetCompositionTiming will fail
+        vblankTime.cbSize = sizeof(DWM_TIMING_INFO);
+        HRESULT hr = WinUtils::dwmGetCompositionTimingInfoPtr(0, &vblankTime);
+        if (SUCCEEDED(hr)) {
+          UNSIGNED_RATIO refreshRate = vblankTime.rateRefresh;
+          // We get the rate in hertz / time, but we want the rate in ms.
+          float rate = ((float) refreshRate.uiDenominator
+                       / (float) refreshRate.uiNumerator) * 1000;
+          mVsyncRate = TimeDuration::FromMilliseconds(rate);
+        } else {
+          mVsyncRate = TimeDuration::FromMilliseconds(1000.0 / 60.0);
+        }
       }
 
       virtual void EnableVsync() override
       {
         MOZ_ASSERT(NS_IsMainThread());
         MOZ_ASSERT(mVsyncThread->IsRunning());
         { // scope lock
           MonitorAutoLock lock(mVsyncEnabledLock);
@@ -2731,16 +2754,21 @@ public:
 
       virtual bool IsVsyncEnabled() override
       {
         MOZ_ASSERT(NS_IsMainThread());
         MonitorAutoLock lock(mVsyncEnabledLock);
         return mVsyncEnabled;
       }
 
+      virtual TimeDuration GetVsyncRate() override
+      {
+        return mVsyncRate;
+      }
+
       void ScheduleSoftwareVsync(TimeStamp aVsyncTimestamp)
       {
         MOZ_ASSERT(IsInVsyncThread());
         NS_WARNING("DwmComposition dynamically disabled, falling back to software timers");
 
         TimeStamp nextVsync = aVsyncTimestamp + mSoftwareVsyncRate;
         TimeDuration delay = nextVsync - TimeStamp::Now();
         if (delay.ToMilliseconds() < 0) {
@@ -2856,16 +2884,17 @@ public:
       {
         return mVsyncThread->thread_id() == PlatformThread::CurrentId();
       }
 
       TimeDuration mSoftwareVsyncRate;
       TimeStamp mPrevVsync; // Only used on Windows 10
       Monitor mVsyncEnabledLock;
       base::Thread* mVsyncThread;
+      TimeDuration mVsyncRate;
       bool mVsyncEnabled;
   }; // end d3dvsyncdisplay
 
   D3DVsyncSource()
   {
     mPrimaryDisplay = new D3DVsyncDisplay();
   }
 
--- a/layout/base/nsRefreshDriver.cpp
+++ b/layout/base/nsRefreshDriver.cpp
@@ -308,16 +308,19 @@ private:
   // to (a) make all RefreshDriverTimer RefCounted or (b) use different
   // VsyncObserver types.
   class RefreshDriverVsyncObserver final : public VsyncObserver
   {
   public:
     explicit RefreshDriverVsyncObserver(VsyncRefreshDriverTimer* aVsyncRefreshDriverTimer)
       : mVsyncRefreshDriverTimer(aVsyncRefreshDriverTimer)
       , mRefreshTickLock("RefreshTickLock")
+      , mRecentVsync(TimeStamp::Now())
+      , mLastChildTick(TimeStamp::Now())
+      , mVsyncRate(TimeDuration::Forever())
       , mProcessedVsync(true)
     {
       MOZ_ASSERT(NS_IsMainThread());
     }
 
     virtual bool NotifyVsync(TimeStamp aVsyncTimestamp) override
     {
       if (!NS_IsMainThread()) {
@@ -347,49 +350,82 @@ private:
     }
 
     void Shutdown()
     {
       MOZ_ASSERT(NS_IsMainThread());
       mVsyncRefreshDriverTimer = nullptr;
     }
 
+    void OnTimerStart()
+    {
+      if (!XRE_IsParentProcess()) {
+        mLastChildTick = TimeStamp::Now();
+      }
+    }
+
   private:
     virtual ~RefreshDriverVsyncObserver() {}
 
+    void RecordTelemetryProbes(TimeStamp aVsyncTimestamp)
+    {
+      MOZ_ASSERT(NS_IsMainThread());
+    #ifndef ANDROID  /* bug 1142079 */
+      if (XRE_IsParentProcess()) {
+        TimeDuration vsyncLatency = TimeStamp::Now() - aVsyncTimestamp;
+        Telemetry::Accumulate(Telemetry::FX_REFRESH_DRIVER_CHROME_FRAME_DELAY_MS,
+                              vsyncLatency.ToMilliseconds());
+      } else if (mVsyncRate != TimeDuration::Forever()) {
+        TimeDuration contentDelay = (TimeStamp::Now() - mLastChildTick) - mVsyncRate;
+        if (contentDelay.ToMilliseconds() < 0 ){
+          // Vsyncs are noisy and some can come at a rate quicker than
+          // the reported hardware rate. In those cases, consider that we have 0 delay.
+          contentDelay = TimeDuration::FromMilliseconds(0);
+        }
+        Telemetry::Accumulate(Telemetry::FX_REFRESH_DRIVER_CONTENT_FRAME_DELAY_MS,
+                              contentDelay.ToMilliseconds());
+      } else {
+        // Request the vsync rate from the parent process. Might be a few vsyncs
+        // until the parent responds.
+        mVsyncRate = mVsyncRefreshDriverTimer->mVsyncChild->GetVsyncRate();
+      }
+    #endif
+    }
+
     void TickRefreshDriver(TimeStamp aVsyncTimestamp)
     {
       MOZ_ASSERT(NS_IsMainThread());
+      RecordTelemetryProbes(aVsyncTimestamp);
 
       if (XRE_IsParentProcess()) {
         MonitorAutoLock lock(mRefreshTickLock);
-        #ifndef ANDROID  /* bug 1142079 */
-          TimeDuration vsyncLatency = TimeStamp::Now() - aVsyncTimestamp;
-          Telemetry::Accumulate(Telemetry::FX_REFRESH_DRIVER_CHROME_FRAME_DELAY_MS,
-          vsyncLatency.ToMilliseconds());
-        #endif
         aVsyncTimestamp = mRecentVsync;
         mProcessedVsync = true;
+      } else {
+        mLastChildTick= TimeStamp::Now();
       }
+
       MOZ_ASSERT(aVsyncTimestamp <= TimeStamp::Now());
 
       // We might have a problem that we call ~VsyncRefreshDriverTimer() before
       // the scheduled TickRefreshDriver() runs. Check mVsyncRefreshDriverTimer
       // before use.
       if (mVsyncRefreshDriverTimer) {
         mVsyncRefreshDriverTimer->RunRefreshDrivers(aVsyncTimestamp);
       }
     }
 
     // VsyncRefreshDriverTimer holds this RefreshDriverVsyncObserver and it will
     // be always available before Shutdown(). We can just use the raw pointer
     // here.
     VsyncRefreshDriverTimer* mVsyncRefreshDriverTimer;
     Monitor mRefreshTickLock;
     TimeStamp mRecentVsync;
+    TimeStamp mLastChildTick;
+    TimeDuration mVsyncRate;
     bool mProcessedVsync;
   }; // RefreshDriverVsyncObserver
 
   virtual ~VsyncRefreshDriverTimer()
   {
     if (XRE_IsParentProcess()) {
       mVsyncDispatcher->SetParentRefreshTimer(nullptr);
       mVsyncDispatcher = nullptr;
@@ -413,16 +449,17 @@ private:
   {
     mLastFireEpoch = JS_Now();
     mLastFireTime = TimeStamp::Now();
 
     if (XRE_IsParentProcess()) {
       mVsyncDispatcher->SetParentRefreshTimer(mVsyncObserver);
     } else {
       unused << mVsyncChild->SendObserve();
+      mVsyncObserver->OnTimerStart();
     }
   }
 
   virtual void StopTimer() override
   {
     if (XRE_IsParentProcess()) {
       mVsyncDispatcher->SetParentRefreshTimer(nullptr);
     } else {
--- a/layout/ipc/PVsync.ipdl
+++ b/layout/ipc/PVsync.ipdl
@@ -18,20 +18,24 @@ namespace layout {
 async protocol PVsync
 {
   manager PBackground;
 
 child:
   // Send vsync event from chrome to content process.
   async Notify(TimeStamp aVsyncTimestamp) compress;
 
+  // Send the vsync rate to the content process.
+  async VsyncRate(float aVsyncRate);
+
 parent:
   // Content process use these messages to acquire the vsync event.
   async Observe();
   async Unobserve();
+  async RequestVsyncRate();
 
   // This message is never sent. Each PVsync actor will stay alive as long as
   // its PBackground manager.
   async __delete__();
 };
 
 } // namespace layout
 } // namespace mozilla
--- a/layout/ipc/VsyncChild.cpp
+++ b/layout/ipc/VsyncChild.cpp
@@ -9,16 +9,17 @@
 #include "nsThreadUtils.h"
 
 namespace mozilla {
 namespace layout {
 
 VsyncChild::VsyncChild()
   : mObservingVsync(false)
   , mIsShutdown(false)
+  , mVsyncRate(TimeDuration::Forever())
 {
   MOZ_ASSERT(NS_IsMainThread());
 }
 
 VsyncChild::~VsyncChild()
 {
   MOZ_ASSERT(NS_IsMainThread());
 }
@@ -67,10 +68,27 @@ VsyncChild::RecvNotify(const TimeStamp& 
 
 void
 VsyncChild::SetVsyncObserver(VsyncObserver* aVsyncObserver)
 {
   MOZ_ASSERT(NS_IsMainThread());
   mObserver = aVsyncObserver;
 }
 
+TimeDuration
+VsyncChild::GetVsyncRate()
+{
+  if (mVsyncRate == TimeDuration::Forever()) {
+    PVsyncChild::SendRequestVsyncRate();
+  }
+
+  return mVsyncRate;
+}
+
+bool
+VsyncChild::RecvVsyncRate(const float& aVsyncRate)
+{
+  mVsyncRate = TimeDuration::FromMilliseconds(aVsyncRate);
+  return true;
+}
+
 } // namespace layout
 } // namespace mozilla
--- a/layout/ipc/VsyncChild.h
+++ b/layout/ipc/VsyncChild.h
@@ -33,27 +33,30 @@ class VsyncChild final : public PVsyncCh
 public:
   // Hide the SendObserve/SendUnobserve in PVsyncChild. We add an flag
   // mObservingVsync to handle the race problem of unobserving vsync event.
   bool SendObserve();
   bool SendUnobserve();
 
   // Bind a VsyncObserver into VsyncChild after ipc channel connected.
   void SetVsyncObserver(VsyncObserver* aVsyncObserver);
+  TimeDuration GetVsyncRate();
 
 private:
   VsyncChild();
   virtual ~VsyncChild();
 
   virtual bool RecvNotify(const TimeStamp& aVsyncTimestamp) override;
+  virtual bool RecvVsyncRate(const float& aVsyncRate) override;
   virtual void ActorDestroy(ActorDestroyReason aActorDestroyReason) override;
 
   bool mObservingVsync;
   bool mIsShutdown;
 
   // The content side vsync observer.
   RefPtr<VsyncObserver> mObserver;
+  TimeDuration mVsyncRate;
 };
 
 } // namespace layout
 } // namespace mozilla
 
 #endif  // mozilla_layout_ipc_VsyncChild_h
--- a/layout/ipc/VsyncParent.cpp
+++ b/layout/ipc/VsyncParent.cpp
@@ -68,16 +68,25 @@ VsyncParent::DispatchVsyncEvent(TimeStam
   // NotifyVsync(). We use mObservingVsync and mDestroyed flags to skip this
   // notification.
   if (mObservingVsync && !mDestroyed) {
     unused << SendNotify(aTimeStamp);
   }
 }
 
 bool
+VsyncParent::RecvRequestVsyncRate()
+{
+  AssertIsOnBackgroundThread();
+  TimeDuration vsyncRate = gfxPlatform::GetPlatform()->GetHardwareVsync()->GetGlobalDisplay().GetVsyncRate();
+  unused << SendVsyncRate(vsyncRate.ToMilliseconds());
+  return true;
+}
+
+bool
 VsyncParent::RecvObserve()
 {
   AssertIsOnBackgroundThread();
   if (!mObservingVsync) {
     mVsyncDispatcher->AddChildRefreshTimer(this);
     mObservingVsync = true;
     return true;
   }
--- a/layout/ipc/VsyncParent.h
+++ b/layout/ipc/VsyncParent.h
@@ -31,16 +31,17 @@ class VsyncParent final : public PVsyncP
 
 private:
   static already_AddRefed<VsyncParent> Create();
 
   VsyncParent();
   virtual ~VsyncParent();
 
   virtual bool NotifyVsync(TimeStamp aTimeStamp) override;
+  virtual bool RecvRequestVsyncRate() override;
 
   virtual bool RecvObserve() override;
   virtual bool RecvUnobserve() override;
   virtual void ActorDestroy(ActorDestroyReason aActorDestroyReason) override;
 
   void DispatchVsyncEvent(TimeStamp aTimeStamp);
 
   bool mObservingVsync;
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -4074,21 +4074,30 @@
   "FX_TAB_ANIM_ANY_FRAME_PAINT_MS": {
     "expires_in_version": "40",
     "kind": "exponential",
     "high": "500",
     "n_buckets": 30,
     "description": "Average paint duration during any tab open/close animation (excluding tabstrip scroll) *** No longer needed (bug 1156565). Delete histogram and accumulation code! ***"
   },
   "FX_REFRESH_DRIVER_CHROME_FRAME_DELAY_MS": {
-    "expires_in_version": "default",
-    "kind": "exponential",
-    "high": "10000",
-    "n_buckets": 50,
-    "description": "Delay in ms between the target and the actual handling time of the frame at refresh driver in chrome process."
+    "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "description": "Delay in ms between the target and the actual handling time of the frame at refresh driver in the chrome process."
+  },
+  "FX_REFRESH_DRIVER_CONTENT_FRAME_DELAY_MS": {
+    "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "description": "Delay in ms between the target and the actual handling time of the frame at refresh driver in the content process."
   },
   "FX_TAB_SWITCH_UPDATE_MS": {
     "alert_emails": ["perf-telemetry-alerts@mozilla.com"],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": "1000",
     "n_buckets": 20,
     "description": "Firefox: Time in ms spent updating UI in response to a tab switch"