bug 658894 - Collect basic telemetry for HTTP requests and page load. r=jduell
authorHonza Bambas <honzab.moz@firemni.cz>
Fri, 01 Jul 2011 22:22:18 +0200
changeset 72729 eb5866601f88f4ebf278222ff28853ee9ed746d6
parent 72728 3a5af9d36fb1071d562f72e6ac5a2c42283de129
child 72730 0d425ab8eb132efbcb78918d70694421b817bf69
push id159
push usereakhgari@mozilla.com
push dateTue, 16 Aug 2011 17:53:11 +0000
treeherdermozilla-beta@8786e3e49240 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjduell
bugs658894
milestone7.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
bug 658894 - Collect basic telemetry for HTTP requests and page load. r=jduell
docshell/base/nsDocShell.cpp
netwerk/base/src/nsLoadGroup.cpp
netwerk/base/src/nsLoadGroup.h
toolkit/components/telemetry/TelemetryHistograms.h
--- a/docshell/base/nsDocShell.cpp
+++ b/docshell/base/nsDocShell.cpp
@@ -99,21 +99,23 @@
 #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"
 #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.
 // until this point, we have an evil hack:
 #include "nsIHttpChannelInternal.h"  
 
 
 // Local Includes
@@ -6111,16 +6113,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) {
+        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;
 
     // clean up reload state for meta charset
     if (eCharsetReloadRequested == mCharsetReloadState)
         mCharsetReloadState = eCharsetReloadStopOrigional;
     else 
         mCharsetReloadState = eCharsetReloadInit;
--- a/netwerk/base/src/nsLoadGroup.cpp
+++ b/netwerk/base/src/nsLoadGroup.cpp
@@ -45,16 +45,19 @@
 #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 "mozilla/Telemetry.h"
+
+using namespace mozilla;
 
 #if defined(PR_LOGGING)
 //
 // Log module for nsILoadGroup logging...
 //
 // To enable logging (see prlog.h for full details):
 //
 //    set NSPR_LOG_MODULES=LoadGroup:5
@@ -63,16 +66,19 @@
 // this enables PR_LOG_DEBUG level information and places all output in
 // the file nspr.log
 //
 static PRLogModuleInfo* gLoadGroupLog = nsnull;
 #endif
 
 #define LOG(args) PR_LOG(gLoadGroupLog, PR_LOG_DEBUG, args)
 
+#define HISTOGRAM_TIME_DELTA(start, end) \
+    (PRUint32)((end - start).ToMilliseconds())
+
 ////////////////////////////////////////////////////////////////////////////////
 
 class RequestMapEntry : public PLDHashEntryHdr
 {
 public:
     RequestMapEntry(nsIRequest *aRequest) :
         mKey(aRequest)
     {
@@ -135,16 +141,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
@@ -502,16 +511,23 @@ 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 &= 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;
 }
 
 NS_IMETHODIMP
 nsLoadGroup::AddRequest(nsIRequest *request, nsISupports* ctxt)
 {
@@ -572,16 +588,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 +674,50 @@ 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;
+            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);
 
     nsLoadFlags flags;
     rv = request->GetLoadFlags(&flags);
     if (NS_FAILED(rv)) return rv;
 
@@ -797,16 +851,180 @@ nsLoadGroup::AdjustPriority(PRInt32 aDel
         mPriority += aDelta;
         PL_DHashTableEnumerate(&mRequests, RescheduleRequests, &aDelta);
     }
     return NS_OK;
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 
+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);
+    // We do not check !asyncOpen.IsNull() bellow, prevent ASSERTIONs this way
+    if (NS_FAILED(rv) || asyncOpen.IsNull())
+        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));               \
+    }                                                                          \
+                                                                               \
+    if (!domainLookupStart.IsNull() && !domainLookupEnd.IsNull()) {            \
+        Telemetry::Accumulate(                                                 \
+            Telemetry::HTTP_##prefix##_DNS_LOOKUP_TIME,                        \
+            HISTOGRAM_TIME_DELTA(domainLookupStart, domainLookupEnd));         \
+    }                                                                          \
+                                                                               \
+    if (!connectStart.IsNull() && !connectEnd.IsNull()) {                      \
+        Telemetry::Accumulate(                                                 \
+            Telemetry::HTTP_##prefix##_TCP_CONNECTION,                         \
+            HISTOGRAM_TIME_DELTA(connectStart, connectEnd));                   \
+    }                                                                          \
+                                                                               \
+                                                                               \
+    if (!requestStart.IsNull() && !responseEnd.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() && !cacheReadEnd.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() && !responseEnd.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;
     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,37 @@ 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              mDefaultRequestCreationTime;
+    bool                            mDefaultLoadIsTimed;
+    PRUint32                        mTimedRequests;
+    PRUint32                        mCachedRequests;
 };
 
 #endif // nsLoadGroup_h__
--- a/toolkit/components/telemetry/TelemetryHistograms.h
+++ b/toolkit/components/telemetry/TelemetryHistograms.h
@@ -57,10 +57,42 @@ HISTOGRAM(GLUESTARTUP_READ_OPS, 1, 100, 
 HISTOGRAM(GLUESTARTUP_READ_TRANSFER, 1, 50 * 1024, 12, EXPONENTIAL, "ProcessIoCounters.ReadTransferCount after glue startup (KB)")
 #elif defined(XP_UNIX)
 HISTOGRAM(EARLY_GLUESTARTUP_HARD_FAULTS, 1, 100, 12, LINEAR, "Hard faults count before glue startup")
 HISTOGRAM(GLUESTARTUP_HARD_FAULTS, 1, 500, 12, EXPONENTIAL, "Hard faults count after glue startup")
 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")
 HISTOGRAM(SHUTDOWN_OK, 0, 1, 2, BOOLEAN, "Did the browser start after a successful shutdown")
+
+/**
+ * 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 _HTTP_HIST(name, label) \
+  HISTOGRAM(name, 1, 10000, 50, EXPONENTIAL, "HTTP " label) \
+
+#define HTTP_HISTOGRAMS(prefix, labelprefix) \
+  _HTTP_HIST(HTTP_##prefix##_DNS_ISSUE_TIME, labelprefix "open() -> DNS request issued (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_DNS_LOOKUP_TIME, labelprefix "DNS lookup time (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_TCP_CONNECTION, labelprefix "TCP connection setup (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_OPEN_TO_FIRST_SENT, labelprefix "Open -> first byte of request sent (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_FIRST_SENT_TO_LAST_RECEIVED, labelprefix "First byte of request sent -> last byte of response received (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_OPEN_TO_FIRST_RECEIVED, labelprefix "Open -> first byte of reply received (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_OPEN_TO_FIRST_FROM_CACHE, labelprefix "Open -> cache read start (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_CACHE_READ_TIME, labelprefix "Cache read time (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_REVALIDATION, labelprefix "Positive cache validation time (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_COMPLETE_LOAD, labelprefix "Overall load time - all (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_COMPLETE_LOAD_CACHED, labelprefix "Overall load time - cache hits (ms)") \
+  _HTTP_HIST(HTTP_##prefix##_COMPLETE_LOAD_NET, labelprefix "Overall load time - network (ms)") \
+
+HTTP_HISTOGRAMS(PAGE, "page: ")
+HTTP_HISTOGRAMS(SUB, "subitem: ")
+
+#undef _HTTP_HIST
+#undef HTTP_HISTOGRAMS
 HISTOGRAM(FIND_PLUGINS, 1, 3000, 10, EXPONENTIAL, "Time spent scanning filesystem for plugins (ms)")
 HISTOGRAM(CHECK_JAVA_ENABLED, 1, 3000, 10, EXPONENTIAL, "Time spent checking if Java is enabled (ms)")