Add trace event for complete network request

third_party/WebKit/Source/core/fetch/ResourceFetcher.cpp

Index: third_party/WebKit/Source/core/fetch/ResourceFetcher.cpp
diff --git a/third_party/WebKit/Source/core/fetch/ResourceFetcher.cpp b/third_party/WebKit/Source/core/fetch/ResourceFetcher.cpp
index 87844840edb85a80b9c188695d2e0aa0de7adc67..1d35a2b9fe38c8ac6ad1d079ea69a5eac76a5cce 100644
--- a/third_party/WebKit/Source/core/fetch/ResourceFetcher.cpp
+++ b/third_party/WebKit/Source/core/fetch/ResourceFetcher.cpp
@@ -40,6 +40,7 @@
 #include "platform/RuntimeEnabledFeatures.h"
 #include "platform/mhtml/ArchiveResource.h"
 #include "platform/mhtml/MHTMLArchive.h"
+#include "platform/network/NetworkInstrumentation.h"
 #include "platform/network/NetworkUtils.h"
 #include "platform/network/ResourceTimingInfo.h"
 #include "platform/tracing/TraceEvent.h"
@@ -484,6 +485,9 @@ Resource* ResourceFetcher::requestResource(
     FetchRequest& request,
     const ResourceFactory& factory,
     const SubstituteData& substituteData) {
+  unsigned long identifier = createUniqueIdentifier();
+  network_instrumentation::ScopedResourceLoadTracker scopedResourceLoadTracker(
+      identifier, request.resourceRequest());
   SCOPED_BLINK_UMA_HISTOGRAM_TIMER("Blink.Fetch.RequestResourceTime");
   DCHECK(request.options().synchronousPolicy == RequestAsynchronously ||
          factory.type() == Resource::Raw ||
@@ -497,17 +501,19 @@ Resource* ResourceFetcher::requestResource(
   context().addClientHintsIfNecessary(request);
   context().addCSPHeaderIfNecessary(factory.type(), request);
 
+  // TODO(dproy): Remove this. http://crbug.com/659666

[Charlie Harrison, 2016/11/08 15:20:18]

drive-by: This trace is important for tracking CPU time of requesting a single
resource. Please make sure that the new probe points capture this before
deleting this trace, as I am actively working on the CPU overhead it covers.

[dproy, 2016/11/08 16:31:50]

Do you mean just this single trace in particular? IIUC it seems like this is
only tracking the requestResource function (as opposed to say, the cost of the
rest of the request lifecycle, including other parts in the renderer and all the
parts in the browser.)

If this particular function is very important to instrument, we can add probes
to capture that.

[Charlie Harrison, 2016/11/08 16:34:26]

Yep this single method does a lot of work, including going out to the
FrameFetchContext, and //content in multiple places. It is the main driver in
forming the request and sending the resource request IPC to the browser process.

While you're here, do you mind moving it to the top of the method, underneath
the SCOPED_BLINK_UMA_HISTOGRAM?

[dproy, 2016/11/08 16:45:35]

Ah I see. This CL is about tracking the entire network request - let's keep it
that way. Once this lands, I'll send a quick follow up CL that removes this
trace point but adds a subslice tracking this function (and I'll put the start
point of that subslice at the beginning of this function underneath the UMA, as
you wanted.) 

[Charlie Harrison, 2016/11/08 17:34:04]

That plan sounds great to me. Just to clarify, will a "subslice" have similar
semantics to this probe point in the UI? I often e.g. double click this event to
find aggregate metrics for it in a single trace. Would that still work when it
is refactored as a subslice?

   TRACE_EVENT1("blink", "ResourceFetcher::requestResource", "url",
                urlForTraceEvent(request.url()));
 
   if (!request.url().isValid())
     return nullptr;
 
-  unsigned long identifier = createUniqueIdentifier();
   request.mutableResourceRequest().setPriority(computeLoadPriority(
       factory.type(), request, ResourcePriority::NotVisible));
   initializeResourceRequest(request.mutableResourceRequest(), factory.type(),
                             request.defer());
+  network_instrumentation::initialResourcePrioritySet(

[caseq, 2016/11/08 18:24:32]

let's unify this with resourcePriorityChanged, I'd rather handle one event
instead of two on the processing side, and I'm sure we would be able to tell one
from another if we really need by nesting -- so just name it something like
resourcePrioritySet and use the same on both call sites.

[dproy, 2016/11/09 20:44:00]

Done.

+      identifier, request.resourceRequest().priority());
 
   if (!context().canRequest(
           factory.type(), request.resourceRequest(),
@@ -634,6 +640,9 @@ Resource* ResourceFetcher::requestResource(
 
   if (!startLoad(resource))
     return nullptr;
+
+  scopedResourceLoadTracker.doNotCloseSliceAtEndOfScope();
+
   DCHECK(!resource->errorOccurred() ||
          request.options().synchronousPolicy == RequestSynchronously);
   return resource;
@@ -1044,8 +1053,6 @@ bool ResourceFetcher::hasPendingRequest() const {
 void ResourceFetcher::preloadStarted(Resource* resource) {
   if (m_preloads && m_preloads->contains(resource))
     return;
-  TRACE_EVENT_ASYNC_STEP_INTO0("blink.net", "Resource", resource->identifier(),
-                               "Preload");
   resource->increasePreloadCount();
 
   if (!m_preloads)
@@ -1118,7 +1125,8 @@ void ResourceFetcher::didFinishLoading(Resource* resource,
                                        double finishTime,
                                        int64_t encodedDataLength,
                                        DidFinishLoadingReason finishReason) {
-  TRACE_EVENT_ASYNC_END0("blink.net", "Resource", resource->identifier());
+  network_instrumentation::endResourceLoad(
+      resource->identifier(), network_instrumentation::RequestOutcome::Success);
   DCHECK(resource);
 
   // When loading a multipart resource, make the loader non-block when finishing
@@ -1173,7 +1181,8 @@ void ResourceFetcher::didFinishLoading(Resource* resource,
 
 void ResourceFetcher::didFailLoading(Resource* resource,
                                      const ResourceError& error) {
-  TRACE_EVENT_ASYNC_END0("blink.net", "Resource", resource->identifier());
+  network_instrumentation::endResourceLoad(
+      resource->identifier(), network_instrumentation::RequestOutcome::Fail);
   removeResourceLoader(resource->loader());
   m_resourceTimingInfoMap.take(const_cast<Resource*>(resource));
   bool isInternalRequest = resource->options().initiatorInfo.name ==
@@ -1419,9 +1428,8 @@ void ResourceFetcher::updateAllImageResourcePriorities() {
 
     resource->didChangePriority(resourceLoadPriority,
                                 resourcePriority.intraPriorityValue);
-    TRACE_EVENT_ASYNC_STEP_INTO1("blink.net", "Resource",
-                                 resource->identifier(), "ChangePriority",
-                                 "priority", resourceLoadPriority);
+    network_instrumentation::resourcePriorityChanged(resource->identifier(),
+                                                     resourceLoadPriority);
     context().dispatchDidChangeResourcePriority(
         resource->identifier(), resourceLoadPriority,
         resourcePriority.intraPriorityValue);