Bug 1857615: Add Telemetry for OnStopRequest/OnDataFinished/etc r=nec…

…ko-reviewers,kershaw Also add OnStartRequest telemetry back Differential Revision: https://phabricator.services.mozilla.com/D190470
dothq · Oct 28, 2023 · 3c97fb9 · 3c97fb9
1 parent d1de97b
commit 3c97fb9
Show file tree

Hide file tree

Showing 4 changed files with 165 additions and 26 deletions.
diff --git a/netwerk/metrics.yaml b/netwerk/metrics.yaml
@@ -197,6 +197,86 @@ networking:
       - [email protected]
     expires: 130
 
+  http_content_ondatafinished_delay:
+    type: timing_distribution
+    time_unit: millisecond
+    description: >
+      The time between dispatching OnDataFinished from the socket thread and processing it.
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615#c
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - [email protected]
+      - [email protected]
+    expires: 130
+
+  http_content_ondatafinished_to_onstop_delay:
+    type: timing_distribution
+    time_unit: millisecond
+    description: >
+      The time between processing OnDataFinished and processing OnStopRequest (if OnDataFinished comes first)
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615#c
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - [email protected]
+      - [email protected]
+    expires: 130
+
+  http_content_ondatafinished_to_onstop_delay_negative:
+    type: timing_distribution
+    time_unit: millisecond
+    description: >
+      The time between processing OnStopRequest and processing OnDataFinished (if OnStopRequest comes first)
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857615#c
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - [email protected]
+      - [email protected]
+    expires: 130
+
+  http_content_html5parser_ondatafinished_to_onstop_delay:
+    type: timing_distribution
+    time_unit: millisecond
+    description: >
+      The time between processing OnDataFinished and processing OnStopRequest (if OnDataFinished comes first)
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857926
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857926
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - [email protected]
+      - [email protected]
+    expires: 130
+
+  http_content_html5parser_ondatafinished_to_onstop_delay_negative:
+    type: timing_distribution
+    time_unit: millisecond
+    description: >
+      The time between processing OnStopRequest and processing OnDataFinished (if OnStopRequest comes first)
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857926
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1857926
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - [email protected]
+      - [email protected]
+    expires: 130
+
   http_1_download_throughput:
     type: custom_distribution
     unit: mbps

diff --git a/netwerk/protocol/http/HttpChannelChild.cpp b/netwerk/protocol/http/HttpChannelChild.cpp
@@ -833,6 +833,10 @@ void HttpChannelChild::SendOnDataFinished(const nsresult& aChannelStatus) {
           ("HttpChannelChild::SendOnDataFinished sending data end "
            "notification[this=%p]\n",
            this));
+      // We want to calculate the delta time between this call and
+      // ProcessOnStopRequest.  Complicating things is that OnStopRequest
+      // could come first, and that it will run on a different thread, so
+      // we need to synchronize and lock data.
       omtEventListener->OnDataFinished(aChannelStatus);
     } else {
       LOG(
@@ -860,24 +864,56 @@ void HttpChannelChild::ProcessOnStopRequest(
     mTransferSize = aTiming.transferSize();
     mEncodedBodySize = aTiming.encodedBodySize();
   }
+
+  class RecordStopRequestDelta final {
+   public:
+    NS_INLINE_DECL_THREADSAFE_REFCOUNTING(RecordStopRequestDelta);
+
+    TimeStamp mOnStopRequestTime;
+    TimeStamp mOnDataFinishedTime;
+
+   private:
+    ~RecordStopRequestDelta() {
+      TimeDuration delta = (mOnStopRequestTime - mOnDataFinishedTime);
+      if (delta.ToMilliseconds() < 0) {
+        // Because Telemetry can't handle negatives
+        delta = -delta;
+        glean::networking::http_content_ondatafinished_to_onstop_delay_negative
+            .AccumulateRawDuration(delta);
+      } else {
+        glean::networking::http_content_ondatafinished_to_onstop_delay
+            .AccumulateRawDuration(delta);
+      }
+    }
+  };
+
+  RefPtr<RecordStopRequestDelta> timing(new RecordStopRequestDelta);
   TimeStamp start = TimeStamp::Now();
   if (StaticPrefs::network_send_OnDataFinished()) {
     mEventQ->RunOrEnqueue(new ChannelFunctionEvent(
         [self = UnsafePtr<HttpChannelChild>(this)]() {
           return self->GetODATarget();
         },
-        [self = UnsafePtr<HttpChannelChild>(this), status = aChannelStatus]() {
+        [self = UnsafePtr<HttpChannelChild>(this), status = aChannelStatus,
+         start, timing]() {
+          TimeStamp now = TimeStamp::Now();
+          TimeDuration delay = now - start;
+          glean::networking::http_content_ondatafinished_delay
+              .AccumulateRawDuration(delay);
+          timing->mOnDataFinishedTime = now;
           self->SendOnDataFinished(status);
         }));
   }
   mEventQ->RunOrEnqueue(new NeckoTargetChannelFunctionEvent(
       this, [self = UnsafePtr<HttpChannelChild>(this), aChannelStatus, aTiming,
              aResponseTrailers,
              consoleReports = CopyableTArray{aConsoleReports.Clone()},
-             aFromSocketProcess, start]() mutable {
-        TimeDuration delay = TimeStamp::Now() - start;
+             aFromSocketProcess, start, timing]() mutable {
+        TimeStamp now = TimeStamp::Now();
+        TimeDuration delay = now - start;
         glean::networking::http_content_onstop_delay.AccumulateRawDuration(
             delay);
+        timing->mOnStopRequestTime = now;
         self->OnStopRequest(aChannelStatus, aTiming, aResponseTrailers);
         if (!aFromSocketProcess) {
           self->DoOnConsoleReport(std::move(consoleReports));

diff --git a/parser/html/nsHtml5StreamParser.cpp b/parser/html/nsHtml5StreamParser.cpp
@@ -1395,34 +1395,50 @@ nsresult nsHtml5StreamParser::OnStopRequest(
     const mozilla::ReentrantMonitorAutoEnter& aProofOfLock) {
   MOZ_ASSERT_IF(aRequest, mRequest == aRequest);
   if (mOnStopCalled) {
-    return NS_OK;
-  }
+    if (mOnDataFinishedTime) {
+      mOnStopRequestTime = TimeStamp::Now();
+    } else {
+      mOnDataFinishedTime = TimeStamp::Now();
+    }
+  } else {
+    mOnStopCalled = true;
+
+    if (MOZ_UNLIKELY(NS_IsMainThread())) {
+      mOnStopRequestTime = TimeStamp::Now();
+      nsCOMPtr<nsIRunnable> stopper = new nsHtml5RequestStopper(this);
+      if (NS_FAILED(
+              mEventTarget->Dispatch(stopper, nsIThread::DISPATCH_NORMAL))) {
+        NS_WARNING("Dispatching StopRequest event failed.");
+      }
+    } else {
+      mOnDataFinishedTime = TimeStamp::Now();
 
-  mOnStopCalled = true;
+      if (StaticPrefs::network_send_OnDataFinished_html5parser()) {
+        MOZ_ASSERT(IsParserThread(), "Wrong thread!");
 
-  if (MOZ_UNLIKELY(NS_IsMainThread())) {
-    nsCOMPtr<nsIRunnable> stopper = new nsHtml5RequestStopper(this);
-    if (NS_FAILED(
-            mEventTarget->Dispatch(stopper, nsIThread::DISPATCH_NORMAL))) {
-      NS_WARNING("Dispatching StopRequest event failed.");
+        mozilla::MutexAutoLock autoLock(mTokenizerMutex);
+        DoStopRequest();
+        PostLoadFlusher();
+      } else {
+        // Let the MainThread event handle this, even though it will just
+        // send it back to this thread, so we can accurately judge the impact
+        // of this change.   This should eventually be removed
+      }
     }
-    return NS_OK;
   }
-
-  if (!StaticPrefs::network_send_OnDataFinished_html5parser()) {
-    // Let the MainThread event handle this, even though it will just
-    // send it back to this thread, so we can accurately judge the impact
-    // of this change. This should eventually be removed once the PoC is
-    // complete
-    mOnStopCalled = false;
-    return NS_OK;
+  if (!mOnStopRequestTime.IsNull() && !mOnDataFinishedTime.IsNull()) {
+    TimeDuration delta = (mOnStopRequestTime - mOnDataFinishedTime);
+    if (delta.ToMilliseconds() < 0) {
+      // Because Telemetry can't handle negatives
+      delta = -delta;
+      glean::networking::
+          http_content_html5parser_ondatafinished_to_onstop_delay_negative
+              .AccumulateRawDuration(delta);
+    } else {
+      glean::networking::http_content_html5parser_ondatafinished_to_onstop_delay
+          .AccumulateRawDuration(delta);
+    }
   }
-
-  MOZ_ASSERT(IsParserThread(), "Wrong thread!");
-
-  mozilla::MutexAutoLock autoLock(mTokenizerMutex);
-  DoStopRequest();
-  PostLoadFlusher();
   return NS_OK;
 }
 

diff --git a/parser/html/nsHtml5StreamParser.h b/parser/html/nsHtml5StreamParser.h
@@ -771,6 +771,13 @@ class nsHtml5StreamParser final : public nsISupports {
    * nsHtml5StreamListener::mDelegateMonitor passed in the OnStopRequest
    */
   bool mOnStopCalled{false};
+
+  /*
+   * Used for telemetry about OnStopRequest vs OnDataFinished
+   */
+  // guarded by nsHtml5StreamListener::mDelegateMonitor
+  mozilla::TimeStamp mOnStopRequestTime;
+  mozilla::TimeStamp mOnDataFinishedTime;
 };
 
 #endif  // nsHtml5StreamParser_h