Add trace event for complete network request

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

 /*
     Copyright (C) 1998 Lars Knoll (knoll@mpi-hd.mpg.de)
     Copyright (C) 2001 Dirk Mueller (mueller@kde.org)
     Copyright (C) 2002 Waldo Bastian (bastian@kde.org)
     Copyright (C) 2004, 2005, 2006, 2007, 2008, 2009, 2010, 2011 Apple Inc. All
     rights reserved.
     Copyright (C) 2009 Torch Mobile Inc. http://www.torchmobile.com/
 
     This library is free software; you can redistribute it and/or
     modify it under the terms of the GNU Library General Public
@@ skipping 22 matching lines @@
 #include "core/fetch/FetchInitiatorTypeNames.h"
 #include "core/fetch/ImageResource.h"
 #include "core/fetch/MemoryCache.h"
 #include "core/fetch/ResourceLoader.h"
 #include "core/fetch/ResourceLoadingLog.h"
 #include "core/fetch/UniqueIdentifier.h"
 #include "platform/Histogram.h"
 #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"
 #include "platform/tracing/TracedValue.h"
 #include "platform/weborigin/KnownPorts.h"
 #include "platform/weborigin/SecurityOrigin.h"
 #include "platform/weborigin/SecurityPolicy.h"
 #include "public/platform/Platform.h"
 #include "public/platform/WebCachePolicy.h"
 #include "public/platform/WebURL.h"
@@ skipping 424 matching lines @@
   if (resource && !resource->isAlive() &&
       (!m_preloads || !m_preloads->contains(resource))) {
     DEFINE_RESOURCE_HISTOGRAM("Dead.");
   }
 }
 
 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 ||
          factory.type() == Resource::XSLStyleSheet);
 
   context().populateRequestData(request.mutableResourceRequest());
   if (request.resourceRequest().httpHeaderField("Upgrade-Insecure-Requests") !=
       AtomicString("1")) {
     context().modifyRequestForCSP(request.mutableResourceRequest());
   }
   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(),
           MemoryCache::removeFragmentIdentifierIfNeeded(request.url()),
           request.options(), request.forPreload(),
           request.getOriginRestriction())) {
     DCHECK(!substituteData.forceSynchronousLoad());
     return resourceForBlockedRequest(request, factory);
   }
 
@@ skipping 106 matching lines @@
 
   // Returns with an existing resource if the resource does not need to start
   // loading immediately. If revalidation policy was determined as |Revalidate|,
   // the resource was already initialized for the revalidation here, but won't
   // start loading.
   if (!resourceNeedsLoad(resource, request, policy))
     return resource;
 
   if (!startLoad(resource))
     return nullptr;
+
+  scopedResourceLoadTracker.doNotCloseSliceAtEndOfScope();
+
   DCHECK(!resource->errorOccurred() ||
          request.options().synchronousPolicy == RequestSynchronously);
   return resource;
 }
 
 void ResourceFetcher::resourceTimingReportTimerFired(TimerBase* timer) {
   DCHECK_EQ(timer, &m_resourceTimingReportTimer);
   Vector<std::unique_ptr<ResourceTimingInfo>> timingReports;
   timingReports.swap(m_scheduledResourceTimingReports);
   for (const auto& timingInfo : timingReports)
@@ skipping 390 matching lines @@
   return m_loaders.size();
 }
 
 bool ResourceFetcher::hasPendingRequest() const {
   return m_loaders.size() > 0 || m_nonBlockingLoaders.size() > 0;
 }
 
 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)
     m_preloads = new HeapListHashSet<Member<Resource>>;
   m_preloads->add(resource);
 
   if (m_preloadedURLsForTest)
     m_preloadedURLsForTest->add(resource->url().getString());
 }
 
@@ skipping 52 matching lines @@
   if (!context().isMainFrame())
     return nullptr;
   m_archive = MHTMLArchive::create(resource->url(), resource->resourceBuffer());
   return m_archive ? m_archive->mainResource() : nullptr;
 }
 
 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
   // loading the first part.
   if (finishReason == DidFinishFirstPartInMultipart)
     moveResourceLoaderToNonBlocking(resource->loader());
   else
     removeResourceLoader(resource->loader());
   DCHECK(!m_loaders.contains(resource->loader()));
   DCHECK(finishReason == DidFinishFirstPartInMultipart ||
@@ skipping 34 matching lines @@
   context().didLoadResource(resource);
 
   if (resource->isImage() &&
       toImageResource(resource)->shouldReloadBrokenPlaceholder()) {
     toImageResource(resource)->reloadIfLoFiOrPlaceholder(this);
   }
 }
 
 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 ==
                            FetchInitiatorTypeNames::internal;
   context().dispatchDidFail(resource->identifier(), error, isInternalRequest);
   resource->error(error);
   context().didLoadResource(resource);
 
   if (resource->isImage() &&
       toImageResource(resource)->shouldReloadBrokenPlaceholder()) {
@@ skipping 225 matching lines @@
     ResourcePriority resourcePriority = resource->priorityFromObservers();
     ResourceLoadPriority resourceLoadPriority = computeLoadPriority(
         Resource::Image,
         FetchRequest(resource->resourceRequest(), FetchInitiatorInfo()),
         resourcePriority.visibility);
     if (resourceLoadPriority == resource->resourceRequest().priority())
       continue;
 
     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);
   }
 }
 
 void ResourceFetcher::reloadLoFiImages() {
   for (const auto& documentResource : m_documentResources) {
     Resource* resource = documentResource.value.get();
     if (resource && resource->isImage()) {
@@ skipping 187 matching lines @@
   visitor->trace(m_context);
   visitor->trace(m_archive);
   visitor->trace(m_loaders);
   visitor->trace(m_nonBlockingLoaders);
   visitor->trace(m_documentResources);
   visitor->trace(m_preloads);
   visitor->trace(m_resourceTimingInfoMap);
 }
 
 }  // namespace blink