More instrumentation to track down net/ jank.

net/proxy/proxy_script_fetcher_impl.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/proxy/proxy_script_fetcher_impl.h"
 
 #include "base/compiler_specific.h"
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
+#include "base/profiler/scoped_tracker.h"
 #include "base/strings/string_util.h"
 #include "net/base/data_url.h"
 #include "net/base/io_buffer.h"
 #include "net/base/load_flags.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_string_util.h"
 #include "net/base/request_priority.h"
 #include "net/cert/cert_status_flags.h"
 #include "net/http/http_response_headers.h"
 #include "net/url_request/url_request_context.h"
@@ skipping 87 matching lines @@
   // Use |result_code_| as the request's error if we have already set it to
   // something specific.
   if (result_code_ == OK && !request->status().is_success())
     result_code_ = request->status().error();
 
   FetchCompleted();
 }
 
 int ProxyScriptFetcherImpl::Fetch(
     const GURL& url, base::string16* text, const CompletionCallback& callback) {
+  // TODO(eroman): Remove ScopedTracker below once crbug.com/455942 is fixed.
+  tracked_objects::ScopedTracker tracking_profile1(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "455942 ProxyScriptFetcherImpl::Fetch (Other)"));
+
   // It is invalid to call Fetch() while a request is already in progress.
   DCHECK(!cur_request_.get());
   DCHECK(!callback.is_null());
   DCHECK(text);
 
   // Handle base-64 encoded data-urls that contain custom PAC scripts.
   if (url.SchemeIs("data")) {
+    // TODO(eroman): Remove ScopedTracker below once crbug.com/455942 is fixed.
+    tracked_objects::ScopedTracker tracking_profile2(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "455942 ProxyScriptFetcherImpl::Fetch (data url)"));
     std::string mime_type;
     std::string charset;
     std::string data;
     if (!DataURL::Parse(url, &mime_type, &charset, &data))
       return ERR_FAILED;
 
     ConvertResponseToUTF16(charset, data, text);
     return OK;
   }
 
@@ skipping 14 matching lines @@
                              LOAD_DISABLE_CERT_REVOCATION_CHECKING);
 
   // Save the caller's info for notification on completion.
   callback_ = callback;
   result_text_ = text;
 
   bytes_read_so_far_.clear();
 
   // Post a task to timeout this request if it takes too long.
   cur_request_id_ = ++next_id_;
+
+  // TODO(eroman): Remove ScopedTracker below once crbug.com/455942 is fixed.
+  tracked_objects::ScopedTracker tracking_profile3(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "455942 ProxyScriptFetcherImpl::Fetch (PostDelayedTask)"));
+
   base::MessageLoop::current()->PostDelayedTask(
       FROM_HERE,
       base::Bind(&ProxyScriptFetcherImpl::OnTimeout,
                  weak_factory_.GetWeakPtr(),
                  cur_request_id_),
       max_duration_);
 
   // Start the request.
   cur_request_->Start();

[mmenke, 2015/04/23 21:32:51]

Hrm...Some poor soul is also stuck looking into jank here.  Suppose proxies are
rare enough that if it were just the same cause of jank, it probably wouldn't be
enough to show up on the dashboard, though.

[eroman, 2015/04/23 22:50:46]

Heh, I wonder who that poor soul might be...
I guess we will see what the data reveals. I am actually curious to see what
this one turns out to be, since I would have guessed URLRequest::Start() would
be the slow thing in this function (but that is already being measured).

Also got me thinking, what happens with ScopedTracker for re-entrency? Maybe it
is posible for URLRequest::Start() to call URLRequest::Start() again by way of
ProxyScriptFetcherImpl. Hmm.

   return ERR_IO_PENDING;
 }
 
 void ProxyScriptFetcherImpl::Cancel() {
   // ResetCurRequestState will free the URLRequest, which will cause
   // cancellation.
   ResetCurRequestState();
 }
 
 URLRequestContext* ProxyScriptFetcherImpl::GetRequestContext() const {
@@ skipping 134 matching lines @@
   // is still applicable.
   if (cur_request_id_ != id)
     return;
 
   DCHECK(cur_request_.get());
   result_code_ = ERR_TIMED_OUT;
   cur_request_->Cancel();
 }
 
 }  // namespace net