Magic-Mirror/gecko-dev
1
0
Fork 0
mirror of https://github.com/mozilla/gecko-dev.git synced 2024-11-30 00:01:50 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Bug 658894 - Collect basic telemetry for HTTP requests and page load, r=jduell+tglek

Browse Source
This commit is contained in:
Honza Bambas 2011-06-28 16:49:45 +02:00
parent d4d2ac2788
commit 1b92ab5f6e
4 changed files with 283 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

16
docshell/base/nsDocShell.cpp
View File

@ -104,11 +104,13 @@
#include "nsIViewManager.h"
#include "nsIScriptChannel.h"
#include "nsIOfflineCacheUpdate.h"
#include "nsITimedChannel.h"
#include "nsCPrefetchService.h"
#include "nsJSON.h"
#include "IHistory.h"
#include "mozilla/Services.h"
#include "mozilla/Preferences.h"
#include "mozilla/Telemetry.h"
// we want to explore making the document own the load group
// so we can associate the document URI with the load group.
@ -6116,6 +6118,20 @@ nsDocShell::EndPageLoad(nsIWebProgress * aProgress,
nsresult rv = aChannel->GetURI(getter_AddRefs(url));
if (NS_FAILED(rv)) return rv;
nsCOMPtr<nsITimedChannel> timingChannel =
do_QueryInterface(aChannel);
if (timingChannel) {
TimeStamp channelCreationTime;
rv = timingChannel->GetChannelCreation(&channelCreationTime);
if (NS_SUCCEEDED(rv) && !channelCreationTime.IsNull()) {
PRUint32 interval = (PRUint32)
(TimeStamp::Now() - channelCreationTime)
.ToMilliseconds();
Telemetry::Accumulate(Telemetry::TOTAL_CONTENT_PAGE_LOAD_TIME,
interval);
}
}
// Timing is picked up by the window, we don't need it anymore
mTiming = nsnull;

222
netwerk/base/src/nsLoadGroup.cpp
View File

@ -50,6 +50,9 @@
#include "nsReadableUtils.h"
#include "nsString.h"
#include "nsTArray.h"
#include "mozilla/Telemetry.h"
using namespace mozilla;
#if defined(PR_LOGGING)
//
@ -68,6 +71,9 @@ static PRLogModuleInfo* gLoadGroupLog = nsnull;
#define LOG(args) PR_LOG(gLoadGroupLog, PR_LOG_DEBUG, args)
#define HISTOGRAM_TIME_DELTA(start, end) \
(PRUint32)((end - start).ToMilliseconds())
////////////////////////////////////////////////////////////////////////////////
class RequestMapEntry : public PLDHashEntryHdr
@ -140,6 +146,9 @@ nsLoadGroup::nsLoadGroup(nsISupports* outer)
, mStatus(NS_OK)
, mPriority(PRIORITY_NORMAL)
, mIsCanceling(PR_FALSE)
, mDefaultLoadIsTimed(false)
, mTimedRequests(0)
, mCachedRequests(0)
{
NS_INIT_AGGREGATED(outer);
@ -340,6 +349,8 @@ nsLoadGroup::Cancel(nsresult status)
NS_RELEASE(request);
}
TelemetryReport();
#if defined(DEBUG)
NS_ASSERTION(mRequests.entryCount == 0, "Request list is not empty.");
NS_ASSERTION(mForegroundCount == 0, "Foreground URLs are active.");
@ -507,6 +518,14 @@ nsLoadGroup::SetDefaultLoadRequest(nsIRequest *aRequest)
// in particular, nsIChannel::LOAD_DOCUMENT_URI...
//
mLoadFlags &= nsIRequest::LOAD_REQUESTMASK;
nsCOMPtr<nsITimedChannel> timedChannel =
do_QueryInterface(aRequest);
mDefaultLoadIsTimed = timedChannel != nsnull;
if (mDefaultLoadIsTimed) {
timedChannel->GetChannelCreation(&mDefaultRequestCreationTime);
timedChannel->SetTimingEnabled(PR_TRUE);
}
}
// Else, do not change the group's load flags (see bug 95981)
return NS_OK;
@ -577,6 +596,10 @@ nsLoadGroup::AddRequest(nsIRequest *request, nsISupports* ctxt)
if (mPriority != 0)
RescheduleRequest(request, mPriority);
nsCOMPtr<nsITimedChannel> timedChannel = do_QueryInterface(request);
if (timedChannel)
timedChannel->SetTimingEnabled(PR_TRUE);
if (!(flags & nsIRequest::LOAD_BACKGROUND)) {
// Update the count of foreground URIs..
mForegroundCount += 1;
@ -659,6 +682,41 @@ nsLoadGroup::RemoveRequest(nsIRequest *request, nsISupports* ctxt,
PL_DHashTableRawRemove(&mRequests, entry);
// Collect telemetry stats only when default request is a timed channel.
// Don't include failed requests in the timing statistics.
if (mDefaultLoadIsTimed && NS_SUCCEEDED(aStatus)) {
nsCOMPtr<nsITimedChannel> timedChannel =
do_QueryInterface(request);
if (timedChannel) {
// Figure out if this request was served from the cache
++mTimedRequests;
TimeStamp timeStamp;
rv = timedChannel->GetCacheReadStart(&timeStamp);
if (NS_SUCCEEDED(rv) && !timeStamp.IsNull())
++mCachedRequests;
rv = timedChannel->GetAsyncOpen(&timeStamp);
if (NS_SUCCEEDED(rv) && !timeStamp.IsNull()) {
Telemetry::Accumulate(
Telemetry::HTTP_SUBITEM_OPEN_LATENCY_TIME,
HISTOGRAM_TIME_DELTA(mDefaultRequestCreationTime, timeStamp));
}
rv = timedChannel->GetResponseStart(&timeStamp);
if (NS_SUCCEEDED(rv) && !timeStamp.IsNull()) {
Telemetry::Accumulate(
Telemetry::HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME,
HISTOGRAM_TIME_DELTA(mDefaultRequestCreationTime, timeStamp));
}
TelemetryReportChannel(timedChannel, false);
}
}
if (mRequests.entryCount == 0) {
TelemetryReport();
}
// Undo any group priority delta...
if (mPriority != 0)
RescheduleRequest(request, -mPriority);
@ -802,6 +860,170 @@ nsLoadGroup::AdjustPriority(PRInt32 aDelta)
////////////////////////////////////////////////////////////////////////////////
void
nsLoadGroup::TelemetryReport()
{
if (mDefaultLoadIsTimed) {
Telemetry::Accumulate(
Telemetry::HTTP_REQUEST_PER_PAGE,
mTimedRequests);
if (mTimedRequests) {
Telemetry::Accumulate(
Telemetry::HTTP_REQUEST_PER_PAGE_FROM_CACHE,
mCachedRequests * 100 / mTimedRequests);
}
nsCOMPtr<nsITimedChannel> timedChannel =
do_QueryInterface(mDefaultLoadRequest);
if (timedChannel)
TelemetryReportChannel(timedChannel, true);
}
mTimedRequests = 0;
mCachedRequests = 0;
mDefaultLoadIsTimed = false;
}
void
nsLoadGroup::TelemetryReportChannel(nsITimedChannel *aTimedChannel,
bool aDefaultRequest)
{
nsresult rv;
PRBool timingEnabled;
rv = aTimedChannel->GetTimingEnabled(&timingEnabled);
if (NS_FAILED(rv) || !timingEnabled)
return;
TimeStamp channelCreation;
rv = aTimedChannel->GetChannelCreation(&channelCreation);
if (NS_FAILED(rv))
return;
TimeStamp asyncOpen;
rv = aTimedChannel->GetAsyncOpen(&asyncOpen);
if (NS_FAILED(rv))
return;
TimeStamp cacheReadStart;
rv = aTimedChannel->GetCacheReadStart(&cacheReadStart);
if (NS_FAILED(rv))
return;
TimeStamp cacheReadEnd;
rv = aTimedChannel->GetCacheReadEnd(&cacheReadEnd);
if (NS_FAILED(rv))
return;
TimeStamp domainLookupStart;
rv = aTimedChannel->GetDomainLookupStart(&domainLookupStart);
if (NS_FAILED(rv))
return;
TimeStamp domainLookupEnd;
rv = aTimedChannel->GetDomainLookupEnd(&domainLookupEnd);
if (NS_FAILED(rv))
return;
TimeStamp connectStart;
rv = aTimedChannel->GetConnectStart(&connectStart);
if (NS_FAILED(rv))
return;
TimeStamp connectEnd;
rv = aTimedChannel->GetConnectEnd(&connectEnd);
if (NS_FAILED(rv))
return;
TimeStamp requestStart;
rv = aTimedChannel->GetRequestStart(&requestStart);
if (NS_FAILED(rv))
return;
TimeStamp responseStart;
rv = aTimedChannel->GetResponseStart(&responseStart);
if (NS_FAILED(rv))
return;
TimeStamp responseEnd;
rv = aTimedChannel->GetResponseEnd(&responseEnd);
if (NS_FAILED(rv))
return;
#define HTTP_REQUEST_HISTOGRAMS(prefix) \
if (!domainLookupStart.IsNull()) { \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_DNS_ISSUE_TIME, \
HISTOGRAM_TIME_DELTA(asyncOpen, domainLookupStart)); \
\
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_DNS_LOOKUP_TIME, \
HISTOGRAM_TIME_DELTA(domainLookupStart, domainLookupEnd)); \
} \
\
if (!connectStart.IsNull()) { \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_TCP_CONNECTION, \
HISTOGRAM_TIME_DELTA(connectStart, connectEnd)); \
} \
\
\
if (!requestStart.IsNull()) { \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_OPEN_TO_FIRST_SENT, \
HISTOGRAM_TIME_DELTA(asyncOpen, requestStart)); \
\
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_FIRST_SENT_TO_LAST_RECEIVED, \
HISTOGRAM_TIME_DELTA(requestStart, responseEnd)); \
\
if (cacheReadStart.IsNull()) { \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_OPEN_TO_FIRST_RECEIVED, \
HISTOGRAM_TIME_DELTA(asyncOpen, responseStart)); \
} \
} \
\
if (!cacheReadStart.IsNull()) { \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_OPEN_TO_FIRST_FROM_CACHE, \
HISTOGRAM_TIME_DELTA(asyncOpen, cacheReadStart)); \
\
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_CACHE_READ_TIME, \
HISTOGRAM_TIME_DELTA(cacheReadStart, cacheReadEnd)); \
\
if (!requestStart.IsNull()) { \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_REVALIDATION, \
HISTOGRAM_TIME_DELTA(requestStart, responseEnd)); \
} \
} \
\
if (!cacheReadEnd.IsNull()) { \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_COMPLETE_LOAD, \
HISTOGRAM_TIME_DELTA(asyncOpen, cacheReadEnd)); \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_COMPLETE_LOAD_CACHED, \
HISTOGRAM_TIME_DELTA(asyncOpen, cacheReadEnd)); \
} \
else if (!responseEnd.IsNull()) { \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_COMPLETE_LOAD, \
HISTOGRAM_TIME_DELTA(asyncOpen, responseEnd)); \
Telemetry::Accumulate( \
Telemetry::HTTP_##prefix##_COMPLETE_LOAD_NET, \
HISTOGRAM_TIME_DELTA(asyncOpen, responseEnd)); \
}
if (aDefaultRequest) {
HTTP_REQUEST_HISTOGRAMS(PAGE)
} else {
HTTP_REQUEST_HISTOGRAMS(SUB)
}
#undef HTTP_REQUEST_HISTOGRAMS
}
nsresult nsLoadGroup::MergeLoadFlags(nsIRequest *aRequest, nsLoadFlags& outFlags)
{
nsresult rv;

13
netwerk/base/src/nsLoadGroup.h
View File

@ -48,7 +48,9 @@
#include "nsIInterfaceRequestor.h"
#include "nsIInterfaceRequestorUtils.h"
#include "nsISupportsPriority.h"
#include "nsITimedChannel.h"
#include "pldhash.h"
#include "mozilla/TimeStamp.h"
class nsISupportsArray;
@ -83,6 +85,11 @@ protected:
nsresult MergeLoadFlags(nsIRequest *aRequest, nsLoadFlags& flags);
private:
void TelemetryReport();
void TelemetryReportChannel(nsITimedChannel *timedChannel,
bool defaultRequest);
protected:
PRUint32 mForegroundCount;
PRUint32 mLoadFlags;
@ -98,6 +105,12 @@ protected:
nsresult mStatus;
PRInt32 mPriority;
PRBool mIsCanceling;
/* Telemetry */
mozilla::TimeStamp mDefaultRequestCreationTime;
bool mDefaultLoadIsTimed;
PRUint32 mTimedRequests;
PRUint32 mCachedRequests;
};
#endif // nsLoadGroup_h__

32
toolkit/components/telemetry/TelemetryHistograms.h
View File

@ -61,3 +61,35 @@ HISTOGRAM(GLUESTARTUP_HARD_FAULTS, 1, 500, 12, EXPONENTIAL, "Hard faults count a
HISTOGRAM(HARD_PAGE_FAULTS, 8, 64 * 1024, 13, EXPONENTIAL, "Hard page faults (since last telemetry ping)")
#endif
HISTOGRAM(ZIPARCHIVE_CRC, 0, 1, 2, BOOLEAN, "Zip item CRC check pass")
/**
* Networking telemetry
*/
HISTOGRAM(TOTAL_CONTENT_PAGE_LOAD_TIME, 100, 10000, 100, EXPONENTIAL, "HTTP: Total page load time (ms)")
HISTOGRAM(HTTP_SUBITEM_OPEN_LATENCY_TIME, 1, 30000, 50, EXPONENTIAL, "HTTP subitem: Page start -> subitem open() (ms)")
HISTOGRAM(HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME, 1, 30000, 50, EXPONENTIAL, "HTTP subitem: Page start -> first byte received for subitem reply (ms)")
HISTOGRAM(HTTP_REQUEST_PER_PAGE, 1, 1000, 50, EXPONENTIAL, "HTTP: Requests per page (count)")
HISTOGRAM(HTTP_REQUEST_PER_PAGE_FROM_CACHE, 1, 101, 102, LINEAR, "HTTP: Requests serviced from cache (%)")
#define _HISTOGRAM_CHANNEL_TIMING(name, label) \
HISTOGRAM(name, 1, 10000, 50, EXPONENTIAL, "HTTP " label) \
#define _HISTOGRAM_CHANNEL_TIMINGS(prefix, labelprefix) \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_DNS_ISSUE_TIME, labelprefix "open() -> DNS request issued (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_DNS_LOOKUP_TIME, labelprefix "DNS lookup time (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_TCP_CONNECTION, labelprefix "TCP connection setup (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_OPEN_TO_FIRST_SENT, labelprefix "Open -> first byte of request sent (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_FIRST_SENT_TO_LAST_RECEIVED, labelprefix "First byte of request sent -> last byte of response received (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_OPEN_TO_FIRST_RECEIVED, labelprefix "Open -> first byte of reply received (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_OPEN_TO_FIRST_FROM_CACHE, labelprefix "Open -> cache read start (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_CACHE_READ_TIME, labelprefix "Cache read time (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_REVALIDATION, labelprefix "Positive cache validation time (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_COMPLETE_LOAD, labelprefix "Overall load time - all (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_COMPLETE_LOAD_CACHED, labelprefix "Overall load time - cache hits (ms)") \
_HISTOGRAM_CHANNEL_TIMING(HTTP_##prefix##_COMPLETE_LOAD_NET, labelprefix "Overall load time - network (ms)") \
_HISTOGRAM_CHANNEL_TIMINGS(PAGE, "page: ")
_HISTOGRAM_CHANNEL_TIMINGS(SUB, "subitem: ")
#undef _HISTOGRAM_CHANNEL_TIMING
#undef _HISTOGRAM_CHANNEL_TIMINGS