Instrumenting URLRequestJob::Read to find jank

net/url_request/url_request_job.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/url_request/url_request_job.h"
 
 #include "base/bind.h"
 #include "base/compiler_specific.h"
 #include "base/message_loop/message_loop.h"
 #include "base/power_monitor/power_monitor.h"
@@ skipping 72 matching lines @@
   DCHECK_LT(buf_size, 1000000);  // Sanity check.
   DCHECK(buf);
   DCHECK(bytes_read);
   DCHECK(filtered_read_buffer_.get() == NULL);
   DCHECK_EQ(0, filtered_read_buffer_len_);
 
   *bytes_read = 0;
 
   // Skip Filter if not present.
   if (!filter_.get()) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile1(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION("423948 URLRequestJob::Read1"));

[mmenke, 2014/12/12 15:23:46]

Suggest putting one in ReadRawDataHelper instead (ReadFilteredData feeds into
it, so putting one at the start of ReadRawData means URLRequestJob::Read2 would
just measure the filter time, while the one in ReadRawData would measure the
time spent by the embedder actually dealing with that data.

[vadimt, 2014/12/12 15:34:50]

Done.

+
     rv = ReadRawDataHelper(buf, buf_size, bytes_read);
   } else {
     // Save the caller's buffers while we do IO
     // in the filter's buffers.
     filtered_read_buffer_ = buf;
     filtered_read_buffer_len_ = buf_size;
 
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile2(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION("423948 URLRequestJob::Read2"));
+
     if (ReadFilteredData(bytes_read)) {
       rv = true;   // We have data to return.
 
       // It is fine to call DoneReading even if ReadFilteredData receives 0
       // bytes from the net, but we avoid making that call if we know for
       // sure that's the case (ReadRawDataHelper path).
+      // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is
+      // fixed.
+      tracked_objects::ScopedTracker tracking_profile3(
+          FROM_HERE_WITH_EXPLICIT_FUNCTION("423948 URLRequestJob::Read3"));
+
       if (*bytes_read == 0)
         DoneReading();
     } else {
       rv = false;  // Error, or a new IO is pending.
     }
   }
+
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile4(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION("423948 URLRequestJob::Read4"));
+
   if (rv && *bytes_read == 0)
     NotifyDone(URLRequestStatus());
   return rv;
 }
 
 void URLRequestJob::StopCaching() {
   // Nothing to do here.
 }
 
 bool URLRequestJob::GetFullRequestHeaders(HttpRequestHeaders* headers) const {
@@ skipping 779 matching lines @@
   // Alter the referrer if redirecting cross-origin (especially HTTP->HTTPS).
   redirect_info.new_referrer =
       ComputeReferrerForRedirect(request_->referrer_policy(),
                                  request_->referrer(),
                                  redirect_info.new_url).spec();
 
   return redirect_info;
 }
 
 }  // namespace net