Bug 1387625 - Fix TIME_TO_DOM_LOADING_MS record timing. r?smaug draft
authorWei-Cheng Pan <wpan@mozilla.com>
Wed, 23 Aug 2017 11:09:24 +0800
changeset 652783 ae111583481ede0a6abd50f50c8f5b8df1ae926d
parent 652622 2306e153fba9ca55726ffcce889eaca7a479c29f
child 728178 17392b26b0bb9eff993286fff0a55bbd6f9b1719
push id76150
push userbmo:wpan@mozilla.com
push dateFri, 25 Aug 2017 07:34:35 +0000
reviewerssmaug
bugs1387625
milestone57.0a1
Bug 1387625 - Fix TIME_TO_DOM_LOADING_MS record timing. r?smaug nsDocument::mTiming can be nullptr when the document is still loading, so we should not record ready state probes in nsDOMNavigationTiming. Also stops recording probes from parent process because we only need data from real web contents. MozReview-Commit-ID: 8XUHC8yKobO
docshell/base/nsDocShell.cpp
docshell/base/nsDocShell.h
dom/base/nsDOMNavigationTiming.cpp
dom/base/nsDOMNavigationTiming.h
dom/base/nsDocument.cpp
dom/base/nsDocument.h
toolkit/components/telemetry/Histograms.json
--- a/docshell/base/nsDocShell.cpp
+++ b/docshell/base/nsDocShell.cpp
@@ -1832,16 +1832,22 @@ nsDocShell::MaybeInitTiming()
 void
 nsDocShell::MaybeResetInitTiming(bool aReset)
 {
   if (aReset) {
     mTiming = nullptr;
   }
 }
 
+nsDOMNavigationTiming*
+nsDocShell::GetNavigationTiming() const
+{
+  return mTiming;
+}
+
 //
 // Bug 13871: Prevent frameset spoofing
 //
 // This routine answers: 'Is origin's document from same domain as
 // target's document?'
 //
 // file: uris are considered the same domain for the purpose of
 // frame navigation regardless of script accessibility (bug 420425)
--- a/docshell/base/nsDocShell.h
+++ b/docshell/base/nsDocShell.h
@@ -283,16 +283,18 @@ public:
   }
   bool InFrameSwap();
 
   const Encoding* GetForcedCharset() { return mForcedCharset; }
 
   mozilla::HTMLEditor* GetHTMLEditorInternal();
   nsresult SetHTMLEditorInternal(mozilla::HTMLEditor* aHTMLEditor);
 
+  nsDOMNavigationTiming* GetNavigationTiming() const;
+
 private:
   bool CanSetOriginAttributes();
 
 public:
   const mozilla::OriginAttributes&
   GetOriginAttributes()
   {
     return mOriginAttributes;
--- a/dom/base/nsDOMNavigationTiming.cpp
+++ b/dom/base/nsDOMNavigationTiming.cpp
@@ -123,33 +123,33 @@ void
 nsDOMNavigationTiming::NotifyLoadEventStart()
 {
   if (!mLoadEventStartSet) {
     mLoadEventStart = DurationFromStart();
     mLoadEventStartSet = true;
 
     profiler_tracing("Navigation", "Load", TRACING_INTERVAL_START);
 
-    if (IsTopLevelContentDocument()) {
+    if (IsTopLevelContentDocumentInContentProcess()) {
       Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_LOAD_EVENT_START_MS,
                                      mNavigationStartTimeStamp);
     }
   }
 }
 
 void
 nsDOMNavigationTiming::NotifyLoadEventEnd()
 {
   if (!mLoadEventEndSet) {
     mLoadEventEnd = DurationFromStart();
     mLoadEventEndSet = true;
 
     profiler_tracing("Navigation", "Load", TRACING_INTERVAL_END);
 
-    if (IsTopLevelContentDocument()) {
+    if (IsTopLevelContentDocumentInContentProcess()) {
       Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_LOAD_EVENT_END_MS,
                                      mNavigationStartTimeStamp);
     }
   }
 }
 
 void
 nsDOMNavigationTiming::SetDOMLoadingTimeStamp(nsIURI* aURI, TimeStamp aValue)
@@ -165,86 +165,71 @@ void
 nsDOMNavigationTiming::NotifyDOMLoading(nsIURI* aURI)
 {
   if (!mDOMLoadingSet) {
     mLoadedURI = aURI;
     mDOMLoading = DurationFromStart();
     mDOMLoadingSet = true;
 
     profiler_add_marker("Navigation::DOMLoading");
-
-    if (IsTopLevelContentDocument()) {
-      Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_LOADING_MS,
-                                     mNavigationStartTimeStamp);
-    }
   }
 }
 
 void
 nsDOMNavigationTiming::NotifyDOMInteractive(nsIURI* aURI)
 {
   if (!mDOMInteractiveSet) {
     mLoadedURI = aURI;
     mDOMInteractive = DurationFromStart();
     mDOMInteractiveSet = true;
 
     profiler_add_marker("Navigation::DOMInteractive");
-
-    if (IsTopLevelContentDocument()) {
-      Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_INTERACTIVE_MS,
-                                     mNavigationStartTimeStamp);
-    }
   }
 }
 
 void
 nsDOMNavigationTiming::NotifyDOMComplete(nsIURI* aURI)
 {
   if (!mDOMCompleteSet) {
     mLoadedURI = aURI;
     mDOMComplete = DurationFromStart();
     mDOMCompleteSet = true;
 
     profiler_add_marker("Navigation::DOMComplete");
-
-    if (IsTopLevelContentDocument()) {
-      Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_COMPLETE_MS,
-                                     mNavigationStartTimeStamp);
-    }
   }
 }
 
 void
 nsDOMNavigationTiming::NotifyDOMContentLoadedStart(nsIURI* aURI)
 {
   if (!mDOMContentLoadedEventStartSet) {
     mLoadedURI = aURI;
     mDOMContentLoadedEventStart = DurationFromStart();
     mDOMContentLoadedEventStartSet = true;
 
     profiler_tracing("Navigation", "DOMContentLoaded", TRACING_INTERVAL_START);
 
-    if (IsTopLevelContentDocument()) {
+    if (IsTopLevelContentDocumentInContentProcess()) {
       Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_CONTENT_LOADED_START_MS,
                                      mNavigationStartTimeStamp);
     }
   }
 }
 
 void
 nsDOMNavigationTiming::NotifyDOMContentLoadedEnd(nsIURI* aURI)
 {
   if (!mDOMContentLoadedEventEndSet) {
     mLoadedURI = aURI;
     mDOMContentLoadedEventEnd = DurationFromStart();
     mDOMContentLoadedEventEndSet = true;
 
     profiler_tracing("Navigation", "DOMContentLoaded", TRACING_INTERVAL_END);
 
-    if (IsTopLevelContentDocument()) {
+    if (IsTopLevelContentDocumentInContentProcess()) {
       Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_CONTENT_LOADED_END_MS,
                                      mNavigationStartTimeStamp);
     }
   }
 }
 
 void
 nsDOMNavigationTiming::NotifyNonBlankPaintForRootContentDocument()
@@ -302,20 +287,23 @@ nsDOMNavigationTiming::GetUnloadEventEnd
   nsresult rv = ssm->CheckSameOriginURI(mLoadedURI, mUnloadedURI, false);
   if (NS_SUCCEEDED(rv)) {
     return mUnloadEnd;
   }
   return 0;
 }
 
 bool
-nsDOMNavigationTiming::IsTopLevelContentDocument() const
+nsDOMNavigationTiming::IsTopLevelContentDocumentInContentProcess() const
 {
   if (!mDocShell) {
     return false;
   }
+  if (!XRE_IsContentProcess()) {
+    return false;
+  }
   nsCOMPtr<nsIDocShellTreeItem> rootItem;
   Unused << mDocShell->GetSameTypeRootTreeItem(getter_AddRefs(rootItem));
   if (rootItem.get() != static_cast<nsIDocShellTreeItem*>(mDocShell.get())) {
     return false;
   }
   return rootItem->ItemType() == nsIDocShellTreeItem::typeContent;
 }
--- a/dom/base/nsDOMNavigationTiming.h
+++ b/dom/base/nsDOMNavigationTiming.h
@@ -121,17 +121,17 @@ public:
   }
 
 private:
   nsDOMNavigationTiming(const nsDOMNavigationTiming &) = delete;
   ~nsDOMNavigationTiming();
 
   void Clear();
 
-  bool IsTopLevelContentDocument() const;
+  bool IsTopLevelContentDocumentInContentProcess() const;
 
   mozilla::WeakPtr<nsDocShell> mDocShell;
 
   nsCOMPtr<nsIURI> mUnloadedURI;
   nsCOMPtr<nsIURI> mLoadedURI;
 
   Type mNavigationType;
   DOMHighResTimeStamp mNavigationStartHighRes;
--- a/dom/base/nsDocument.cpp
+++ b/dom/base/nsDocument.cpp
@@ -1556,16 +1556,19 @@ nsDocument::nsDocument(const char* aCont
   , mScaleStrEmpty(false)
   , mWidthStrEmpty(false)
   , mStackRefCnt(0)
   , mNeedsReleaseAfterStackRefCntRelease(false)
   , mMaybeServiceWorkerControlled(false)
 #ifdef DEBUG
   , mWillReparent(false)
 #endif
+  , mDOMLoadingSet(false)
+  , mDOMInteractiveSet(false)
+  , mDOMCompleteSet(false)
 {
   SetContentTypeInternal(nsDependentCString(aContentType));
 
   MOZ_LOG(gDocumentLeakPRLog, LogLevel::Debug, ("DOCUMENT %p created", this));
 
   // Start out mLastStyleSheetSet as null, per spec
   SetDOMStringToNull(mLastStyleSheetSet);
 
@@ -9639,16 +9642,18 @@ nsDocument::SetReadyStateInternal(ReadyS
         break;
     }
   }
   // At the time of loading start, we don't have timing object, record time.
   if (READYSTATE_LOADING == rs) {
     mLoadingTimeStamp = mozilla::TimeStamp::Now();
   }
 
+  RecordNavigationTiming(rs);
+
   RefPtr<AsyncEventDispatcher> asyncDispatcher =
     new AsyncEventDispatcher(this, NS_LITERAL_STRING("readystatechange"),
                              false, false);
   asyncDispatcher->RunDOMEventWhenSafe();
 }
 
 NS_IMETHODIMP
 nsDocument::GetReadyState(nsAString& aReadyState)
@@ -13820,8 +13825,58 @@ nsIDocument::GetSelection(ErrorResult& a
 
   NS_ASSERTION(window->IsInnerWindow(), "Should have inner window here!");
   if (!window->IsCurrentInnerWindow()) {
     return nullptr;
   }
 
   return nsGlobalWindow::Cast(window)->GetSelection(aRv);
 }
+
+void
+nsDocument::RecordNavigationTiming(ReadyState aReadyState)
+{
+  if (!XRE_IsContentProcess()) {
+    return;
+  }
+  if (!IsTopLevelContentDocument()) {
+    return;
+  }
+  // If we dont have the timing yet (mostly because the doc is still loading),
+  // get it from docshell.
+  RefPtr<nsDOMNavigationTiming> timing = mTiming;
+  if (!timing) {
+    if (!mDocumentContainer) {
+      return;
+    }
+    timing = mDocumentContainer->GetNavigationTiming();
+    if (!timing) {
+      return;
+    }
+  }
+  TimeStamp startTime = timing->GetNavigationStartTimeStamp();
+  switch (aReadyState) {
+    case READYSTATE_LOADING:
+      if (!mDOMLoadingSet) {
+        Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_LOADING_MS,
+                                       startTime);
+        mDOMLoadingSet = true;
+      }
+      break;
+    case READYSTATE_INTERACTIVE:
+      if (!mDOMInteractiveSet) {
+        Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_INTERACTIVE_MS,
+                                       startTime);
+        mDOMInteractiveSet = true;
+      }
+      break;
+    case READYSTATE_COMPLETE:
+      if (!mDOMCompleteSet) {
+        Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_COMPLETE_MS,
+                                       startTime);
+        mDOMCompleteSet = true;
+      }
+      break;
+    default:
+      NS_WARNING("Unexpected ReadyState value");
+      break;
+  }
+}
--- a/dom/base/nsDocument.h
+++ b/dom/base/nsDocument.h
@@ -1425,16 +1425,22 @@ private:
   // with mapped attributes in Servo mode. This list contains all elements which
   // need lazy resolution
   nsTHashtable<nsPtrHashKey<nsSVGElement>> mLazySVGPresElements;
 
 #ifdef DEBUG
 public:
   bool mWillReparent;
 #endif
+
+private:
+  void RecordNavigationTiming(ReadyState aReadyState);
+  bool mDOMLoadingSet : 1;
+  bool mDOMInteractiveSet : 1;
+  bool mDOMCompleteSet : 1;
 };
 
 class nsDocumentOnStack
 {
 public:
   explicit nsDocumentOnStack(nsDocument* aDoc) : mDoc(aDoc)
   {
     mDoc->IncreaseStackRefCnt();
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -13099,77 +13099,77 @@
     "expires_in_version": "61",
     "kind": "exponential",
     "low": 1,
     "high": 1000,
     "n_buckets": 10,
     "description": "Time in ms used to execute callbacks from setTimeout/setInterval, when the script belongs to a tab in the background and the script is on the tracking list. Multiple events are aggregated over a 1s interval."
   },
   "TIME_TO_DOM_LOADING_MS": {
-    "record_in_processes": ["main", "content"],
+    "record_in_processes": ["content"],
     "alert_emails": ["wpan@mozilla.com"],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 50000,
     "n_buckets": 100,
     "bug_numbers": [1344893],
     "description": "Time in milliseconds from navigationStart to domLoading."
   },
   "TIME_TO_DOM_INTERACTIVE_MS": {
-    "record_in_processes": ["main", "content"],
+    "record_in_processes": ["content"],
     "alert_emails": ["wpan@mozilla.com"],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 50000,
     "n_buckets": 100,
     "bug_numbers": [1344893],
     "description": "Time in milliseconds from navigationStart to domInteractive."
   },
   "TIME_TO_DOM_CONTENT_LOADED_START_MS": {
-    "record_in_processes": ["main", "content"],
+    "record_in_processes": ["content"],
     "alert_emails": ["wpan@mozilla.com"],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 50000,
     "n_buckets": 100,
     "bug_numbers": [1344893],
     "description": "Time in milliseconds from navigationStart to domContentLoadedEventStart."
   },
   "TIME_TO_DOM_CONTENT_LOADED_END_MS": {
-    "record_in_processes": ["main", "content"],
+    "record_in_processes": ["content"],
     "alert_emails": ["wpan@mozilla.com"],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 50000,
     "n_buckets": 100,
     "bug_numbers": [1344893],
     "description": "Time in milliseconds from navigationStart to domContentLoadedEventEnd."
   },
   "TIME_TO_DOM_COMPLETE_MS": {
-    "record_in_processes": ["main", "content"],
+    "record_in_processes": ["content"],
     "alert_emails": ["wpan@mozilla.com"],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 50000,
     "n_buckets": 100,
     "bug_numbers": [1344893],
     "description": "Time in milliseconds from navigationStart to domComplete."
   },
   "TIME_TO_LOAD_EVENT_START_MS": {
-    "record_in_processes": ["main", "content"],
+    "record_in_processes": ["content"],
     "alert_emails": ["wpan@mozilla.com"],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 50000,
     "n_buckets": 100,
     "bug_numbers": [1344893],
     "description": "Time in milliseconds from navigationStart to loadEventStart."
   },
   "TIME_TO_LOAD_EVENT_END_MS": {
-    "record_in_processes": ["main", "content"],
+    "record_in_processes": ["content"],
     "alert_emails": ["wpan@mozilla.com"],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 50000,
     "n_buckets": 100,
     "bug_numbers": [1344893],
     "description": "Time in milliseconds from navigationStart to loadEventEnd."
   },