Bug 1221674 - Add telemetry probe in the content process to measure the time between refresh driver ticks. r=kats
authorMason Chang <mchang@mozilla.com>
Fri, 06 Nov 2015 08:20:58 -0800
changeset 271543 43305927701d23fa5eb5f950fb520f3c16f0bf4d
parent 271542 771ace622de13963fa5f348d74cd9f2cedeea1f0
child 271544 8d20513ae79ed8bf3366536f318935bdab1ed9f2
push id67684
push usermchang@mozilla.com
push dateFri, 06 Nov 2015 16:21:11 +0000
treeherdermozilla-inbound@43305927701d [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerskats
bugs1221674
milestone45.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1221674 - Add telemetry probe in the content process to measure the time between refresh driver ticks. r=kats
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
@@ -2659,16 +2659,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);
@@ -2696,16 +2719,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) {
@@ -2821,16 +2849,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,32 +350,57 @@ 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;
+        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);
@@ -380,16 +408,18 @@ private:
     }
 
     // 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 +443,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
@@ -4085,17 +4085,24 @@
     "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."
+    "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": {
+    "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 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"