Bug 658894 - Collect basic telemetry for HTTP requests and page load, r=jduell
authorHonza Bambas <honzab.moz@firemni.cz>
Thu, 09 Jun 2011 14:04:16 +0200
changeset 70790 701b76c4e716be05b8bb769c9b1fc8b183946642
parent 70789 8f30c4d067247eb2bc255ae171e948ed09ce9ff7
child 70791 63a285db615c52b0d17b46c07bc71f69814c7c4f
child 70834 0fd6f88a7c1bb319c2672c0fbbdb90767294377c
push id1
push userroot
push dateMon, 20 Oct 2014 17:29:22 +0000
reviewersjduell
bugs658894
milestone7.0a1
Bug 658894 - Collect basic telemetry for HTTP requests and page load, r=jduell
docshell/base/Makefile.in
docshell/base/nsDocShell.cpp
netwerk/base/src/nsLoadGroup.cpp
netwerk/base/src/nsLoadGroup.h
--- 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__