Bug 1261373 - Record how long it takes for content response notifications to be delivered to APZ. r=botond f=bsmedberg
authorKartikaya Gupta <kgupta@mozilla.com>
Tue, 12 Apr 2016 16:17:20 -0400
changeset 292906 06616766e22e50155e23d99a5621911b8308b059
parent 292905 246b4f8d75bdb8dbf7856392f7716f2a7f0484d8
child 292907 8bce23713e8fe6b57af9f7f66f18a3aab2515d99
push id30170
push usercbook@mozilla.com
push dateWed, 13 Apr 2016 09:53:56 +0000
treeherdermozilla-central@564b225d5535 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersbotond
bugs1261373
milestone48.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 1261373 - Record how long it takes for content response notifications to be delivered to APZ. r=botond f=bsmedberg MozReview-Commit-ID: 74sGJ0JRLai
gfx/layers/apz/src/InputBlockState.cpp
gfx/layers/apz/src/InputBlockState.h
gfx/layers/apz/src/InputQueue.cpp
gfx/layers/apz/src/InputQueue.h
toolkit/components/telemetry/Histograms.json
--- a/gfx/layers/apz/src/InputBlockState.cpp
+++ b/gfx/layers/apz/src/InputBlockState.cpp
@@ -5,16 +5,17 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "InputBlockState.h"
 #include "AsyncPanZoomController.h"         // for AsyncPanZoomController
 #include "AsyncScrollBase.h"                // for kScrollSeriesTimeoutMs
 #include "gfxPrefs.h"                       // for gfxPrefs
 #include "mozilla/MouseEvents.h"
 #include "mozilla/SizePrintfMacros.h"       // for PRIuSIZE
+#include "mozilla/Telemetry.h"              // for Telemetry
 #include "mozilla/layers/APZCTreeManager.h" // for AllowedTouchBehavior
 #include "OverscrollHandoffState.h"
 
 #define TBS_LOG(...)
 // #define TBS_LOG(...) printf_stderr("TBS: " __VA_ARGS__)
 
 namespace mozilla {
 namespace layers {
@@ -148,16 +149,23 @@ CancelableBlockState::SetContentResponse
   }
   TBS_LOG("%p got content response %d with timer expired %d\n",
     this, aPreventDefault, mContentResponseTimerExpired);
   mPreventDefault = aPreventDefault;
   mContentResponded = true;
   return true;
 }
 
+void
+CancelableBlockState::StartContentResponseTimer()
+{
+  MOZ_ASSERT(mContentResponseTimer.IsNull());
+  mContentResponseTimer = TimeStamp::Now();
+}
+
 bool
 CancelableBlockState::TimeoutContentResponse()
 {
   if (mContentResponseTimerExpired) {
     return false;
   }
   TBS_LOG("%p got content timer expired with response received %d\n",
     this, mContentResponded);
@@ -177,16 +185,22 @@ CancelableBlockState::IsContentResponseT
 bool
 CancelableBlockState::IsDefaultPrevented() const
 {
   MOZ_ASSERT(mContentResponded || mContentResponseTimerExpired);
   return mPreventDefault;
 }
 
 bool
+CancelableBlockState::HasReceivedAllContentNotifications() const
+{
+  return IsTargetConfirmed() && mContentResponded;
+}
+
+bool
 CancelableBlockState::IsReadyForHandling() const
 {
   if (!IsTargetConfirmed()) {
     return false;
   }
   return mContentResponded || mContentResponseTimerExpired;
 }
 
@@ -199,16 +213,36 @@ CancelableBlockState::DispatchImmediate(
 }
 
 void
 CancelableBlockState::DispatchEvent(const InputData& aEvent) const
 {
   GetTargetApzc()->HandleInputEvent(aEvent, mTransformToApzc);
 }
 
+void
+CancelableBlockState::RecordContentResponseTime()
+{
+  if (!mContentResponseTimer) {
+    // We might get responses from content even though we didn't wait for them.
+    // In that case, ignore the time on them, because they're not relevant for
+    // tuning our timeout value. Also this function might get called multiple
+    // times on the same input block, so we should only record the time from the
+    // first successful call.
+    return;
+  }
+  if (!HasReceivedAllContentNotifications()) {
+    // Not done yet, we'll get called again
+    return;
+  }
+  mozilla::Telemetry::Accumulate(mozilla::Telemetry::CONTENT_RESPONSE_DURATION,
+    (uint32_t)(TimeStamp::Now() - mContentResponseTimer).ToMilliseconds());
+  mContentResponseTimer = TimeStamp();
+}
+
 DragBlockState::DragBlockState(const RefPtr<AsyncPanZoomController>& aTargetApzc,
                                bool aTargetConfirmed,
                                const MouseInput& aInitialEvent)
   : CancelableBlockState(aTargetApzc, aTargetConfirmed)
   , mReceivedMouseUp(false)
 {
 }
 
@@ -381,25 +415,16 @@ WheelBlockState::Update(ScrollWheelInput
 
 void
 WheelBlockState::AddEvent(const ScrollWheelInput& aEvent)
 {
   mEvents.AppendElement(aEvent);
 }
 
 bool
-WheelBlockState::IsReadyForHandling() const
-{
-  if (!CancelableBlockState::IsReadyForHandling()) {
-    return false;
-  }
-  return true;
-}
-
-bool
 WheelBlockState::HasEvents() const
 {
   return !mEvents.IsEmpty();
 }
 
 void
 WheelBlockState::DropEvents()
 {
@@ -650,16 +675,23 @@ PanGestureBlockState::SetContentResponse
   if (mWaitingForContentResponse) {
     mWaitingForContentResponse = false;
     stateChanged = true;
   }
   return stateChanged;
 }
 
 bool
+PanGestureBlockState::HasReceivedAllContentNotifications() const
+{
+  return CancelableBlockState::HasReceivedAllContentNotifications()
+      && !mWaitingForContentResponse;
+}
+
+bool
 PanGestureBlockState::IsReadyForHandling() const
 {
   if (!CancelableBlockState::IsReadyForHandling()) {
     return false;
   }
   return !mWaitingForContentResponse ||
          IsContentResponseTimerExpired();
 }
@@ -717,16 +749,23 @@ TouchBlockState::CopyPropertiesFrom(cons
   if (gfxPrefs::TouchActionEnabled()) {
     MOZ_ASSERT(aOther.mAllowedTouchBehaviorSet || aOther.IsContentResponseTimerExpired());
     SetAllowedTouchBehaviors(aOther.mAllowedTouchBehaviors);
   }
   mTransformToApzc = aOther.mTransformToApzc;
 }
 
 bool
+TouchBlockState::HasReceivedAllContentNotifications() const
+{
+  return CancelableBlockState::HasReceivedAllContentNotifications()
+      && (!gfxPrefs::TouchActionEnabled() || mAllowedTouchBehaviorSet);
+}
+
+bool
 TouchBlockState::IsReadyForHandling() const
 {
   if (!CancelableBlockState::IsReadyForHandling()) {
     return false;
   }
 
   if (!gfxPrefs::TouchActionEnabled()) {
     return true;
--- a/gfx/layers/apz/src/InputBlockState.h
+++ b/gfx/layers/apz/src/InputBlockState.h
@@ -6,16 +6,17 @@
 
 #ifndef mozilla_layers_InputBlockState_h
 #define mozilla_layers_InputBlockState_h
 
 #include "InputData.h"                      // for MultiTouchInput
 #include "mozilla/gfx/Matrix.h"             // for Matrix4x4
 #include "mozilla/layers/APZUtils.h"        // for TouchBehaviorFlags
 #include "mozilla/layers/AsyncDragMetrics.h"
+#include "mozilla/TimeStamp.h"              // for TimeStamp
 #include "nsAutoPtr.h"                      // for nsRefPtr
 #include "nsTArray.h"                       // for nsTArray
 #include "TouchCounter.h"
 
 namespace mozilla {
 namespace layers {
 
 class AsyncPanZoomController;
@@ -117,16 +118,30 @@ public:
    * Record whether or not content cancelled this block of events.
    * @param aPreventDefault true iff the block is cancelled.
    * @return false if this block has already received a response from
    *         web content, true if not.
    */
   virtual bool SetContentResponse(bool aPreventDefault);
 
   /**
+   * This should be called when this block is starting to wait for the
+   * necessary content response notifications. It is used to gather data
+   * on how long the content response notifications take.
+   */
+  void StartContentResponseTimer();
+
+  /**
+   * This should be called when a content response notification has been
+   * delivered to this block. If all the notifications have arrived, this
+   * will report the total time take to telemetry.
+   */
+  void RecordContentResponseTime();
+
+  /**
    * Record that content didn't respond in time.
    * @return false if this block already timed out, true if not.
    */
   bool TimeoutContentResponse();
 
   /**
    * Checks if the content response timer has already expired.
    */
@@ -146,16 +161,22 @@ public:
 
   /**
    * Dispatch the event to the target APZC. Mostly this is a hook for
    * subclasses to do any per-event processing they need to.
    */
   virtual void DispatchEvent(const InputData& aEvent) const;
 
   /**
+   * @return true iff this block has received all the information it could
+   *         have gotten from the content thread.
+   */
+  virtual bool HasReceivedAllContentNotifications() const;
+
+  /**
    * @return true iff this block has received all the information needed
    *         to properly dispatch the events in the block.
    */
   virtual bool IsReadyForHandling() const;
 
   /**
    * Returns whether or not this block has pending events.
    */
@@ -179,33 +200,33 @@ public:
   virtual bool MustStayActive() = 0;
 
   /**
    * Return a descriptive name for the block kind.
    */
   virtual const char* Type() = 0;
 
 private:
+  TimeStamp mContentResponseTimer;
   bool mPreventDefault;
   bool mContentResponded;
   bool mContentResponseTimerExpired;
 };
 
 /**
  * A single block of wheel events.
  */
 class WheelBlockState : public CancelableBlockState
 {
 public:
   WheelBlockState(const RefPtr<AsyncPanZoomController>& aTargetApzc,
                   bool aTargetConfirmed,
                   const ScrollWheelInput& aEvent);
 
   bool SetContentResponse(bool aPreventDefault) override;
-  bool IsReadyForHandling() const override;
   bool HasEvents() const override;
   void DropEvents() override;
   void HandleEvents() override;
   bool MustStayActive() override;
   const char* Type() override;
   bool SetConfirmedTargetApzc(const RefPtr<AsyncPanZoomController>& aTargetApzc) override;
 
   void AddEvent(const ScrollWheelInput& aEvent);
@@ -315,16 +336,17 @@ private:
 class PanGestureBlockState : public CancelableBlockState
 {
 public:
   PanGestureBlockState(const RefPtr<AsyncPanZoomController>& aTargetApzc,
                        bool aTargetConfirmed,
                        const PanGestureInput& aEvent);
 
   bool SetContentResponse(bool aPreventDefault) override;
+  bool HasReceivedAllContentNotifications() const override;
   bool IsReadyForHandling() const override;
   bool HasEvents() const override;
   void DropEvents() override;
   void HandleEvents() override;
   bool MustStayActive() override;
   const char* Type() override;
   bool SetConfirmedTargetApzc(const RefPtr<AsyncPanZoomController>& aTargetApzc) override;
 
@@ -393,16 +415,22 @@ public:
    */
   bool GetAllowedTouchBehaviors(nsTArray<TouchBehaviorFlags>& aOutBehaviors) const;
 
   /**
    * Copy various properties from another block.
    */
   void CopyPropertiesFrom(const TouchBlockState& aOther);
 
+  /*
+   * @return true iff this block has received all the information it could
+   *         have gotten from the content thread.
+   */
+  bool HasReceivedAllContentNotifications() const override;
+
   /**
    * @return true iff this block has received all the information needed
    *         to properly dispatch the events in the block.
    */
   bool IsReadyForHandling() const override;
 
   /**
    * Sets a flag that indicates this input block occurred while the APZ was
--- a/gfx/layers/apz/src/InputQueue.cpp
+++ b/gfx/layers/apz/src/InputQueue.cpp
@@ -421,29 +421,29 @@ InputQueue::MaybeRequestContentResponse(
     // block.
     waitForMainThread = true;
   }
   if (waitForMainThread) {
     // We either don't know for sure if aTarget is the right APZC, or we may
     // need to wait to give content the opportunity to prevent-default the
     // touch events. Either way we schedule a timeout so the main thread stuff
     // can run.
-    ScheduleMainThreadTimeout(aTarget, aBlock->GetBlockId());
+    ScheduleMainThreadTimeout(aTarget, aBlock);
   }
 }
 
 uint64_t
 InputQueue::InjectNewTouchBlock(AsyncPanZoomController* aTarget)
 {
   TouchBlockState* block = StartNewTouchBlock(aTarget,
     /* aTargetConfirmed = */ true,
     /* aCopyPropertiesFromCurrent = */ true);
   INPQ_LOG("injecting new touch block %p with id %" PRIu64 " and target %p\n",
     block, block->GetBlockId(), aTarget);
-  ScheduleMainThreadTimeout(aTarget, block->GetBlockId());
+  ScheduleMainThreadTimeout(aTarget, block);
   return block->GetBlockId();
 }
 
 void
 InputQueue::SweepDepletedBlocks()
 {
   // We're going to start a new block, so clear out any depleted blocks at the head of the queue.
   // See corresponding comment in ProcessInputBlocks.
@@ -560,20 +560,22 @@ InputQueue::IsDragOnScrollbar(bool aHitS
   // Now that we know we are in a drag, get the info from the drag tracker.
   // We keep it in the tracker rather than the block because the block can get
   // interrupted by something else (like a wheel event) and then a new block
   // will get created without the info we want. The tracker will persist though.
   return mDragTracker.IsOnScrollbar(aHitScrollbar);
 }
 
 void
-InputQueue::ScheduleMainThreadTimeout(const RefPtr<AsyncPanZoomController>& aTarget, uint64_t aInputBlockId) {
+InputQueue::ScheduleMainThreadTimeout(const RefPtr<AsyncPanZoomController>& aTarget,
+                                      CancelableBlockState* aBlock) {
   INPQ_LOG("scheduling main thread timeout for target %p\n", aTarget.get());
+  aBlock->StartContentResponseTimer();
   aTarget->PostDelayedTask(
-    NewRunnableMethod(this, &InputQueue::MainThreadTimeout, aInputBlockId),
+    NewRunnableMethod(this, &InputQueue::MainThreadTimeout, aBlock->GetBlockId()),
     gfxPrefs::APZContentResponseTimeout());
 }
 
 void
 InputQueue::MainThreadTimeout(const uint64_t& aInputBlockId) {
   APZThreadUtils::AssertOnControllerThread();
 
   INPQ_LOG("got a main thread timeout; block=%" PRIu64 "\n", aInputBlockId);
@@ -595,37 +597,40 @@ InputQueue::MainThreadTimeout(const uint
 
 void
 InputQueue::ContentReceivedInputBlock(uint64_t aInputBlockId, bool aPreventDefault) {
   APZThreadUtils::AssertOnControllerThread();
 
   INPQ_LOG("got a content response; block=%" PRIu64 "\n", aInputBlockId);
   bool success = false;
   for (size_t i = 0; i < mInputBlockQueue.Length(); i++) {
-    if (mInputBlockQueue[i]->GetBlockId() == aInputBlockId) {
-      CancelableBlockState* block = mInputBlockQueue[i].get();
+    CancelableBlockState* block = mInputBlockQueue[i].get();
+    if (block->GetBlockId() == aInputBlockId) {
       success = block->SetContentResponse(aPreventDefault);
+      block->RecordContentResponseTime();
       break;
     }
   }
   if (success) {
     ProcessInputBlocks();
   }
 }
 
 void
 InputQueue::SetConfirmedTargetApzc(uint64_t aInputBlockId, const RefPtr<AsyncPanZoomController>& aTargetApzc) {
   APZThreadUtils::AssertOnControllerThread();
 
   INPQ_LOG("got a target apzc; block=%" PRIu64 " guid=%s\n",
     aInputBlockId, aTargetApzc ? Stringify(aTargetApzc->GetGuid()).c_str() : "");
   bool success = false;
   for (size_t i = 0; i < mInputBlockQueue.Length(); i++) {
-    if (mInputBlockQueue[i]->GetBlockId() == aInputBlockId) {
-      success = mInputBlockQueue[i]->SetConfirmedTargetApzc(aTargetApzc);
+    CancelableBlockState* block = mInputBlockQueue[i].get();
+    if (block->GetBlockId() == aInputBlockId) {
+      success = block->SetConfirmedTargetApzc(aTargetApzc);
+      block->RecordContentResponseTime();
       break;
     }
   }
   if (success) {
     ProcessInputBlocks();
   }
 }
 
@@ -638,16 +643,17 @@ InputQueue::ConfirmDragBlock(uint64_t aI
   INPQ_LOG("got a target apzc; block=%" PRIu64 " guid=%s\n",
     aInputBlockId, aTargetApzc ? Stringify(aTargetApzc->GetGuid()).c_str() : "");
   bool success = false;
   for (size_t i = 0; i < mInputBlockQueue.Length(); i++) {
     DragBlockState* block = mInputBlockQueue[i]->AsDragBlock();
     if (block && block->GetBlockId() == aInputBlockId) {
       block->SetDragMetrics(aDragMetrics);
       success = block->SetConfirmedTargetApzc(aTargetApzc);
+      block->RecordContentResponseTime();
       break;
     }
   }
   if (success) {
     ProcessInputBlocks();
   }
 }
 
@@ -657,16 +663,17 @@ InputQueue::SetAllowedTouchBehavior(uint
 
   INPQ_LOG("got allowed touch behaviours; block=%" PRIu64 "\n", aInputBlockId);
   bool success = false;
   for (size_t i = 0; i < mInputBlockQueue.Length(); i++) {
     if (mInputBlockQueue[i]->GetBlockId() == aInputBlockId) {
       TouchBlockState *block = mInputBlockQueue[i]->AsTouchBlock();
       if (block) {
         success = block->SetAllowedTouchBehaviors(aBehaviors);
+        block->RecordContentResponseTime();
       } else {
         NS_WARNING("input block is not a touch block");
       }
       break;
     }
   }
   if (success) {
     ProcessInputBlocks();
--- a/gfx/layers/apz/src/InputQueue.h
+++ b/gfx/layers/apz/src/InputQueue.h
@@ -170,17 +170,18 @@ private:
 
   /**
    * Processes the current block if it's ready for handling, using the block's
    * target APZC.
    */
   bool MaybeHandleCurrentBlock(CancelableBlockState* block,
                                const InputData& aEvent);
 
-  void ScheduleMainThreadTimeout(const RefPtr<AsyncPanZoomController>& aTarget, uint64_t aInputBlockId);
+  void ScheduleMainThreadTimeout(const RefPtr<AsyncPanZoomController>& aTarget,
+                                 CancelableBlockState* aBlock);
   void MainThreadTimeout(const uint64_t& aInputBlockId);
   void ProcessInputBlocks();
   void UpdateActiveApzc(const RefPtr<AsyncPanZoomController>& aNewActive);
 
 private:
   // The queue of input blocks that have not yet been fully processed.
   // This member must only be accessed on the controller/UI thread.
   nsTArray<UniquePtr<CancelableBlockState>> mInputBlockQueue;
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -141,16 +141,25 @@
   },
   "COMPOSITE_FRAME_ROUNDTRIP_TIME" : {
     "expires_in_version": "never",
     "description": "Time from vsync to finishing a composite in milliseconds.",
     "kind": "exponential",
     "high": 1000,
     "n_buckets": 50
   },
+  "CONTENT_RESPONSE_DURATION" : {
+    "alert_emails": ["kgupta@mozilla.com"],
+    "bug_numbers": [1261373],
+    "expires_in_version": "55",
+    "description": "Main thread response times for APZ notifications about input events (ms)",
+    "kind" : "exponential",
+    "high": 60000,
+    "n_buckets": 50
+  },
   "CYCLE_COLLECTOR": {
     "alert_emails": ["dev-telemetry-gc-alerts@mozilla.org"],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": 10000,
     "n_buckets": 50,
     "description": "Time spent on one cycle collection (ms)"
   },