Bug 1713489 - Record telemetry for how long we spend waiting on the m…

…ain thread to process image preload network steps. r=bas,dragana,necko-reviewers Differential Revision: https://phabricator.services.mozilla.com/D116318
dothq · May 31, 2021 · c1f699c · c1f699c
1 parent ac6b41f
commit c1f699c
Show file tree

Hide file tree

Showing 10 changed files with 66 additions and 7 deletions.
diff --git a/dom/base/Document.cpp b/dom/base/Document.cpp
@@ -12020,6 +12020,7 @@ void Document::PreLoadImage(nsIURI* aUri, const nsAString& aCrossOriginAttr,
                             ReferrerPolicyEnum aReferrerPolicy, bool aIsImgSet,
                             bool aLinkPreload) {
   nsLoadFlags loadFlags = nsIRequest::LOAD_NORMAL |
+                          nsIRequest::LOAD_RECORD_START_REQUEST_DELAY |
                           nsContentUtils::CORSModeToLoadImageFlags(
                               Element::StringToCORSMode(aCrossOriginAttr));
 
@@ -12048,7 +12049,8 @@ void Document::PreLoadImage(nsIURI* aUri, const nsAString& aCrossOriginAttr,
 void Document::MaybePreLoadImage(nsIURI* aUri,
                                  const nsAString& aCrossOriginAttr,
                                  ReferrerPolicyEnum aReferrerPolicy,
-                                 bool aIsImgSet, bool aLinkPreload) {
+                                 bool aIsImgSet, bool aLinkPreload,
+                                 const TimeStamp& aInitTimestamp) {
   if (aLinkPreload) {
     // Check if the image was already preloaded in this document to avoid
     // duplicate preloading.
@@ -12069,6 +12071,13 @@ void Document::MaybePreLoadImage(nsIURI* aUri,
     return;
   }
 
+#ifdef NIGHTLY_BUILD
+  Telemetry::Accumulate(
+      Telemetry::DOCUMENT_PRELOAD_IMAGE_ASYNCOPEN_DELAY,
+      static_cast<uint32_t>(
+          (TimeStamp::Now() - aInitTimestamp).ToMilliseconds()));
+#endif
+
   // Image not in cache - trigger preload
   PreLoadImage(aUri, aCrossOriginAttr, aReferrerPolicy, aIsImgSet,
                aLinkPreload);

diff --git a/dom/base/Document.h b/dom/base/Document.h
@@ -2936,7 +2936,7 @@ class Document : public nsINode,
    */
   void MaybePreLoadImage(nsIURI* uri, const nsAString& aCrossOriginAttr,
                          ReferrerPolicyEnum aReferrerPolicy, bool aIsImgSet,
-                         bool aLinkPreload);
+                         bool aLinkPreload, const TimeStamp& aInitTimestamp);
   void PreLoadImage(nsIURI* uri, const nsAString& aCrossOriginAttr,
                     ReferrerPolicyEnum aReferrerPolicy, bool aIsImgSet,
                     bool aLinkPreload);

diff --git a/image/imgLoader.cpp b/image/imgLoader.cpp
@@ -2301,6 +2301,9 @@ nsresult imgLoader::LoadImage(
     // Propagate background loading...
     requestFlags |= nsIRequest::LOAD_BACKGROUND;
   }
+  if (aLoadFlags & nsIRequest::LOAD_RECORD_START_REQUEST_DELAY) {
+    requestFlags |= nsIRequest::LOAD_RECORD_START_REQUEST_DELAY;
+  }
 
   if (aLinkPreload) {
     // Set background loading if it is <link rel=preload>

diff --git a/netwerk/base/nsIRequest.idl b/netwerk/base/nsIRequest.idl
@@ -210,6 +210,15 @@ interface nsIRequest : nsISupports
      */
     const long LOAD_ANONYMOUS_ALLOW_CLIENT_CERT = 1 << 5;
 
+    /**
+     * Record HTTP_PRELOAD_IMAGE_STARTREQUEST_DELAY telemetry for the delay between
+     * sending OnStartRequest from the socket thread to it being processed by the
+     * main thread.
+     * This is temporary while we collect telemetry around the value of
+     * handling OnStartRequest off the main thread.
+     */
+    const long LOAD_RECORD_START_REQUEST_DELAY = 1 << 6;
+
     /**************************************************************************
      * The following flags control the flow of data into the cache.
      */

diff --git a/netwerk/protocol/http/HttpChannelChild.cpp b/netwerk/protocol/http/HttpChannelChild.cpp
@@ -362,9 +362,20 @@ void HttpChannelChild::ProcessOnStartRequest(
   LOG(("HttpChannelChild::ProcessOnStartRequest [this=%p]\n", this));
   MOZ_ASSERT(OnSocketThread());
 
+  TimeStamp start = TimeStamp::Now();
+
   mEventQ->RunOrEnqueue(new NeckoTargetChannelFunctionEvent(
       this, [self = UnsafePtr<HttpChannelChild>(this), aResponseHead,
-             aUseResponseHead, aRequestHeaders, aArgs]() {
+             aUseResponseHead, aRequestHeaders, aArgs, start]() {
+#ifdef NIGHTLY_BUILD
+        if (self->mLoadFlags & nsIRequest::LOAD_RECORD_START_REQUEST_DELAY) {
+          TimeDuration delay = TimeStamp::Now() - start;
+          Telemetry::Accumulate(
+              Telemetry::HTTP_PRELOAD_IMAGE_STARTREQUEST_DELAY,
+              static_cast<uint32_t>(delay.ToMilliseconds()));
+        }
+#endif
+
         self->OnStartRequest(aResponseHead, aUseResponseHead, aRequestHeaders,
                              aArgs);
       }));

diff --git a/parser/html/nsHtml5SpeculativeLoad.cpp b/parser/html/nsHtml5SpeculativeLoad.cpp
@@ -43,7 +43,7 @@ void nsHtml5SpeculativeLoad::Perform(nsHtml5TreeOpExecutor* aExecutor) {
       aExecutor->PreloadImage(
           mUrlOrSizes, mCrossOrigin, mMedia, mCharsetOrSrcset,
           mTypeOrCharsetSourceOrDocumentModeOrMetaCSPOrSizesOrIntegrity,
-          mReferrerPolicyOrIntegrity, mIsLinkPreload);
+          mReferrerPolicyOrIntegrity, mIsLinkPreload, mInitTimestamp);
       break;
     case eSpeculativeLoadOpenPicture:
       aExecutor->PreloadOpenPicture();

diff --git a/parser/html/nsHtml5SpeculativeLoad.h b/parser/html/nsHtml5SpeculativeLoad.h
@@ -93,6 +93,7 @@ class nsHtml5SpeculativeLoad {
     aSizes.ToString(
         mTypeOrCharsetSourceOrDocumentModeOrMetaCSPOrSizesOrIntegrity);
     mIsLinkPreload = aLinkPreload;
+    mInitTimestamp = mozilla::TimeStamp::Now();
   }
 
   inline void InitFont(nsHtml5String aUrl, nsHtml5String aCrossOrigin,
@@ -377,6 +378,8 @@ class nsHtml5SpeculativeLoad {
    * (REFERRER_POLICY_*) defined in nsIHttpChannel.
    */
   mozilla::dom::ReferrerPolicy mScriptReferrerPolicy;
+
+  mozilla::TimeStamp mInitTimestamp;
 };
 
 #endif  // nsHtml5SpeculativeLoad_h
diff --git a/parser/html/nsHtml5TreeOpExecutor.cpp b/parser/html/nsHtml5TreeOpExecutor.cpp
@@ -1194,7 +1194,8 @@ void nsHtml5TreeOpExecutor::PreloadStyle(const nsAString& aURL,
 void nsHtml5TreeOpExecutor::PreloadImage(
     const nsAString& aURL, const nsAString& aCrossOrigin,
     const nsAString& aMedia, const nsAString& aSrcset, const nsAString& aSizes,
-    const nsAString& aImageReferrerPolicy, bool aLinkPreload) {
+    const nsAString& aImageReferrerPolicy, bool aLinkPreload,
+    const TimeStamp& aInitTimestamp) {
   nsCOMPtr<nsIURI> baseURI = BaseURIForPreload();
   bool isImgSet = false;
   nsCOMPtr<nsIURI> uri =
@@ -1203,7 +1204,7 @@ void nsHtml5TreeOpExecutor::PreloadImage(
     // use document wide referrer policy
     mDocument->MaybePreLoadImage(uri, aCrossOrigin,
                                  GetPreloadReferrerPolicy(aImageReferrerPolicy),
-                                 isImgSet, aLinkPreload);
+                                 isImgSet, aLinkPreload, aInitTimestamp);
   }
 }
 

diff --git a/parser/html/nsHtml5TreeOpExecutor.h b/parser/html/nsHtml5TreeOpExecutor.h
@@ -244,7 +244,8 @@ class nsHtml5TreeOpExecutor final
   void PreloadImage(const nsAString& aURL, const nsAString& aCrossOrigin,
                     const nsAString& aMedia, const nsAString& aSrcset,
                     const nsAString& aSizes,
-                    const nsAString& aImageReferrerPolicy, bool aLinkPreload);
+                    const nsAString& aImageReferrerPolicy, bool aLinkPreload,
+                    const mozilla::TimeStamp& aInitTimestamp);
 
   void PreloadOpenPicture();
 

diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json
@@ -16656,6 +16656,28 @@
     "alert_emails": ["[email protected]", "[email protected]"],
     "description": "HTTP subitem channel: ODoH lookup time (ms)"
   },
+  "HTTP_PRELOAD_IMAGE_STARTREQUEST_DELAY": {
+    "record_in_processes": ["content"],
+    "products": ["firefox"],
+    "expires_in_version": "96",
+    "kind": "exponential",
+    "high": 5000,
+    "n_buckets": 50,
+    "bug_numbers": [1713489],
+    "alert_emails": ["[email protected]", "[email protected]"],
+    "description": "Time spent waiting on the main-thread to be available to process OnStartRequest, for image preload requests"
+  },
+  "DOCUMENT_PRELOAD_IMAGE_ASYNCOPEN_DELAY": {
+    "record_in_processes": ["content"],
+    "products": ["firefox"],
+    "expires_in_version": "96",
+    "kind": "exponential",
+    "high": 5000,
+    "n_buckets": 50,
+    "bug_numbers": [1713489],
+    "alert_emails": ["[email protected]", "[email protected]"],
+    "description": "Time spent waiting on the main-thread to be available to run AsyncOpen, for image preload requests"
+  },
   "OPAQUE_RESPONSE_BLOCKING_TIME_MS" : {
     "record_in_processes": ["main"],
     "products": ["firefox"],