Bug 1261373 - Record how long it takes for content response notifications to be delivered to APZ. r? draft
authorKartikaya Gupta <kgupta@mozilla.com>
Thu, 07 Apr 2016 13:15:24 -0400
changeset 348539 5bcae7b57667e390744e747186d34ab3022808dd
parent 348506 b6683e141c47c022598c0caac3ea8ba8c6236d42
child 517863 32aa393b633e666dfce549ed6242d26c9e60242f
push id14840
push userkgupta@mozilla.com
push dateThu, 07 Apr 2016 17:16:55 +0000
bugs1261373
milestone48.0a1
Bug 1261373 - Record how long it takes for content response notifications to be delivered to APZ. r? MozReview-Commit-ID: JMmK2Bpw86N
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 in milliseconds",
+    "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)"
   },