Add fine grain tracing to HostResolverImpl....

Add fine grain tracing to HostResolverImpl.

This will help in diagnosing the "slow resolving host" bugs.

Users can now click an "Enable tracing" button on "chrome://net-internals/hostresolver".
This logs detailed information on the DNS requests flowing through the browser (when they were received, when they were posted to the thread pool, when they started running on the worker thread, etc...).

BUG=12754
Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=37776

[willchan no longer on Chromium, 2010-02-01 19:31:00]

Looks good to me, although I raise two questions.  I leave it up to you whether
or not you want to address them.  If you do, then I will take another look
again.  Otherwise, feel free to submit as is if you want.

http://codereview.chromium.org/556094/diff/5001/5004
File net/base/host_resolver.h (right):

http://codereview.chromium.org/556094/diff/5001/5004#newcode159
net/base/host_resolver.h:159: virtual bool IsHostResolverImpl() { return false;
}
My first gut reaction was "ew".  This looks ugly.  I see now that you need it in
URLRequestViewNetInternalsJob.  That is unfortunate.  I don't know how the
URLRequestViewNetInternalsJob code is hooked in, but my impression is that we
should only register the fine tracing stuff if we know that we're using the
HostResolverImpl.  So at the point where we decide (which is in IOThread when we
create the host resolver), we can also register the fine tracing stuff in
URLRequestViewNetInternalsJob.  I'm not sure if this is a reasonable approach. 
That's just my gut instinct of how this should work because I don't like to have
this cheapo re-implementation of RTTI.  That said, doing my solution might be
impractical or too much effort to be worth the gain.  So if you don't think my
suggestion works, then I'd be ok letting this go in.  I just think it's ugly,
but sometimes the uglier solution is good enough (and it doesn't look likely to
be abused further, at least I hope).

http://codereview.chromium.org/556094/diff/5001/5006
File net/base/host_resolver_impl.cc (right):

http://codereview.chromium.org/556094/diff/5001/5006#newcode160
net/base/host_resolver_impl.cc:160: void Add(const std::string& msg) {
I don't care too much, but my impression is that we generally avoid locking.  It
looks like the reason you have it here is because multiple worker threads may be
trying to write to this while the IOThread may be reading/writing it.  It seems
like another way of doing it is having the worker threads do
origin_loop_->PostTask instead of locking.  Is there a worry of incorrect
ordering of the log messages or something that led you to use Locks instead?

http://codereview.chromium.org/556094/diff/5001/5006#newcode212
net/base/host_resolver_impl.cc:212: if (requests_trace_) {
No need for the braces

[eroman, 2010-02-01 20:31:25]

Thanks for the review.

http://codereview.chromium.org/556094/diff/5001/5004
File net/base/host_resolver.h (right):

http://codereview.chromium.org/556094/diff/5001/5004#newcode159
net/base/host_resolver.h:159: virtual bool IsHostResolverImpl() { return false;
}
On 2010/02/01 19:31:01, willchan wrote:
> My first gut reaction was "ew".  This looks ugly.  I see now that you need it
in
> URLRequestViewNetInternalsJob.  That is unfortunate.  I don't know how the
> URLRequestViewNetInternalsJob code is hooked in, but my impression is that we
> should only register the fine tracing stuff if we know that we're using the
> HostResolverImpl.  So at the point where we decide (which is in IOThread when
we
> create the host resolver), we can also register the fine tracing stuff in
> URLRequestViewNetInternalsJob.  I'm not sure if this is a reasonable approach.

> That's just my gut instinct of how this should work because I don't like to
have
> this cheapo re-implementation of RTTI.  That said, doing my solution might be
> impractical or too much effort to be worth the gain.  So if you don't think my
> suggestion works, then I'd be ok letting this go in.  I just think it's ugly,
> but sometimes the uglier solution is good enough (and it doesn't look likely
to
> be abused further, at least I hope).

I agree that this is ugly. Here is my justification.

Previously, we had this GetCache() virtual method on the HostResolver interface,
which was basically the same sort of hack but narrower in scope. Everything
except HostResolverImpl would return NULL. URLRequestViewNetInternalsJob and the
"flush cache when leaving incognito mode" were the only consumers of this.

So now when I wanted to add more stuff (for the tracing), it felt wrong to force
them into the base interface in the same manner, since then HostResolver becomes
bloated. 

I am not too excited about a registration based system (setting up the
URLRequestViewNetInternalsJob to "know" what the host resolver is), since it
doesn't address the incognito consumer (unless that too were to use the
registration paradigm), and it makes it more difficult to swap host resolvers at
runtime.

In the spirit of expediency, I am inclined to leave this as is. But I will
definitely interested in finding a better solution, and will give it more
thought.

http://codereview.chromium.org/556094/diff/5001/5006
File net/base/host_resolver_impl.cc (right):

http://codereview.chromium.org/556094/diff/5001/5006#newcode160
net/base/host_resolver_impl.cc:160: void Add(const std::string& msg) {
On 2010/02/01 19:31:01, willchan wrote:
> I don't care too much, but my impression is that we generally avoid locking. 
It
> looks like the reason you have it here is because multiple worker threads may
be
> trying to write to this while the IOThread may be reading/writing it.  It
seems
> like another way of doing it is having the worker threads do
> origin_loop_->PostTask instead of locking.  Is there a worry of incorrect
> ordering of the log messages or something that led you to use Locks instead?

Since the locking is *only* going to be used in cases where DNS tracing is
enabled, and the lock duration is very short, I don't think this is going to be
much of an issue.

I prefer locking to message posting, since it is simple (and i don't want the
logging code to add more complexity).

I added the logging in the worker thread, since we have seen cases of suspected
worker pool starvation (in particular on mac). By logging the start/end on this
thread, we can see when the job really starts running.

[willchan no longer on Chromium, 2010-02-01 21:27:33]

Ok, just wanted to respond to your comments for posterity's sake, but everything
still LGTM.

http://codereview.chromium.org/556094/diff/5001/5004
File net/base/host_resolver.h (right):

http://codereview.chromium.org/556094/diff/5001/5004#newcode159
net/base/host_resolver.h:159: virtual bool IsHostResolverImpl() { return false;
}
On 2010/02/01 20:31:25, eroman wrote:
> On 2010/02/01 19:31:01, willchan wrote:
> > My first gut reaction was "ew".  This looks ugly.  I see now that you need
it
> in
> > URLRequestViewNetInternalsJob.  That is unfortunate.  I don't know how the
> > URLRequestViewNetInternalsJob code is hooked in, but my impression is that
we
> > should only register the fine tracing stuff if we know that we're using the
> > HostResolverImpl.  So at the point where we decide (which is in IOThread
when
> we
> > create the host resolver), we can also register the fine tracing stuff in
> > URLRequestViewNetInternalsJob.  I'm not sure if this is a reasonable
approach.
> 
> > That's just my gut instinct of how this should work because I don't like to
> have
> > this cheapo re-implementation of RTTI.  That said, doing my solution might
be
> > impractical or too much effort to be worth the gain.  So if you don't think
my
> > suggestion works, then I'd be ok letting this go in.  I just think it's
ugly,
> > but sometimes the uglier solution is good enough (and it doesn't look likely
> to
> > be abused further, at least I hope).
> 
> I agree that this is ugly. Here is my justification.
> 
> Previously, we had this GetCache() virtual method on the HostResolver
interface,
> which was basically the same sort of hack but narrower in scope. Everything
> except HostResolverImpl would return NULL. URLRequestViewNetInternalsJob and
the
> "flush cache when leaving incognito mode" were the only consumers of this.
> 
> So now when I wanted to add more stuff (for the tracing), it felt wrong to
force
> them into the base interface in the same manner, since then HostResolver
becomes
> bloated. 
> 
> I am not too excited about a registration based system (setting up the
> URLRequestViewNetInternalsJob to "know" what the host resolver is), since it
> doesn't address the incognito consumer (unless that too were to use the
> registration paradigm), and it makes it more difficult to swap host resolvers
at
> runtime.

Yes, I'd imagine the incognito consumer would have to know too.  I agree this
solution isn't exactly pretty either.

> 
> In the spirit of expediency, I am inclined to leave this as is. But I will
> definitely interested in finding a better solution, and will give it more
> thought.

Sounds fine to me.

http://codereview.chromium.org/556094/diff/5001/5006
File net/base/host_resolver_impl.cc (right):

http://codereview.chromium.org/556094/diff/5001/5006#newcode160
net/base/host_resolver_impl.cc:160: void Add(const std::string& msg) {
On 2010/02/01 20:31:25, eroman wrote:
> On 2010/02/01 19:31:01, willchan wrote:
> > I don't care too much, but my impression is that we generally avoid locking.

> It
> > looks like the reason you have it here is because multiple worker threads
may
> be
> > trying to write to this while the IOThread may be reading/writing it.  It
> seems
> > like another way of doing it is having the worker threads do
> > origin_loop_->PostTask instead of locking.  Is there a worry of incorrect
> > ordering of the log messages or something that led you to use Locks instead?
> 
> Since the locking is *only* going to be used in cases where DNS tracing is
> enabled, and the lock duration is very short, I don't think this is going to
be
> much of an issue.

I agree the performance isn't an issue.

> 
> I prefer locking to message posting, since it is simple (and i don't want the
> logging code to add more complexity).

I can see a counter-argument where most of our code uses message passing, so a
mutex-based approach is inconsistent and thus more confusing.  I agree that in
terms of this single change the locking approach is simpler.

> 
> I added the logging in the worker thread, since we have seen cases of
suspected
> worker pool starvation (in particular on mac). By logging the start/end on
this
> thread, we can see when the job really starts running.

I'm not sure I understand why message passing doesn't work for what you describe
here.  You could have a easily have a LoadLog::AddStringAtTime() function, so
that the timeticks delay between the posting of the task and its actual running
does not get recorded, since the current time would be passed as a parameter.

[eroman, 2010-02-01 22:43:02]

> I'm not sure I understand why message passing doesn't work 
> for what you describe here. 

Message passing is certainly workable, but more complicated.

Reconstituting the correct order isn't too bad, but properly handling
cancellation semantics is hairier. Since worker threads (may) outlive the IO
thread, you need to be careful to test for cancellation using a lock before
trying to post back to log on IO thread.

[willchan no longer on Chromium, 2010-02-01 22:48:46]

On Mon, Feb 1, 2010 at 2:43 PM,  <eroman@chromium.org> wrote:
>> I'm not sure I understand why message passing doesn't work
>> for what you describe here.
>
> Message passing is certainly workable, but more complicated.
>
> Reconstituting the correct order isn't too bad, but properly handling
> cancellation semantics is hairier. Since worker threads (may) outlive the IO
> thread, you need to be careful to test for cancellation using a lock before
> trying to post back to log on IO thread.

Ah, point well taken.  Thanks for the explanation.

>
> http://codereview.chromium.org/556094
>