Instrumenting URLRequestJob::NotifyHeadersComplete to locate the source of jankiness

Instrumenting URLRequestJob::NotifyHeadersComplete to locate the source of jankiness

Previous instrumentations showed that URLRequestJob::NotifyHeadersComplete
alone is responsible for ~57.1 janks per hour in IO thread. I need to instrument
the code inside it to find out which part causes jank.

This is a mechanical change that adds instrumentation required to locate the
source of jankiness (i.e. a long-running fragment of code executed as a part of
the task that causes jank) in the code. See the bug for details on what kind of
jank we are after.
A number of similar CLs were landed, and none of them caused issues. They've
helped to find and fix janky code. The code of the instrumentation is highly
optimized and is not expected to affect performance. The code simply creates a
diagnostic task which is identical to ones created by PostTask or IPC message
handlers. The task gets created only in developer build and in Canary channel.

BUG=423948
Committed: https://crrev.com/844c155753d7e42619a437ef6f3036aaf466e140
Cr-Commit-Position: refs/heads/master@{#302694}

[vadimt, 2014-10-30 19:31:01]

vadimt@chromium.org changed reviewers:
+ asanka@chromium.org

[vadimt, 2014-10-30 19:31:01]

asanka@, please provide OWNER's approval

[asanka, 2014-10-31 04:32:30]

asanka@chromium.org changed reviewers:
+ mmenke@chromium.org

[asanka, 2014-10-31 04:32:30]

Tossing at Matt FHI. My guess is that the jank comes from the delegates, rather
than the code being instrumented here. Then it'd be useful to know which
delegate it was and I don't really see how to gather that information here in a
performant manner.

[mmenke, 2014-10-31 16:52:15]

https://codereview.chromium.org/696483002/diff/1/net/url_request/url_request_...
File net/url_request/url_request_job.cc (right):

https://codereview.chromium.org/696483002/diff/1/net/url_request/url_request_...
net/url_request/url_request_job.cc:331: tracked_objects::ScopedTracker
tracking_profile1(
Could we get some docs on this class?  I have no idea what it does, or how
results from this show up.  Depending on the answer to that, the arrangement of
some of these may be in need of work.

https://codereview.chromium.org/696483002/diff/1/net/url_request/url_request_...
net/url_request/url_request_job.cc:361: ComputeRedirectInfo(new_location,
http_status_code);
This call is pretty uninteresting.  The NotifyReceivedRedirect is much more
interesting.

https://codereview.chromium.org/696483002/diff/1/net/url_request/url_request_...
net/url_request/url_request_job.cc:397: GetAuthChallengeInfo(&auth_info);
Hrm..  AUTH requests are a fairly obscure corner case that I really don't think
we care about.

If we do, though, this function just dereferences a couple pointers, and is
completely irrelevant when it comes to performances.  The call to
request_->NotifyAuthRequired is where you should be looking, if we care (I
maintain we don't, really).

https://codereview.chromium.org/696483002/diff/1/net/url_request/url_request_...
net/url_request/url_request_job.cc:421: "423948
URLRequestJob::NotifyHeadersComplete 9"));
This seems completely uninteresting - lookup up a single header, and a single
call to StringToInt64.  The SetupFilter() above also isn't terribly interesting,
but if we're concerned about reading a single header or two, makes sense to
cover that one, too (Or cover both with one tracker).

[asanka, 2014-10-31 18:01:41]

+1 to Matt's concerns. Are you also instrumenting the common
URLRequest::Delegates? In particular I don't see any instrumentation on
ResourceLoader which would be one of the primary suspects.

[mmenke, 2014-10-31 18:21:26]

On 2014/10/31 18:01:41, asanka wrote:
> +1 to Matt's concerns. Are you also instrumenting the common
> URLRequest::Delegates? In particular I don't see any instrumentation on
> ResourceLoader which would be one of the primary suspects.

I agree that the URLRequest::Delegate / ResourceLoader (and possibly the
[Chrome]NetworkDelegate) are almost certainly the problem here.  I'm not sure
instrumenting the ResourceLoader itself will get us much (Other than showing it
isn't the ResourceFetcherImplCore that's the problem).  The issue is most likely
with ResourceHandlers/ResourceThrottles.  If we want to know which of those is
the issue, We should instrument the ResourceThrottleHandler (All throttles have
IDs, so we should be able to include the ID in the string we report the timing
for), and the individual ResourceHandlers.

[mmenke, 2014-10-31 18:23:55]

On 2014/10/31 18:21:26, mmenke wrote:
> On 2014/10/31 18:01:41, asanka wrote:
> > +1 to Matt's concerns. Are you also instrumenting the common
> > URLRequest::Delegates? In particular I don't see any instrumentation on
> > ResourceLoader which would be one of the primary suspects.
> 
> I agree that the URLRequest::Delegate / ResourceLoader (and possibly the
> [Chrome]NetworkDelegate) are almost certainly the problem here.  I'm not sure
> instrumenting the ResourceLoader itself will get us much (Other than showing
it
> isn't the ResourceFetcherImplCore that's the problem).  The issue is most
likely
> with ResourceHandlers/ResourceThrottles.  If we want to know which of those is
> the issue, We should instrument the ResourceThrottleHandler (All throttles
have
> IDs, so we should be able to include the ID in the string we report the timing
> for), and the individual ResourceHandlers.

Err...ResourceFetcherImplCore -> URLFetcherImplCore

[vadimt, 2014-10-31 23:38:33]

I added some changes (it took 3 patches).

I instrumented calls to virtual calls of URLRequest::Delegate and
NetworkDelegate. AFAUI, the rest that you mentioned is invoked from the
overrides.

My plan is to figure out which virtual call is/are the most offensive, and then
drill into the specific call with the next iteration of instrumentation.

Should I remove the instrumentations that I originally added in this CL to
url_request_job.cc?

https://codereview.chromium.org/696483002/diff/1/net/url_request/url_request_...
File net/url_request/url_request_job.cc (right):

https://codereview.chromium.org/696483002/diff/1/net/url_request/url_request_...
net/url_request/url_request_job.cc:331: tracked_objects::ScopedTracker
tracking_profile1(
On 2014/10/31 16:52:15, mmenke wrote:
> Could we get some docs on this class?  I have no idea what it does, or how
> results from this show up.  Depending on the answer to that, the arrangement
of
> some of these may be in need of work.

Done.

[mmenke, 2014-11-03 16:19:15]

https://codereview.chromium.org/696483002/diff/60001/base/profiler/scoped_tra...
File base/profiler/scoped_tracker.h (right):

https://codereview.chromium.org/696483002/diff/60001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:29: // tasks.
Ahh...This is the important detail I was really concerned about.

https://codereview.chromium.org/696483002/diff/60001/net/url_request/url_requ...
File net/url_request/url_request_job.cc (right):

https://codereview.chromium.org/696483002/diff/60001/net/url_request/url_requ...
net/url_request/url_request_job.cc:330: // TODO(vadimt): Remove ScopedTracker
below once crbug.com/423948 is fixed.
Do you really mean to keep this in that long?  I'm not expecting an easy fix to
this, and I'm not sure we want to keep all this extra stuff around too long -
seems like we can figure out what's slow, then remove those that track
everything that's fast enough that we don't care.

If that's the actual plan, just say so, no need to update comments to reflect
that.

https://codereview.chromium.org/696483002/diff/60001/net/url_request/url_requ...
net/url_request/url_request_job.cc:421: "423948
URLRequestJob::NotifyHeadersComplete 9"));
I'd argue one just above "has_handled_response_ = true;" makes more sense than
one here - SetupFilter is presumably about as heavy weight than the code here,
since this just looks for on header, and converts a string to an integer, while
SetupFilter looks for one header and does some more work on top of that.

More importantly, that subtracts out time from "423948
URLRequestJob::NotifyHeadersComplete 2", so it's clearer just what it
contains...Which is, admittedly, not a whole lot.

[vadimt, 2014-11-04 01:04:23]

Addressed comments + rebase.

https://codereview.chromium.org/696483002/diff/60001/net/url_request/url_requ...
File net/url_request/url_request_job.cc (right):

https://codereview.chromium.org/696483002/diff/60001/net/url_request/url_requ...
net/url_request/url_request_job.cc:330: // TODO(vadimt): Remove ScopedTracker
below once crbug.com/423948 is fixed.
Yes, it's perfectly OK not not wait till the issue is solved. It's enough to
diagnose it, and then remove all instrumentations, perhaps, except the one
around the slow place.

It's not quite clear what you mean by "no need to update comments". These TODO
comments include the bug number, which lets us to find the instrumentations that
need to be removed for a given bug. This is necessary, since there are several
parallel investigations in progress.

https://codereview.chromium.org/696483002/diff/60001/net/url_request/url_requ...
net/url_request/url_request_job.cc:421: "423948
URLRequestJob::NotifyHeadersComplete 9"));
Moved the instrumentation up.

[mmenke, 2014-11-04 19:50:13]

LGTM

https://codereview.chromium.org/696483002/diff/60001/net/url_request/url_requ...
File net/url_request/url_request_job.cc (right):

https://codereview.chromium.org/696483002/diff/60001/net/url_request/url_requ...
net/url_request/url_request_job.cc:330: // TODO(vadimt): Remove ScopedTracker
below once crbug.com/423948 is fixed.
On 2014/11/04 01:04:23, vadimt wrote:
> Yes, it's perfectly OK not not wait till the issue is solved. It's enough to
> diagnose it, and then remove all instrumentations, perhaps, except the one
> around the slow place.
> 
> It's not quite clear what you mean by "no need to update comments". These TODO
> comments include the bug number, which lets us to find the instrumentations
that
> need to be removed for a given bug. This is necessary, since there are several
> parallel investigations in progress.
> 

I mean your TODO about when you're going to remove it is inaccurate, per my
question, but updating it to be accurate is probably more effort than it's
worth.

[vadimt, 2014-11-04 20:06:20]

mark@, please review changes in base/

[vadimt, 2014-11-04 20:08:07]

vadimt@chromium.org changed reviewers:
+ mark@chromium.org

[vadimt, 2014-11-04 20:08:08]

mark@chromium.org: Please review changes in base

[vadimt, 2014-11-04 20:08:10]

mark@chromium.org: Please review changes in base

[Mark Mentovai, 2014-11-04 20:53:42]

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
File base/profiler/scoped_tracker.h (right):

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:26: // 2. That task extends from the object's
constructor to its destructor
I had to read this a few times to make maximum sense of it. Instead of “that
task extends,” how about “that task’s lifetime extends?”

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:31: // 4. Task creation that this class utilizes
was highly optimized by jar@.
Only if jar is OK being called out by name.

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:36: // performance problems, after which the
instrumentation has to be removed.
Make this stronger: “has to be”→“must”.

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:37: // However, in rare cases it might be added
permanently, as an exception.
This is kind of wishy-washy. If there are cases where you envision exceptions
being made, you should provide guidance here. Otherwise, you should remove this
sentence, which basically leaves it up to future discretion anyway.

[vadimt, 2014-11-04 21:11:14]

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
File base/profiler/scoped_tracker.h (right):

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:26: // 2. That task extends from the object's
constructor to its destructor
On 2014/11/04 20:53:41, Mark Mentovai wrote:
> I had to read this a few times to make maximum sense of it. Instead of “that
> task extends,” how about “that task’s lifetime extends?”

Done.

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:31: // 4. Task creation that this class utilizes
was highly optimized by jar@.
On 2014/11/04 20:53:41, Mark Mentovai wrote:
> Only if jar is OK being called out by name.

Done.

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:36: // performance problems, after which the
instrumentation has to be removed.
On 2014/11/04 20:53:42, Mark Mentovai wrote:
> Make this stronger: “has to be”→“must”.

Done.

https://codereview.chromium.org/696483002/diff/80001/base/profiler/scoped_tra...
base/profiler/scoped_tracker.h:37: // However, in rare cases it might be added
permanently, as an exception.
Let's remove for now. If I or someone else wants to leave an instrumentation, we
can revisit this rule later.

[Mark Mentovai, 2014-11-04 21:19:43]

LGTM in base.

[vadimt, 2014-11-04 21:23:47]

The CQ bit was checked by vadimt@chromium.org

[commit-bot: I haz the power, 2014-11-04 21:25:42]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/696483002/100001

[commit-bot: I haz the power, 2014-11-04 22:56:12]

Committed patchset #6 (id:100001)

[commit-bot: I haz the power, 2014-11-04 22:56:50]

Patchset 6 (id:??) landed as
https://crrev.com/844c155753d7e42619a437ef6f3036aaf466e140
Cr-Commit-Position: refs/heads/master@{#302694}