Instrumenting URLRequestJob::Read to find jank

net/url_request/url_request_job.cc

Index: net/url_request/url_request_job.cc
diff --git a/net/url_request/url_request_job.cc b/net/url_request/url_request_job.cc
index 3cd8cf40ee30fcd02f01377152179c65b9fc13a3..36e2eadf35d468fd12e16a877ae4f5f1cc9105f0 100644
--- a/net/url_request/url_request_job.cc
+++ b/net/url_request/url_request_job.cc
@@ -90,6 +90,10 @@ bool URLRequestJob::Read(IOBuffer* buf, int buf_size, int *bytes_read) {
 
   // 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
@@ -97,18 +101,32 @@ bool URLRequestJob::Read(IOBuffer* buf, int buf_size, int *bytes_read) {
     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;