Bug 1307242 - Add a non-blank paint telemetry probe for foreground root content documents. r?bkelly, f?bsmedberg draft
authorMarkus Stange <mstange@themasta.com>
Thu, 10 Nov 2016 14:26:54 -0500
changeset 437393 66be2aab4c4a32d20fb44c88c5270c5b5cfc0b81
parent 437392 db3eb7cfa534b2b7312047871d4ae4fb97061b03
child 437553 d884f2766379dfc3e2d4152f75c61b4bbc40fd72
push id35401
push userbmo:mstange@themasta.com
push dateThu, 10 Nov 2016 21:03:18 +0000
reviewersbkelly
bugs1307242
milestone52.0a1
Bug 1307242 - Add a non-blank paint telemetry probe for foreground root content documents. r?bkelly, f?bsmedberg This adds a probe called TIME_TO_NON_BLANK_PAINT_MS which reports time to non-blank paint for documents which are the root content document, and whose docshell was active for the entire time between navigation start and non-blank paint. MozReview-Commit-ID: 7JQdk5vHr1O
docshell/base/nsDocShell.cpp
dom/base/nsDOMNavigationTiming.cpp
dom/base/nsDOMNavigationTiming.h
image/SVGDocumentWrapper.cpp
layout/base/nsPresContext.cpp
toolkit/components/telemetry/Histograms.json
--- a/docshell/base/nsDocShell.cpp
+++ b/docshell/base/nsDocShell.cpp
@@ -1723,17 +1723,19 @@ nsDocShell::MaybeInitTiming()
       mBlankTiming = false;
     }
   }
 
   if (!mTiming) {
     mTiming = new nsDOMNavigationTiming();
   }
 
-  mTiming->NotifyNavigationStart();
+  mTiming->NotifyNavigationStart(
+    mIsActive ? nsDOMNavigationTiming::DocShellState::eActive
+              : nsDOMNavigationTiming::DocShellState::eInactive);
 }
 
 //
 // Bug 13871: Prevent frameset spoofing
 //
 // This routine answers: 'Is origin's document from same domain as
 // target's document?'
 //
@@ -6175,16 +6177,30 @@ nsDocShell::SetIsActive(bool aIsActive)
           ScreenOrientation::UpdateActiveOrientationLock(orientation);
         }
       }
 
       doc->PostVisibilityUpdateEvent();
     }
   }
 
+  // Tell the nsDOMNavigationTiming about it
+  RefPtr<nsDOMNavigationTiming> timing = mTiming;
+  if (!timing && mContentViewer) {
+    nsIDocument* doc = mContentViewer->GetDocument();
+    if (doc) {
+      timing = doc->GetNavigationTiming();
+    }
+  }
+  if (timing) {
+    timing->NotifyDocShellStateChanged(
+      aIsActive ? nsDOMNavigationTiming::DocShellState::eActive
+                : nsDOMNavigationTiming::DocShellState::eInactive);
+  }
+
   // Recursively tell all of our children, but don't tell <iframe mozbrowser>
   // children; they handle their state separately.
   nsTObserverArray<nsDocLoader*>::ForwardIterator iter(mChildList);
   while (iter.HasMore()) {
     nsCOMPtr<nsIDocShell> docshell = do_QueryObject(iter.GetNext());
     if (!docshell) {
       continue;
     }
--- a/dom/base/nsDOMNavigationTiming.cpp
+++ b/dom/base/nsDOMNavigationTiming.cpp
@@ -43,16 +43,17 @@ nsDOMNavigationTiming::Clear()
 
   mLoadEventStartSet = false;
   mLoadEventEndSet = false;
   mDOMLoadingSet = false;
   mDOMInteractiveSet = false;
   mDOMContentLoadedEventStartSet = false;
   mDOMContentLoadedEventEndSet = false;
   mDOMCompleteSet = false;
+  mDocShellHasBeenActiveSinceNavigationStart = false;
 }
 
 DOMTimeMilliSec
 nsDOMNavigationTiming::TimeStampToDOM(mozilla::TimeStamp aStamp) const
 {
   if (aStamp.IsNull()) {
     return 0;
   }
@@ -61,20 +62,21 @@ nsDOMNavigationTiming::TimeStampToDOM(mo
 }
 
 DOMTimeMilliSec nsDOMNavigationTiming::DurationFromStart()
 {
   return TimeStampToDOM(mozilla::TimeStamp::Now());
 }
 
 void
-nsDOMNavigationTiming::NotifyNavigationStart()
+nsDOMNavigationTiming::NotifyNavigationStart(DocShellState aDocShellState)
 {
   mNavigationStartHighRes = (double)PR_Now() / PR_USEC_PER_MSEC;
   mNavigationStartTimeStamp = mozilla::TimeStamp::Now();
+  mDocShellHasBeenActiveSinceNavigationStart = (aDocShellState == DocShellState::eActive);
 }
 
 void
 nsDOMNavigationTiming::NotifyFetchStart(nsIURI* aURI, Type aNavigationType)
 {
   mNavigationType = aNavigationType;
   // At the unload event time we don't really know the loading uri.
   // Need it for later check for unload timing access.
@@ -180,37 +182,51 @@ nsDOMNavigationTiming::NotifyDOMContentL
   if (!mDOMContentLoadedEventEndSet) {
     mLoadedURI = aURI;
     mDOMContentLoadedEventEnd = DurationFromStart();
     mDOMContentLoadedEventEndSet = true;
   }
 }
 
 void
-nsDOMNavigationTiming::NotifyNonBlankPaint()
+nsDOMNavigationTiming::NotifyNonBlankPaintForRootContentDocument()
 {
   MOZ_ASSERT(NS_IsMainThread());
   MOZ_ASSERT(!mNavigationStartTimeStamp.IsNull());
 
   if (!mNonBlankPaintTimeStamp.IsNull()) {
     return;
   }
 
   mNonBlankPaintTimeStamp = TimeStamp::Now();
   TimeDuration elapsed = mNonBlankPaintTimeStamp - mNavigationStartTimeStamp;
 
   if (profiler_is_active()) {
     nsAutoCString spec;
     if (mLoadedURI) {
       mLoadedURI->GetSpec(spec);
     }
-    nsPrintfCString marker("Non-blank paint after %dms for URL %s",
-                           int(elapsed.ToMilliseconds()), spec.get());
+    nsPrintfCString marker("Non-blank paint after %dms for URL %s, %s",
+                           int(elapsed.ToMilliseconds()), spec.get(),
+                           mDocShellHasBeenActiveSinceNavigationStart ? "foreground tab" : "this tab was inactive some of the time between navigation start and first non-blank paint");
     PROFILER_MARKER(marker.get());
   }
+
+  if (mDocShellHasBeenActiveSinceNavigationStart) {
+    Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_NON_BLANK_PAINT_MS,
+                                   mNavigationStartTimeStamp,
+                                   mNonBlankPaintTimeStamp);
+  }
+}
+
+void
+nsDOMNavigationTiming::NotifyDocShellStateChanged(DocShellState aDocShellState)
+{
+  mDocShellHasBeenActiveSinceNavigationStart &=
+    (aDocShellState == DocShellState::eActive);
 }
 
 DOMTimeMilliSec
 nsDOMNavigationTiming::GetUnloadEventStart()
 {
   nsIScriptSecurityManager* ssm = nsContentUtils::GetSecurityManager();
   nsresult rv = ssm->CheckSameOriginURI(mLoadedURI, mUnloadedURI, false);
   if (NS_SUCCEEDED(rv)) {
--- a/dom/base/nsDOMNavigationTiming.h
+++ b/dom/base/nsDOMNavigationTiming.h
@@ -76,34 +76,40 @@ public:
   {
     return mLoadEventStart;
   }
   DOMTimeMilliSec GetLoadEventEnd() const
   {
     return mLoadEventEnd;
   }
 
-  void NotifyNavigationStart();
+  enum class DocShellState : uint8_t {
+    eActive,
+    eInactive
+  };
+
+  void NotifyNavigationStart(DocShellState aDocShellState);
   void NotifyFetchStart(nsIURI* aURI, Type aNavigationType);
   void NotifyBeforeUnload();
   void NotifyUnloadAccepted(nsIURI* aOldURI);
   void NotifyUnloadEventStart();
   void NotifyUnloadEventEnd();
   void NotifyLoadEventStart();
   void NotifyLoadEventEnd();
 
   // Document changes state to 'loading' before connecting to timing
   void SetDOMLoadingTimeStamp(nsIURI* aURI, mozilla::TimeStamp aValue);
   void NotifyDOMLoading(nsIURI* aURI);
   void NotifyDOMInteractive(nsIURI* aURI);
   void NotifyDOMComplete(nsIURI* aURI);
   void NotifyDOMContentLoadedStart(nsIURI* aURI);
   void NotifyDOMContentLoadedEnd(nsIURI* aURI);
 
-  void NotifyNonBlankPaint();
+  void NotifyNonBlankPaintForRootContentDocument();
+  void NotifyDocShellStateChanged(DocShellState aDocShellState);
 
   DOMTimeMilliSec TimeStampToDOM(mozilla::TimeStamp aStamp) const;
 
   inline DOMHighResTimeStamp TimeStampToDOMHighRes(mozilla::TimeStamp aStamp)
   {
     mozilla::TimeDuration duration = aStamp - mNavigationStartTimeStamp;
     return duration.ToMilliseconds();
   }
@@ -140,11 +146,12 @@ private:
   // once.
   bool mLoadEventStartSet : 1;
   bool mLoadEventEndSet : 1;
   bool mDOMLoadingSet : 1;
   bool mDOMInteractiveSet : 1;
   bool mDOMContentLoadedEventStartSet : 1;
   bool mDOMContentLoadedEventEndSet : 1;
   bool mDOMCompleteSet : 1;
+  bool mDocShellHasBeenActiveSinceNavigationStart : 1;
 };
 
 #endif /* nsDOMNavigationTiming_h___ */
--- a/image/SVGDocumentWrapper.cpp
+++ b/image/SVGDocumentWrapper.cpp
@@ -357,17 +357,17 @@ SVGDocumentWrapper::SetupViewer(nsIReque
   // document needs this navigation timing object for time computation, such
   // as to calculate current time stamp based on the start time of navigation
   // time object.
   //
   // For a root document, DocShell would do these sort of things
   // automatically. Since there is no DocShell for this wrapped SVG document,
   // we must set it up manually.
   RefPtr<nsDOMNavigationTiming> timing = new nsDOMNavigationTiming();
-  timing->NotifyNavigationStart();
+  timing->NotifyNavigationStart(nsDOMNavigationTiming::DocShellState::eInactive);
   viewer->SetNavigationTiming(timing);
 
   nsCOMPtr<nsIParser> parser = do_QueryInterface(listener);
   NS_ENSURE_TRUE(parser, NS_ERROR_UNEXPECTED);
 
   // XML-only, because this is for SVG content
   nsCOMPtr<nsIContentSink> sink = parser->GetContentSink();
   NS_ENSURE_TRUE(sink, NS_ERROR_UNEXPECTED);
--- a/layout/base/nsPresContext.cpp
+++ b/layout/base/nsPresContext.cpp
@@ -2752,19 +2752,21 @@ nsPresContext::IsRootContentDocument() c
   return (f && f->PresContext()->IsChrome());
 }
 
 void
 nsPresContext::NotifyNonBlankPaint()
 {
   MOZ_ASSERT(!mHadNonBlankPaint);
   mHadNonBlankPaint = true;
-  RefPtr<nsDOMNavigationTiming> timing = mDocument->GetNavigationTiming();
-  if (timing) {
-    timing->NotifyNonBlankPaint();
+  if (IsRootContentDocument()) {
+    RefPtr<nsDOMNavigationTiming> timing = mDocument->GetNavigationTiming();
+    if (timing) {
+      timing->NotifyNonBlankPaintForRootContentDocument();
+    }
   }
 }
 
 bool nsPresContext::GetPaintFlashing() const
 {
   if (!mPaintFlashingInitialized) {
     bool pref = Preferences::GetBool("nglayout.debug.paint_flashing");
     if (!pref && IsChrome()) {
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -10484,10 +10484,19 @@
     "alert_emails": ["mconley@mozilla.com"],
     "bug_numbers": [1313686],
     "expires_in_version": "56",
     "kind": "exponential",
     "high": 1000,
     "n_buckets": 50,
     "description": "Time spent painting the contents of a remote browser (ms).",
     "releaseChannelCollection": "opt-out"
+  },
+  "TIME_TO_NON_BLANK_PAINT_MS": {
+    "alert_emails": ["hkirschner@mozilla.com"],
+    "expires_in_version": "55",
+    "kind": "exponential",
+    "high": 100000,
+    "n_buckets": 100,
+    "bug_numbers": [1307242],
+    "description": "The time between navigation start and the first non-blank paint of a foreground root content document, in milliseconds. This only records documents that were in an active docshell throughout the whole time between navigation start and non-blank paint. The non-blank paint timestamp is taken during display list building and does not include rasterization or compositing of that paint."
   }
 }