Bug 1411632 - Introduce onload and DOMContentLoaded telemetry for active tab and network optimization. r=valentin, r=francois

This commit is contained in:
Honza Bambas 2017-12-02 18:13:43 -05:00
Родитель a55e238edf
Коммит 4eab23cce4
13 изменённых файлов: 229 добавлений и 9 удалений

Просмотреть файл

@ -10,6 +10,7 @@
#include "nsCOMPtr.h"
#include "nsContentUtils.h"
#include "nsDocShell.h"
#include "nsHttp.h"
#include "nsIDocShellTreeItem.h"
#include "nsIScriptSecurityManager.h"
#include "prtime.h"
@ -119,8 +120,23 @@ nsDOMNavigationTiming::NotifyLoadEventStart()
PROFILER_TRACING("Navigation", "Load", TRACING_INTERVAL_START);
if (IsTopLevelContentDocumentInContentProcess()) {
TimeStamp now = TimeStamp::Now();
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_LOAD_EVENT_START_MS,
mNavigationStart);
mNavigationStart,
now);
if (mDocShellHasBeenActiveSinceNavigationStart) {
if (net::nsHttp::IsBeforeLastActiveTabLoadOptimization(mNavigationStart)) {
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_LOAD_EVENT_START_ACTIVE_NETOPT_MS,
mNavigationStart,
now);
} else {
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_LOAD_EVENT_START_ACTIVE_MS,
mNavigationStart,
now);
}
}
}
}
@ -199,8 +215,23 @@ nsDOMNavigationTiming::NotifyDOMContentLoadedStart(nsIURI* aURI)
PROFILER_TRACING("Navigation", "DOMContentLoaded", TRACING_INTERVAL_START);
if (IsTopLevelContentDocumentInContentProcess()) {
TimeStamp now = TimeStamp::Now();
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_CONTENT_LOADED_START_MS,
mNavigationStart);
mNavigationStart,
now);
if (mDocShellHasBeenActiveSinceNavigationStart) {
if (net::nsHttp::IsBeforeLastActiveTabLoadOptimization(mNavigationStart)) {
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_CONTENT_LOADED_START_ACTIVE_NETOPT_MS,
mNavigationStart,
now);
} else {
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_DOM_CONTENT_LOADED_START_ACTIVE_MS,
mNavigationStart,
now);
}
}
}
}
@ -249,6 +280,16 @@ nsDOMNavigationTiming::NotifyNonBlankPaintForRootContentDocument()
#endif
if (mDocShellHasBeenActiveSinceNavigationStart) {
if (net::nsHttp::IsBeforeLastActiveTabLoadOptimization(mNavigationStart)) {
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_NON_BLANK_PAINT_NETOPT_MS,
mNavigationStart,
mNonBlankPaint);
} else {
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_NON_BLANK_PAINT_NO_NETOPT_MS,
mNavigationStart,
mNonBlankPaint);
}
Telemetry::AccumulateTimeDelta(Telemetry::TIME_TO_NON_BLANK_PAINT_MS,
mNavigationStart,
mNonBlankPaint);

Просмотреть файл

@ -1279,6 +1279,8 @@ Http2Stream::UpdatePriorityDependency()
" depends on background group for trans %p\n",
this, trans));
mPriorityDependency = Http2Session::kBackgroundGroupID;
nsHttp::NotifyActiveTabLoadOptimization();
}
LOG3(("Http2Stream::UpdatePriorityDependency %p "
@ -1311,6 +1313,8 @@ Http2Stream::TopLevelOuterContentWindowIdChanged(uint64_t windowId)
mPriorityDependency = Http2Session::kBackgroundGroupID;
LOG3(("Http2Stream::TopLevelOuterContentWindowIdChanged %p "
"move into background group.\n", this));
nsHttp::NotifyActiveTabLoadOptimization();
} else {
nsHttpTransaction *trans = mTransaction->QueryHttpTransaction();
if (!trans) {

Просмотреть файл

@ -180,11 +180,17 @@ HttpBackgroundChannelChild::RecvOnTransportAndData(
IPCResult
HttpBackgroundChannelChild::RecvOnStopRequest(
const nsresult& aChannelStatus,
const ResourceTimingStruct& aTiming)
const ResourceTimingStruct& aTiming,
const TimeStamp& aLastActiveTabOptHit)
{
LOG(("HttpBackgroundChannelChild::RecvOnStopRequest [this=%p]\n", this));
MOZ_ASSERT(OnSocketThread());
// It's enough to set this from (just before) OnStopRequest notification, since
// we don't need this value sooner than a channel was done loading - everything
// this timestamp affects takes place only after a channel's OnStopRequest.
nsHttp::SetLastActiveTabLoadOptimizationHit(aLastActiveTabOptHit);
if (NS_WARN_IF(!mChannelChild)) {
return IPC_OK();
}
@ -194,12 +200,13 @@ HttpBackgroundChannelChild::RecvOnStopRequest(
static_cast<uint32_t>(aChannelStatus)));
mQueuedRunnables.AppendElement(
NewRunnableMethod<const nsresult, const ResourceTimingStruct>(
NewRunnableMethod<const nsresult, const ResourceTimingStruct, const TimeStamp>(
"HttpBackgroundChannelChild::RecvOnStopRequest",
this,
&HttpBackgroundChannelChild::RecvOnStopRequest,
aChannelStatus,
aTiming));
aTiming,
aLastActiveTabOptHit));
return IPC_OK();
}

Просмотреть файл

@ -48,7 +48,8 @@ protected:
const nsCString& aData) override;
IPCResult RecvOnStopRequest(const nsresult& aChannelStatus,
const ResourceTimingStruct& aTiming) override;
const ResourceTimingStruct& aTiming,
const TimeStamp& aLastActiveTabOptHit) override;
IPCResult RecvOnProgress(const int64_t& aProgress,
const int64_t& aProgressMax) override;

Просмотреть файл

@ -246,7 +246,10 @@ HttpBackgroundChannelParent::OnStopRequest(const nsresult& aChannelStatus,
return NS_SUCCEEDED(rv);
}
return SendOnStopRequest(aChannelStatus, aTiming);
// See the child code for why we do this.
TimeStamp lastActTabOpt = nsHttp::GetLastActiveTabLoadOptimizationHit();
return SendOnStopRequest(aChannelStatus, aTiming, lastActTabOpt);
}
bool

Просмотреть файл

@ -36,7 +36,8 @@ child:
uint32_t count,
nsCString data);
async OnStopRequest(nsresult channelStatus, ResourceTimingStruct timing);
async OnStopRequest(nsresult channelStatus, ResourceTimingStruct timing,
TimeStamp lastActiveTabOptimization);
async OnProgress(int64_t progress, int64_t progressMax);

Просмотреть файл

@ -15,6 +15,7 @@
#include "nsCRT.h"
#include "nsHttpRequestHead.h"
#include "nsHttpResponseHead.h"
#include "nsHttpHandler.h"
#include "nsICacheEntry.h"
#include "nsIRequest.h"
#include <errno.h>
@ -540,6 +541,33 @@ DetermineFramingAndImmutability(nsICacheEntry *entry,
*isImmutable = !*weaklyFramed && isHttps && responseHead->Immutable();
}
bool
IsBeforeLastActiveTabLoadOptimization(TimeStamp const & when)
{
return gHttpHandler && gHttpHandler->IsBeforeLastActiveTabLoadOptimization(when);
}
void
NotifyActiveTabLoadOptimization()
{
if (gHttpHandler) {
gHttpHandler->NotifyActiveTabLoadOptimization();
}
}
TimeStamp const GetLastActiveTabLoadOptimizationHit()
{
return gHttpHandler ? gHttpHandler->GetLastActiveTabLoadOptimizationHit() : TimeStamp();
}
void
SetLastActiveTabLoadOptimizationHit(TimeStamp const &when)
{
if (gHttpHandler) {
gHttpHandler->SetLastActiveTabLoadOptimizationHit(when);
}
}
} // namespace nsHttp

Просмотреть файл

@ -13,6 +13,7 @@
#include "nsString.h"
#include "nsError.h"
#include "nsTArray.h"
#include "mozilla/TimeStamp.h"
#include "mozilla/UniquePtr.h"
// http version codes
@ -216,6 +217,14 @@ namespace nsHttp
bool isHttps, bool *weaklyFramed,
bool *isImmutable);
// Called when an optimization feature affecting active vs background tab load
// took place. Called only on the parent process and only updates
// mLastActiveTabLoadOptimizationHit timestamp to now.
void NotifyActiveTabLoadOptimization();
TimeStamp const GetLastActiveTabLoadOptimizationHit();
void SetLastActiveTabLoadOptimizationHit(TimeStamp const &when);
bool IsBeforeLastActiveTabLoadOptimization(TimeStamp const &when);
// Declare all atoms
//
// The atom names and values are stored in nsHttpAtomList.h and are brought
@ -299,7 +308,6 @@ private:
nsCString mFull;
};
} // namespace net
} // namespace mozilla

Просмотреть файл

@ -5193,6 +5193,12 @@ nsConnectionEntry::AppendPendingQForNonFocusedWindows(
it.UserData()->RemoveElementsAt(0, count);
if (maxCount && totalCount == maxCount) {
if (it.UserData()->Length()) {
// There are still some pending transactions for background
// tabs but we limit their dispatch. This is considered as
// an active tab optimization.
nsHttp::NotifyActiveTabLoadOptimization();
}
break;
}
}

Просмотреть файл

@ -282,6 +282,7 @@ nsHttpHandler::nsHttpHandler()
, mActiveTabPriority(true)
, mProcessId(0)
, mNextChannelId(1)
, mLastActiveTabLoadOptimizationLock("nsHttpConnectionMgr::LastActiveTabLoadOptimization")
{
LOG(("Creating nsHttpHandler [this=%p].\n", this));
@ -2670,5 +2671,38 @@ nsHttpHandler::NewChannelId(uint64_t& channelId)
return NS_OK;
}
void
nsHttpHandler::NotifyActiveTabLoadOptimization()
{
SetLastActiveTabLoadOptimizationHit(TimeStamp::Now());
}
TimeStamp const nsHttpHandler::GetLastActiveTabLoadOptimizationHit()
{
MutexAutoLock lock(mLastActiveTabLoadOptimizationLock);
return mLastActiveTabLoadOptimizationHit;
}
void
nsHttpHandler::SetLastActiveTabLoadOptimizationHit(TimeStamp const &when)
{
MutexAutoLock lock(mLastActiveTabLoadOptimizationLock);
if (mLastActiveTabLoadOptimizationHit.IsNull() ||
(!when.IsNull() && mLastActiveTabLoadOptimizationHit < when)) {
mLastActiveTabLoadOptimizationHit = when;
}
}
bool
nsHttpHandler::IsBeforeLastActiveTabLoadOptimization(TimeStamp const &when)
{
MutexAutoLock lock(mLastActiveTabLoadOptimizationLock);
return !mLastActiveTabLoadOptimizationHit.IsNull() &&
when <= mLastActiveTabLoadOptimizationHit;
}
} // namespace net
} // namespace mozilla

Просмотреть файл

@ -11,7 +11,9 @@
#include "nsHttpConnectionMgr.h"
#include "ASpdySession.h"
#include "mozilla/Mutex.h"
#include "mozilla/StaticPtr.h"
#include "mozilla/TimeStamp.h"
#include "nsString.h"
#include "nsCOMPtr.h"
#include "nsWeakReference.h"
@ -403,6 +405,14 @@ public:
return mActiveTabPriority;
}
// Called when an optimization feature affecting active vs background tab load
// took place. Called only on the parent process and only updates
// mLastActiveTabLoadOptimizationHit timestamp to now.
void NotifyActiveTabLoadOptimization();
TimeStamp const GetLastActiveTabLoadOptimizationHit();
void SetLastActiveTabLoadOptimizationHit(TimeStamp const &when);
bool IsBeforeLastActiveTabLoadOptimization(TimeStamp const &when);
private:
nsHttpHandler();
@ -689,6 +699,18 @@ private:
uint32_t mProcessId;
uint32_t mNextChannelId;
// The last time any of the active tab page load optimization took place.
// This is accessed on multiple threads, hence a lock is needed.
// On the parent process this is updated to now every time a scheduling
// or rate optimization related to the active/background tab is hit.
// We carry this value through each http channel's onstoprequest notification
// to the parent process. On the content process then we just update this
// value from ipc onstoprequest arguments. This is a sufficent way of passing
// it down to the content process, since the value will be used only after
// onstoprequest notification coming from an http channel.
Mutex mLastActiveTabLoadOptimizationLock;
TimeStamp mLastActiveTabLoadOptimizationHit;
public:
MOZ_MUST_USE nsresult NewChannelId(uint64_t& channelId);
};

Просмотреть файл

@ -910,6 +910,11 @@ nsHttpTransaction::WriteSegments(nsAHttpSegmentWriter *writer,
}
if (ShouldStopReading()) {
if (gHttpHandler->ConnMgr()->CurrentTopLevelOuterContentWindowId() !=
mTopLevelOuterContentWindowId) {
nsHttp::NotifyActiveTabLoadOptimization();
}
// Must remember that we have to call ResumeRecv() on our connection when
// called back by the conn manager to resume reading.
LOG(("nsHttpTransaction::WriteSegments %p response throttled", this));

Просмотреть файл

@ -13160,6 +13160,26 @@
"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."
},
"TIME_TO_NON_BLANK_PAINT_NETOPT_MS": {
"record_in_processes": ["main", "content"],
"alert_emails": ["necko@mozilla.com", "hbambas@mozilla.com"],
"expires_in_version": "63",
"kind": "exponential",
"high": 100000,
"n_buckets": 100,
"bug_numbers": [1411632],
"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. This probe only accumulates when there were active-tab network load optimizations happening during the interval."
},
"TIME_TO_NON_BLANK_PAINT_NO_NETOPT_MS": {
"record_in_processes": ["main", "content"],
"alert_emails": ["necko@mozilla.com", "hbambas@mozilla.com"],
"expires_in_version": "63",
"kind": "exponential",
"high": 100000,
"n_buckets": 100,
"bug_numbers": [1411632],
"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. This probe only accumulates when there were no active-tab network load optimizations happening during the interval."
},
"TAB_AUDIO_INDICATOR_USED": {
"record_in_processes": ["main", "content"],
"alert_emails": ["alwu@mozilla.com"],
@ -13380,6 +13400,26 @@
"bug_numbers": [1344893],
"description": "Time in milliseconds from navigationStart to domContentLoadedEventStart."
},
"TIME_TO_DOM_CONTENT_LOADED_START_ACTIVE_NETOPT_MS": {
"record_in_processes": ["content"],
"alert_emails": ["necko@mozilla.com", "hbambas@mozilla.com"],
"expires_in_version": "63",
"kind": "exponential",
"high": 50000,
"n_buckets": 100,
"bug_numbers": [1411632],
"description": "Time in milliseconds from navigationStart to domContentLoadedEventStart for all-the-time active page for which some of the network loading optimization happened."
},
"TIME_TO_DOM_CONTENT_LOADED_START_ACTIVE_MS": {
"record_in_processes": ["content"],
"alert_emails": ["necko@mozilla.com", "hbambas@mozilla.com"],
"expires_in_version": "63",
"kind": "exponential",
"high": 50000,
"n_buckets": 100,
"bug_numbers": [1411632],
"description": "Time in milliseconds from navigationStart to domContentLoadedEventStart for all-the-time active page for which none of the network loading optimization happened."
},
"TIME_TO_DOM_CONTENT_LOADED_END_MS": {
"record_in_processes": ["content"],
"alert_emails": ["wpan@mozilla.com"],
@ -13410,6 +13450,26 @@
"bug_numbers": [1344893],
"description": "Time in milliseconds from navigationStart to loadEventStart."
},
"TIME_TO_LOAD_EVENT_START_ACTIVE_NETOPT_MS": {
"record_in_processes": ["content"],
"alert_emails": ["necko@mozilla.com", "hbambas@mozilla.com"],
"expires_in_version": "63",
"kind": "exponential",
"high": 50000,
"n_buckets": 100,
"bug_numbers": [1411632],
"description": "Time in milliseconds from navigationStart to loadEventStart for all-the-time active page for which some of the network loading optimization happened."
},
"TIME_TO_LOAD_EVENT_START_ACTIVE_MS": {
"record_in_processes": ["content"],
"alert_emails": ["necko@mozilla.com", "hbambas@mozilla.com"],
"expires_in_version": "63",
"kind": "exponential",
"high": 50000,
"n_buckets": 100,
"bug_numbers": [1411632],
"description": "Time in milliseconds from navigationStart to loadEventStart for all-the-time active page for which none of the network loading optimization happened."
},
"TIME_TO_LOAD_EVENT_END_MS": {
"record_in_processes": ["content"],
"alert_emails": ["wpan@mozilla.com"],