Bug 658894 - Collect basic telemetry for HTTP requests and page load, r=jduell
--- a/docshell/base/Makefile.in
+++ b/docshell/base/Makefile.in
@@ -109,15 +109,17 @@ CPPSRCS = \
nsAboutRedirector.cpp \
nsDownloadHistory.cpp \
$(NULL)
# we don't want the shared lib, but we want to force the creation of a
# static lib.
FORCE_STATIC_LIB = 1
+include $(topsrcdir)/config/config.mk
+include $(topsrcdir)/ipc/chromium/chromium-config.mk
include $(topsrcdir)/config/rules.mk
LOCAL_INCLUDES += \
-I$(srcdir)/../shistory/src \
-I$(topsrcdir)/layout/base \
-I$(topsrcdir)/js/src/xpconnect/src \
$(NULL)
--- a/docshell/base/nsDocShell.cpp
+++ b/docshell/base/nsDocShell.cpp
@@ -41,16 +41,19 @@
*
* ***** END LICENSE BLOCK ***** */
#ifdef MOZ_LOGGING
// so we can get logging even in release builds (but only for some things)
#define FORCE_PR_LOG 1
#endif
+#include "base/histogram.h"
+#include "base/logging.h"
+
#include "nsIBrowserDOMWindow.h"
#include "nsIComponentManager.h"
#include "nsIContent.h"
#include "mozilla/dom/Element.h"
#include "nsIDocument.h"
#include "nsIDOMDocument.h"
#include "nsIDOMElement.h"
#include "nsIDOMStorageObsolete.h"
@@ -103,16 +106,17 @@
#include "nsIAppShell.h"
#include "nsWidgetsCID.h"
#include "nsDOMJSUtils.h"
#include "nsIInterfaceRequestorUtils.h"
#include "nsIView.h"
#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"
// we want to explore making the document own the load group
// so we can associate the document URI with the load group.
// until this point, we have an evil hack:
@@ -6041,16 +6045,30 @@ nsDocShell::EndPageLoad(nsIWebProgress *
{
if(!aChannel)
return NS_ERROR_NULL_POINTER;
nsCOMPtr<nsIURI> url;
nsresult rv = aChannel->GetURI(getter_AddRefs(url));
if (NS_FAILED(rv)) return rv;
+ nsCOMPtr<nsITimedChannel> timingChannel =
+ do_QueryInterface(aChannel);
+ if (timingChannel) {
+ mozilla::TimeStamp channelCreationTime;
+ rv = timingChannel->GetChannelCreation(&channelCreationTime);
+ if (NS_SUCCEEDED(rv) && !channelCreationTime.IsNull()) {
+ PRUint32 interval = (PRUint32)
+ (mozilla::TimeStamp::Now() - channelCreationTime)
+ .ToMilliseconds();
+ UMA_HISTOGRAM_TIMES("HTTP: Total page load time (ms)",
+ base::TimeDelta::FromMilliseconds(interval));
+ }
+ }
+
// clean up reload state for meta charset
if (eCharsetReloadRequested == mCharsetReloadState)
mCharsetReloadState = eCharsetReloadStopOrigional;
else
mCharsetReloadState = eCharsetReloadInit;
// Save a pointer to the currently-loading history entry.
// nsDocShell::EndPageLoad will clear mLSHE, but we may need this history
--- a/netwerk/base/src/nsLoadGroup.cpp
+++ b/netwerk/base/src/nsLoadGroup.cpp
@@ -32,47 +32,57 @@
* use your version of this file under the terms of the MPL, indicate your
* decision by deleting the provisions above and replace them with the notice
* and other provisions required by the GPL or the LGPL. If you do not delete
* the provisions above, a recipient may use your version of this file under
* the terms of any one of the MPL, the GPL or the LGPL.
*
* ***** END LICENSE BLOCK ***** */
+#include "base/basictypes.h"
#include "nsLoadGroup.h"
#include "nsISupportsArray.h"
#include "nsEnumeratorUtils.h"
#include "nsIServiceManager.h"
#include "nsCOMPtr.h"
#include "nsIURI.h"
#include "prlog.h"
#include "nsCRT.h"
#include "netCore.h"
#include "nsXPIDLString.h"
#include "nsReadableUtils.h"
#include "nsString.h"
#include "nsTArray.h"
+#include "base/histogram.h"
+#include "base/logging.h"
#if defined(PR_LOGGING)
//
// Log module for nsILoadGroup logging...
//
// To enable logging (see prlog.h for full details):
//
// set NSPR_LOG_MODULES=LoadGroup:5
// set NSPR_LOG_FILE=nspr.log
//
// this enables PR_LOG_DEBUG level information and places all output in
// the file nspr.log
//
static PRLogModuleInfo* gLoadGroupLog = nsnull;
#endif
+#ifdef LOG
+#undef LOG
+#endif
#define LOG(args) PR_LOG(gLoadGroupLog, PR_LOG_DEBUG, args)
+#define HISTOGRAM_TIME_DELTA(start, end) \
+ base::TimeDelta::FromMilliseconds( \
+ (PRUint32)((end - start).ToMilliseconds()))
+
////////////////////////////////////////////////////////////////////////////////
class RequestMapEntry : public PLDHashEntryHdr
{
public:
RequestMapEntry(nsIRequest *aRequest) :
mKey(aRequest)
{
@@ -135,16 +145,19 @@ RescheduleRequests(PLDHashTable *table,
nsLoadGroup::nsLoadGroup(nsISupports* outer)
: mForegroundCount(0)
, mLoadFlags(LOAD_NORMAL)
, mStatus(NS_OK)
, mPriority(PRIORITY_NORMAL)
, mIsCanceling(PR_FALSE)
+ , mDefaultLoadIsTimed(false)
+ , mTimedRequests(0)
+ , mCachedRequests(0)
{
NS_INIT_AGGREGATED(outer);
#if defined(PR_LOGGING)
// Initialize the global PRLogModule for nsILoadGroup logging
if (nsnull == gLoadGroupLog)
gLoadGroupLog = PR_NewLogModule("LoadGroup");
#endif
@@ -335,16 +348,18 @@ nsLoadGroup::Cancel(nsresult status)
// Remember the first failure and return it...
if (NS_FAILED(rv) && NS_SUCCEEDED(firstError))
firstError = rv;
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.");
#endif
mStatus = NS_OK;
mIsCanceling = PR_FALSE;
@@ -502,16 +517,24 @@ nsLoadGroup::SetDefaultLoadRequest(nsIRe
// Inherit the group load flags from the default load request
if (mDefaultLoadRequest) {
mDefaultLoadRequest->GetLoadFlags(&mLoadFlags);
//
// Mask off any bits that are not part of the nsIRequest flags.
// in particular, nsIChannel::LOAD_DOCUMENT_URI...
//
mLoadFlags &= 0xFFFF;
+
+ 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;
}
NS_IMETHODIMP
nsLoadGroup::AddRequest(nsIRequest *request, nsISupports* ctxt)
{
@@ -572,16 +595,20 @@ nsLoadGroup::AddRequest(nsIRequest *requ
if (!entry) {
return NS_ERROR_OUT_OF_MEMORY;
}
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;
//
// Fire the OnStartRequest notification out to the observer...
//
// If the notification fails then DO NOT add the request to
@@ -654,16 +681,51 @@ nsLoadGroup::RemoveRequest(nsIRequest *r
LOG(("LOADGROUP [%x]: Unable to remove request %x. Not in group!\n",
this, request));
return NS_ERROR_FAILURE;
}
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;
+ mozilla::TimeStamp timeStamp;
+ rv = timedChannel->GetCacheReadStart(&timeStamp);
+ if (NS_SUCCEEDED(rv) && !timeStamp.IsNull())
+ ++mCachedRequests;
+
+ rv = timedChannel->GetAsyncOpen(&timeStamp);
+ if (NS_SUCCEEDED(rv) && !timeStamp.IsNull()) {
+ UMA_HISTOGRAM_MEDIUM_TIMES(
+ "HTTP subitem: Page start -> subitem open() (ms)",
+ HISTOGRAM_TIME_DELTA(mDefaultRequestCreationTime, timeStamp));
+ }
+
+ rv = timedChannel->GetResponseStart(&timeStamp);
+ if (NS_SUCCEEDED(rv) && !timeStamp.IsNull()) {
+ UMA_HISTOGRAM_MEDIUM_TIMES(
+ "HTTP subitem: Page start -> first byte received for subitem reply (ms)",
+ HISTOGRAM_TIME_DELTA(mDefaultRequestCreationTime, timeStamp));
+ }
+
+ TelemetryReportChannel(timedChannel, false);
+ }
+ }
+
+ if (mRequests.entryCount == 0) {
+ TelemetryReport();
+ }
+
// Undo any group priority delta...
if (mPriority != 0)
RescheduleRequest(request, -mPriority);
nsLoadFlags flags;
rv = request->GetLoadFlags(&flags);
if (NS_FAILED(rv)) return rv;
@@ -797,16 +859,180 @@ nsLoadGroup::AdjustPriority(PRInt32 aDel
mPriority += aDelta;
PL_DHashTableEnumerate(&mRequests, RescheduleRequests, &aDelta);
}
return NS_OK;
}
////////////////////////////////////////////////////////////////////////////////
+void
+nsLoadGroup::TelemetryReport()
+{
+ if (mDefaultLoadIsTimed) {
+ UMA_HISTOGRAM_COUNTS("HTTP: Requests per page (count)",
+ mTimedRequests);
+ if (mTimedRequests) {
+ UMA_HISTOGRAM_ENUMERATION(
+ "HTTP: Requests serviced from cache (%)",
+ mCachedRequests * 100 / mTimedRequests,
+ 101);
+ }
+
+ 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;
+
+ mozilla::TimeStamp channelCreation;
+ rv = aTimedChannel->GetChannelCreation(&channelCreation);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp asyncOpen;
+ rv = aTimedChannel->GetAsyncOpen(&asyncOpen);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp cacheReadStart;
+ rv = aTimedChannel->GetCacheReadStart(&cacheReadStart);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp cacheReadEnd;
+ rv = aTimedChannel->GetCacheReadEnd(&cacheReadEnd);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp domainLookupStart;
+ rv = aTimedChannel->GetDomainLookupStart(&domainLookupStart);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp domainLookupEnd;
+ rv = aTimedChannel->GetDomainLookupEnd(&domainLookupEnd);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp connectStart;
+ rv = aTimedChannel->GetConnectStart(&connectStart);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp connectEnd;
+ rv = aTimedChannel->GetConnectEnd(&connectEnd);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp requestStart;
+ rv = aTimedChannel->GetRequestStart(&requestStart);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp responseStart;
+ rv = aTimedChannel->GetResponseStart(&responseStart);
+ if (NS_FAILED(rv))
+ return;
+
+ mozilla::TimeStamp responseEnd;
+ rv = aTimedChannel->GetResponseEnd(&responseEnd);
+ if (NS_FAILED(rv))
+ return;
+
+#define _UMA_HTTP_REQUEST_HISTOGRAMS_(prefix) \
+ if (!domainLookupStart.IsNull()) { \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "open() -> DNS request issued (ms)", \
+ HISTOGRAM_TIME_DELTA(asyncOpen, domainLookupStart)); \
+ \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "DNS lookup time (ms)", \
+ HISTOGRAM_TIME_DELTA(domainLookupStart, domainLookupEnd)); \
+ } \
+ \
+ if (!connectStart.IsNull()) { \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "TCP connection setup (ms)", \
+ HISTOGRAM_TIME_DELTA(connectStart, connectEnd)); \
+ } \
+ \
+ \
+ if (!requestStart.IsNull()) { \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Open -> first byte of request sent (ms)", \
+ HISTOGRAM_TIME_DELTA(asyncOpen, requestStart)); \
+ \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "First byte of request sent -> " \
+ "last byte of response received (ms)", \
+ HISTOGRAM_TIME_DELTA(requestStart, responseEnd)); \
+ \
+ if (cacheReadStart.IsNull()) { \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Open -> first byte of reply received (ms)", \
+ HISTOGRAM_TIME_DELTA(asyncOpen, responseStart)); \
+ } \
+ } \
+ \
+ if (!cacheReadStart.IsNull()) { \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Open -> cache read start (ms)", \
+ HISTOGRAM_TIME_DELTA(asyncOpen, cacheReadStart)); \
+ \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Cache read time (ms)", \
+ HISTOGRAM_TIME_DELTA(cacheReadStart, cacheReadEnd)); \
+ \
+ if (!requestStart.IsNull()) { \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Positive cache validation time (ms)", \
+ HISTOGRAM_TIME_DELTA(requestStart, responseEnd)); \
+ } \
+ } \
+ if (!cacheReadEnd.IsNull()) { \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Overall load time - all (ms)", \
+ HISTOGRAM_TIME_DELTA(asyncOpen, cacheReadEnd)); \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Overall load time - cache hits (ms)", \
+ HISTOGRAM_TIME_DELTA(asyncOpen, cacheReadEnd)); \
+ } \
+ else if (!responseEnd.IsNull()) { \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Overall load time - all (ms)", \
+ HISTOGRAM_TIME_DELTA(asyncOpen, responseEnd)); \
+ UMA_HISTOGRAM_TIMES( \
+ prefix "Overall load time: network (ms)", \
+ HISTOGRAM_TIME_DELTA(asyncOpen, responseEnd)); \
+ }
+
+ if (aDefaultRequest) {
+ _UMA_HTTP_REQUEST_HISTOGRAMS_("HTTP page: ")
+ } else {
+ _UMA_HTTP_REQUEST_HISTOGRAMS_("HTTP subitem: ")
+ }
+#undef _UMA_HTTP_REQUEST_HISTOGRAMS_
+}
+
nsresult nsLoadGroup::MergeLoadFlags(nsIRequest *aRequest, nsLoadFlags& outFlags)
{
nsresult rv;
nsLoadFlags flags, oldFlags;
rv = aRequest->GetLoadFlags(&flags);
if (NS_FAILED(rv))
return rv;
--- a/netwerk/base/src/nsLoadGroup.h
+++ b/netwerk/base/src/nsLoadGroup.h
@@ -43,17 +43,19 @@
#include "nsIStreamListener.h"
#include "nsAgg.h"
#include "nsCOMPtr.h"
#include "nsWeakPtr.h"
#include "nsWeakReference.h"
#include "nsIInterfaceRequestor.h"
#include "nsIInterfaceRequestorUtils.h"
#include "nsISupportsPriority.h"
+#include "nsITimedChannel.h"
#include "pldhash.h"
+#include "mozilla/TimeStamp.h"
class nsISupportsArray;
class nsLoadGroup : public nsILoadGroup,
public nsISupportsPriority,
public nsSupportsWeakReference
{
public:
@@ -78,26 +80,38 @@ public:
nsresult Init();
protected:
virtual ~nsLoadGroup();
nsresult MergeLoadFlags(nsIRequest *aRequest, nsLoadFlags& flags);
+private:
+ void TelemetryReport();
+ void TelemetryReportChannel(nsITimedChannel *timedChannel,
+ bool defaultRequest);
+
protected:
PRUint32 mForegroundCount;
PRUint32 mLoadFlags;
nsCOMPtr<nsILoadGroup> mLoadGroup; // load groups can contain load groups
nsCOMPtr<nsIInterfaceRequestor> mCallbacks;
nsCOMPtr<nsIRequest> mDefaultLoadRequest;
PLDHashTable mRequests;
nsWeakPtr mObserver;
nsresult mStatus;
PRInt32 mPriority;
PRBool mIsCanceling;
+
+ /* Telemetry */
+ mozilla::TimeStamp mPageLoadStartTime;
+ mozilla::TimeStamp mDefaultRequestCreationTime;
+ bool mDefaultLoadIsTimed;
+ PRUint32 mTimedRequests;
+ PRUint32 mCachedRequests;
};
#endif // nsLoadGroup_h__