Update NetLog to be thread safe.

Update NetLog to be threadsafe.

The ChromeNetLog is now owned by the browser process,
and passed to the IOThread on creation.

NetLog entries can be added from any thread.

Observers must be able to handle having log entries added
from any thread.  Observers can add/remove themselves on any
thread.

BUG=63334
TEST=None, yet


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

[mmenke, 2010-10-28 17:58:39]

Just wanted to see what you thought of this before I continue to work on it:  A
bunch of unittests would have to be updated.  I also feel I should replace all
the NetLog* parameter passing to "const scoped_refptr<NetLog>&", to make it
clear that naked NetLog pointers should no longer be kept around like before,
but there seems to be some divergence of opinion on that.


Other than reference counting (And a few other atomic operations), the only
performance impact of logging events from the IO thread is the lock and thread
local storage access used by BrowserThread::CurrentlyOn().

It's possible to get rid of the lock either by modifying
BrowserThread::CurrentlyOn() to use thread local storage, or to have the browser
thread call some function when it's destroyed, setting some Atomic32 variable in
response (Could delete the observers owned by the NetLog there, too, so we'd
always delete them on the browser thread, though it looks like they don't care
much about where they're destroyed).

[mmenke, 2010-10-29 19:56:06]

Think I'll break this up into two CLs...one for the thread safety, another for
putting the scoped pointers everywhere.  Hadn't realized quite how many files
this touched.

[eroman, 2010-10-29 21:49:00]

[+willchan] for his take on the use of refcounting.

Some initial high-level comments:

- I am not sure it is desirable to make net-log refcounted (explicit
cancellation during shutdown could avoid threads holding lingering pointers to
netlog).

- You should be able to use the ThreadSafeObserverList class in ChromeNetLog --
it will remove the restriction that observers must be registered/removed on the
IO thread, by re-broadcasting to the message loop that introduced the observer.

- I think we can do something fancier with respect to the event ordering. As I
understand the CL currently, the javascript (and other ChromeNetLog::Observers)
can receive events out of order if events were emitted from different threads.
To handle this you have introduced checks at each place that processes the event
stream to re-position events which are clearly out of order. (This repositioning
is done using the event's timestamp.)

What I don't like about this is approach is that
(a) timestamps are not guaranteed unique so it may not be possible to rebuild
exact ordering
(b) it adds implementation complexity to each consumer of the netlog event
stream (needing to know events may be slightly out of order in some cases).

I think we can address this a little more globally on the C++ side of things in
ChromeNetLog, in order to _guarantee_ that the javascript (and any other
ChromeNetLog::Observer) is only fed events in the chronological order.

Here is what I am thinking:

(1) Associate a sequence number with each event. In other words, when
ChromeNetLog::AddEntry() is called do an atomic increment on a sequence number
counter. Now post a task to run ChromeNetLog::AddEntryFromIOThread() (or call it
directly if we are currently on the IO thread).

(2) When we receive events through ChromeNetLog::AddEntryFromIOThread(), they
have a sequence number associated with them. In the ordinary case, this sequence
number is one greater than what we saw earlier, so we can simply broadcast it to
the observers. Sweet. However n the uncommon case, this number will be greater
than the previously seen sequence numbering, implying there is an event waiting
to reach the IO thread which preceded the currently received one. In such case,
we will buffer the events until the earlier ones are received. (up to some limit
in case things go horribly wrong).

(3) As an extra, we can add this sequence number to the JSON format we feed the
renderer. This should be useful for the javascript, since it should allow us to
simplify the sorting logic we have for sources (i.e. the special casing we use
for sources without an ID).

What do you think?

[willchan no longer on Chromium, 2010-10-30 00:53:30]

<caveat> I haven't read any of the code yet </caveat>

I think that making NetLog be threadsafe is possibly a good thing.  I don't
like having to post to the IO thread to update it.  Logging seems like a
type of functionality that should just be threadsafe.  Especially if we want
to extend this past the IO thread.  But I am not as familiar wrt the DOMUI
reading of it.

I don't want to refcount NetLog.  If you need more explanation here, let me
know.  But I dislike refcounting.  NetLog sounds like something whose
lifetime we understand.  If it's networking only, it should strictly be
bound to the IO thread's lifetime.  If it's process wide, then it should
last as long as the process.  Anyhow, that's my thought for now.

I defer to Eric generally here, but if there's more discussion about
refcounting, then I will educate myself about the details and will try to
fight refcounting.

On Fri, Oct 29, 2010 at 2:49 PM, <eroman@chromium.org> wrote:

> [+willchan] for his take on the use of refcounting.
>
> Some initial high-level comments:
>
> - I am not sure it is desirable to make net-log refcounted (explicit
> cancellation during shutdown could avoid threads holding lingering pointers
> to
> netlog).
>
> - You should be able to use the ThreadSafeObserverList class in
> ChromeNetLog --
> it will remove the restriction that observers must be registered/removed on
> the
> IO thread, by re-broadcasting to the message loop that introduced the
> observer.
>
> - I think we can do something fancier with respect to the event ordering.
> As I
> understand the CL currently, the javascript (and other
> ChromeNetLog::Observers)
> can receive events out of order if events were emitted from different
> threads.
> To handle this you have introduced checks at each place that processes the
> event
> stream to re-position events which are clearly out of order. (This
> repositioning
> is done using the event's timestamp.)
>
> What I don't like about this is approach is that
> (a) timestamps are not guaranteed unique so it may not be possible to
> rebuild
> exact ordering
> (b) it adds implementation complexity to each consumer of the netlog event
> stream (needing to know events may be slightly out of order in some cases).
>
> I think we can address this a little more globally on the C++ side of
> things in
> ChromeNetLog, in order to _guarantee_ that the javascript (and any other
> ChromeNetLog::Observer) is only fed events in the chronological order.
>
> Here is what I am thinking:
>
> (1) Associate a sequence number with each event. In other words, when
> ChromeNetLog::AddEntry() is called do an atomic increment on a sequence
> number
> counter. Now post a task to run ChromeNetLog::AddEntryFromIOThread() (or
> call it
> directly if we are currently on the IO thread).
>
> (2) When we receive events through ChromeNetLog::AddEntryFromIOThread(),
> they
> have a sequence number associated with them. In the ordinary case, this
> sequence
> number is one greater than what we saw earlier, so we can simply broadcast
> it to
> the observers. Sweet. However n the uncommon case, this number will be
> greater
> than the previously seen sequence numbering, implying there is an event
> waiting
> to reach the IO thread which preceded the currently received one. In such
> case,
> we will buffer the events until the earlier ones are received. (up to some
> limit
> in case things go horribly wrong).
>
> (3) As an extra, we can add this sequence number to the JSON format we feed
> the
> renderer. This should be useful for the javascript, since it should allow
> us to
> simplify the sorting logic we have for sources (i.e. the special casing we
> use
> for sources without an ID).
>
> What do you think?
>
>
> http://codereview.chromium.org/4118004/show
>

[mmenke, 2010-11-01 19:27:20]

- I'm not overly fond of the idea of ref counting the NetLog, but I'm not sure
there's a better solution.

We might not event know about events on other threads we'd need to cancel.  If
the disk cache is busy cleaning up a disk cache entry, I believe we may have
already deleted all references to it in the network stack, and just have a
pending operation to delete the entry on the CACHE thread (which outlives the IO
thread).  I suspect we'd encounter similar issues elsewhere.  I'm not sure the
redesign is worth the cost.

- The reason I didn't make it safe to have on observer on any thread is because
I wasn't sure about overhead of the extra message passing to handle events on
different threads.  If this isn't going to be a problem, ObserverListThreadSafe
is definitely the way to go.

- Assigning a unique id to each event seems like a reasonable approach.  The one
thing I don't like about it is that there is no guarantee the ids we assign have
non-decreasing times.  That is, an event at time 1000 could end up with a lower
id than an event at time 999.  This most likely would be quite rare, and I don't
believe it would cause any serious issues for the net-internals code, if we
ignored it entirely but it is rather counter-intuitive.

I went with sorting by time in the Javascript code to avoid that issue.  My code
has this issue that events may appear out of order, though if modified to use
ObserverListThreadSafe, events that are dependent on one another should always
appear in order (Current code already has this property  as long as message
passing is used instead of locks to wait for an event).

The only solution to both issues that I can think of is to use a lock, and get
the time and dispatch the event (Or assign a unique id) while we have the lock. 
If we're dispatching to Observers' message loops anyways, this may be the best
way to go.  Then we won't need the ID for each event, but it would probably be
convenient to add one, anyways, for the reason you state.

[mmenke, 2010-11-01 19:32:54]

One other potential issue with the ObserverListThreadSafe - we'd lose events on
quit.  The IO thread processes no new messages once it starts to close, so we
wouldn't get any more NetLog events related to cleanup.  Would have to be
outputting the NetLog to the LOG to see those messages, anyways, of course, but
we'd lose the ability if we used ObserverListThreadSafe, unless we moved the
NetLog to a longer-lived thread.

On 2010/11/01 19:27:20, Matt Menke wrote:
> - I'm not overly fond of the idea of ref counting the NetLog, but I'm not sure
> there's a better solution.
> 
> We might not event know about events on other threads we'd need to cancel.  If
> the disk cache is busy cleaning up a disk cache entry, I believe we may have
> already deleted all references to it in the network stack, and just have a
> pending operation to delete the entry on the CACHE thread (which outlives the
IO
> thread).  I suspect we'd encounter similar issues elsewhere.  I'm not sure the
> redesign is worth the cost.
> 
> - The reason I didn't make it safe to have on observer on any thread is
because
> I wasn't sure about overhead of the extra message passing to handle events on
> different threads.  If this isn't going to be a problem,
ObserverListThreadSafe
> is definitely the way to go.
> 
> - Assigning a unique id to each event seems like a reasonable approach.  The
one
> thing I don't like about it is that there is no guarantee the ids we assign
have
> non-decreasing times.  That is, an event at time 1000 could end up with a
lower
> id than an event at time 999.  This most likely would be quite rare, and I
don't
> believe it would cause any serious issues for the net-internals code, if we
> ignored it entirely but it is rather counter-intuitive.
> 
> I went with sorting by time in the Javascript code to avoid that issue.  My
code
> has this issue that events may appear out of order, though if modified to use
> ObserverListThreadSafe, events that are dependent on one another should always
> appear in order (Current code already has this property  as long as message
> passing is used instead of locks to wait for an event).
> 
> The only solution to both issues that I can think of is to use a lock, and get
> the time and dispatch the event (Or assign a unique id) while we have the
lock. 
> If we're dispatching to Observers' message loops anyways, this may be the best
> way to go.  Then we won't need the ID for each event, but it would probably be
> convenient to add one, anyways, for the reason you state.

[willchan no longer on Chromium, 2010-11-01 19:40:01]

On Mon, Nov 1, 2010 at 7:27 PM, <mmenke@chromium.org> wrote:

> - I'm not overly fond of the idea of ref counting the NetLog, but I'm not
> sure
> there's a better solution.
>
> We might not event know about events on other threads we'd need to cancel.
>  If
> the disk cache is busy cleaning up a disk cache entry, I believe we may
> have
> already deleted all references to it in the network stack, and just have a
> pending operation to delete the entry on the CACHE thread (which outlives
> the IO
> thread).  I suspect we'd encounter similar issues elsewhere.  I'm not sure
> the
> redesign is worth the cost.
>

Why does the cache thread outlive the IO thread?  I'm pretty sure Ricardo or
whoever had a reason, but I think it's something we can revisit and change.
 What other threads do we need to worry about?  DNS worker threads?  I think
those do not log right now, we only log on the IO thread for DNS.  Can we do
a similar thing for the cache?


>
> - The reason I didn't make it safe to have on observer on any thread is
> because
> I wasn't sure about overhead of the extra message passing to handle events
> on
> different threads.  If this isn't going to be a problem,
> ObserverListThreadSafe
> is definitely the way to go.
>
> - Assigning a unique id to each event seems like a reasonable approach.
>  The one
> thing I don't like about it is that there is no guarantee the ids we assign
> have
> non-decreasing times.  That is, an event at time 1000 could end up with a
> lower
> id than an event at time 999.  This most likely would be quite rare, and I
> don't
> believe it would cause any serious issues for the net-internals code, if we
> ignored it entirely but it is rather counter-intuitive.
>
> I went with sorting by time in the Javascript code to avoid that issue.  My
> code
> has this issue that events may appear out of order, though if modified to
> use
> ObserverListThreadSafe, events that are dependent on one another should
> always
> appear in order (Current code already has this property  as long as message
> passing is used instead of locks to wait for an event).
>
> The only solution to both issues that I can think of is to use a lock, and
> get
> the time and dispatch the event (Or assign a unique id) while we have the
> lock.
> If we're dispatching to Observers' message loops anyways, this may be the
> best
> way to go.  Then we won't need the ID for each event, but it would probably
> be
> convenient to add one, anyways, for the reason you state.
>
>
> http://codereview.chromium.org/4118004/show
>

[eroman, 2010-11-01 20:03:47]

Hi Matt, thanks for your comment responses.

You are right, if we added IDs in ChromeNetLog::AddEntry they may not be
consistent with the timestamps (since the timestamps are generated earlier).

Hmm, threadsafety is gnarly indeed :-)

So I have been thinking about this design some more, and I think thread-safe
observers may be the most viable solution.

Your current proposal posts any event generated off the IO thread, to the IO
thread.

The nice thing about this design is it keeps the observers simple since by not
requiring them to be thread safe.

My concern is the performance impact this might have.

If we were to log say 60 messages on the cache thread, then that would cause a
flurry of 60 message loop tasks on the IO thread. This won't scale nicely as
more logging is done off the IO thread, since afterall we expect logging to be
cheap (at least the passive side).

I propose instead forcing ALL the ChromeNetLog::Observers to be threadsafe, and
calling them directly on the source thread.

This would mean the PassiveLogCollector would have to protect access to its data
using a lock, but shouldn't be too bad.

(And the other observers would need other changes to make them threadsafe too.)

WDYT?

[mmenke, 2010-11-01 21:55:11]

willchan:

I'll look into why the cache thread is destroyed before the IO thread.  I don't
think the DNS worker threads need any logging, since they're pretty simple,
though there's been at least some talk of using other DNS servers when the main
one's down, and that probably could use some logging, if ever done, so I'll at
least take a look at them.

It's also been suggested that NetLog be expanded to include more than just
network events (http://crbug.com/30802).


eroman:

I think that makes sense.  It does have the issue that unless we do something
more on the NetLog side, each Observer can theoretically get events in a
different order.  We could use a lock to get around that, but not sure it's
worth the effort.  And we'd still have the issue of event order/timestamp
ordering inconsistencies.  Maybe we should just ignore such issues unless they
end up being a problem.

Removing observers becomes a little complicated, though.  If we remove an
observer while dealing with a message, Bad things would happen...  So I guess
that means ChromeNetLog would have to use locks on events, too.  Some Observers
might not even have to use them, in that case.

There's still the issue of when/where/how the NetLog should be destroyed.  Your
proposal makes that a bit less complicated, in that we don't have to worry about
being able to receive messages.  Could even just make it a Singleton, I suppose.

[willchan no longer on Chromium, 2010-11-01 22:19:25]

On Mon, Nov 1, 2010 at 9:55 PM, <mmenke@chromium.org> wrote:

> willchan:
>
> I'll look into why the cache thread is destroyed before the IO thread.  I
> don't
> think the DNS worker threads need any logging, since they're pretty simple,
> though there's been at least some talk of using other DNS servers when the
> main
> one's down, and that probably could use some logging, if ever done, so I'll
> at
> least take a look at them.
>

I asked Ricardo.  The cache thread has a strictly greater lifetime than the
IO thread to ensure that it's alive for anything the IO thread could do.
 This is probably done because we use BrowserThread for it.  If not, we
could just make the cache thread be a member of HttpCache or the BackendImpl
(I'm not sure which is more appropriate).  It seems the reason it's a
BrowserThread is so that ChromeAppCacheService can share the thread.  I
somewhat doubt this is strictly necessary.  I suspect it was more of "hey,
we're both doing caching, why don't we share the same thread?".


>
> It's also been suggested that NetLog be expanded to include more than just
> network events (http://crbug.com/30802).
>

Ok.  This doesn't mean it needs to be refcounted.  It just means we need to
make sure the lifetime is appropriate.  We could create it on the main
process thread (the UI thread) and have it be deleted on exit from
BrowserMain().  Of course, any thread that lives past BrowserMain (like a
worker thread) would not be allowed to write to the NetLog.  That seems
reasonable for now.


>
>
> eroman:
>
> I think that makes sense.  It does have the issue that unless we do
> something
> more on the NetLog side, each Observer can theoretically get events in a
> different order.  We could use a lock to get around that, but not sure it's
> worth the effort.  And we'd still have the issue of event order/timestamp
> ordering inconsistencies.  Maybe we should just ignore such issues unless
> they
> end up being a problem.
>
> Removing observers becomes a little complicated, though.  If we remove an
> observer while dealing with a message, Bad things would happen...  So I
> guess
> that means ChromeNetLog would have to use locks on events, too.  Some
> Observers
> might not even have to use them, in that case.
>
> There's still the issue of when/where/how the NetLog should be destroyed.
>  Your
> proposal makes that a bit less complicated, in that we don't have to worry
> about
> being able to receive messages.  Could even just make it a Singleton, I
> suppose.


I prefer not using Singleton unless we have to.  It's usually the wrong
thing to do.


>
>
> http://codereview.chromium.org/4118004/show
>

[willchan no longer on Chromium, 2010-11-01 22:23:55]

On Mon, Nov 1, 2010 at 8:03 PM, <eroman@chromium.org> wrote:

> Hi Matt, thanks for your comment responses.
>
> You are right, if we added IDs in ChromeNetLog::AddEntry they may not be
> consistent with the timestamps (since the timestamps are generated
> earlier).
>
> Hmm, threadsafety is gnarly indeed :-)
>
> So I have been thinking about this design some more, and I think
> thread-safe
> observers may be the most viable solution.
>
> Your current proposal posts any event generated off the IO thread, to the
> IO
> thread.
>
> The nice thing about this design is it keeps the observers simple since by
> not
> requiring them to be thread safe.
>
> My concern is the performance impact this might have.
>
> If we were to log say 60 messages on the cache thread, then that would
> cause a
> flurry of 60 message loop tasks on the IO thread. This won't scale nicely
> as
> more logging is done off the IO thread, since afterall we expect logging to
> be
> cheap (at least the passive side).
>

What is so expensive about 60 tasks on the IO thread?  If the individual
tasks are pretty trivial (which I believe they should be), then 60 tasks are
probably still pretty trivial.


>
> I propose instead forcing ALL the ChromeNetLog::Observers to be threadsafe,
> and
> calling them directly on the source thread.
>

It's not like this means we don't get by the perceived problem with the 60
tasks.  I guess it depends on all the cases, which you guys know better than
I do, but if the source thread is not the IO thread, don't we have to post
the message to the IO thread so it gets sent over IPC to the renderer
process for the net-internals renderer to display?


>
> This would mean the PassiveLogCollector would have to protect access to its
> data
> using a lock, but shouldn't be too bad.
>
> (And the other observers would need other changes to make them threadsafe
> too.)
>
> WDYT?
>
>
> http://codereview.chromium.org/4118004/show
>

[mmenke, 2010-11-01 22:31:43]

On 2010/11/01 22:19:25, willchan wrote:
> Ok.  This doesn't mean it needs to be refcounted.  It just means we need to
> make sure the lifetime is appropriate.  We could create it on the main
> process thread (the UI thread) and have it be deleted on exit from
> BrowserMain().  Of course, any thread that lives past BrowserMain (like a
> worker thread) would not be allowed to write to the NetLog.  That seems
> reasonable for now.

Indeed, creating it on the UI thread seems perfectly reasonable to me, assuming
passing from the UI thread to the IO thread isn't too painful.

I assume the reason for eric's suggestion was two-fold:  We no longer have to
worry which thread handles NetLog entries being added, and we avoid the overhead
of passing lots of messages between threads.  The IPC overhead when
about:net-internals isn't the biggest performance concern - what we're more
worried about is performance when about:net-internals is not showing.  Don't
want to slow things down under normal usage conditions.  That having been said,
I have no idea how much overhead is involved in sending lots of messages around.

[mmenke, 2010-11-12 19:26:48]

I'm still not sure this is the best approach, but here's a pass at requiring the
observers themselves be threadsafe.

It's a little messy, as each observer type has slightly different requirements.

Quick consideration of other methods, now that I'm a bit more familiar with the
other observers:

One alternative is to just use ObserverListThreadSafe, but then we'd have to
handle the observers this does not work with separately.  If it were just
NetLogLogger, which needs to handle shutdown events, this might be reasonable;
however, LoadTimingObserver also needs to handle events immediately, as it's
assumed to have already handled all previous events.  Only other issue we'd have
to worry about is preventing missing entries when net-internals starts, which
becomes non-trivial in this case.

Or we could just have all observers (except a special case for the NetLogLogger)
live on the IO thread, push messages there if we aren't already on the IO
thread, and if we are, call all observers instantly.  Issue here would be out of
order messages, but if we numbered entries, we could sort them as needed...
However, we would have to pass them to observers in the order they arrive on the
IO Thread, to prevent LoadTimingObserver breakage.  This is the simplest route,
but probably the most likely to need revision in the future, as requirements
change.

[eroman, 2010-11-16 17:51:14]

Ooops, forgot to hit publish for my comments! Sry.

Better late then never :-)

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/debugger/de...
File chrome/browser/debugger/devtools_netlog_observer.cc (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/debugger/de...
chrome/browser/debugger/devtools_netlog_observer.cc:61:
BrowserThread::PostTask(BrowserThread::IO,
Can we instead just return immediately if we aren't on the IO thread?

It looks like the only events which the DevToolsNetLogObserver is interested in
anyway are things emitted on the IO thread (i.e. the existing set of events).

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/io_thread.h
File chrome/browser/io_thread.h (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/io_thread.h...
chrome/browser/io_thread.h:49: explicit IOThread(ChromeNetLog* net_log);
Please describe ownership model (i.e. net_log must outlive IOThread, or can be
NULL).

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.cc (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:28: if (net_log) {
Are there any existing cases where this would be NULL?

If not we can probably just avoid this 'if' (to avoid people passing in NULL
each time but then failing to properly update).

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:114: void ChromeNetLog::UpdateLogLevel_() {
Can you call lock_.AssertAcquired() ?

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.h (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:85: void set_log_level(LogLevel log_level,
ChromeNetLog* net_log);
Please rename this to SetLogLevel(). (The hacker_notation() is only for raw
setters/getters).

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:122: // Called whenever an Observer is added
or removed, or changes it log level.
change it log level --> changes its log level.

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:123: // Must have locked |lock_| prior to
calling.
nit: "locked" --> acquired.

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/load_ti...
File chrome/browser/net/load_timing_observer.cc (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/load_ti...
chrome/browser/net/load_timing_observer.cc:69: AutoLock lock(lock_);
I don't believe we need any locking in this class.

Rather, how about just:

if (!BrowserThread::CurrentlyOn(BrowserThread::IO))
  return;

Since it looks like every one of the events this observer is interested in are
generated on the IO thread anyway, so no need to handle those from other
threads.

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/net_log...
File chrome/browser/net/net_log_logger.cc (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/net_log...
chrome/browser/net/net_log_logger.cc:24: LOG(INFO) << json;
Is this change intentional?

http://codereview.chromium.org/4118004/diff/114002/net/base/capturing_net_log.h
File net/base/capturing_net_log.h (right):

http://codereview.chromium.org/4118004/diff/114002/net/base/capturing_net_log...
net/base/capturing_net_log.h:60: void get_entries(EntryList* entry_list) const;
nit: GetEntries

http://codereview.chromium.org/4118004/diff/114002/net/base/capturing_net_log...
net/base/capturing_net_log.h:94: void get_entries(CapturingNetLog::EntryList*
entry_list) const;
GetEntries

[mmenke, 2010-11-16 21:34:48]

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/debugger/de...
File chrome/browser/debugger/devtools_netlog_observer.cc (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/debugger/de...
chrome/browser/debugger/devtools_netlog_observer.cc:61:
BrowserThread::PostTask(BrowserThread::IO,
On 2010/11/16 17:51:14, eroman wrote:
> Can we instead just return immediately if we aren't on the IO thread?
> 
> It looks like the only events which the DevToolsNetLogObserver is interested
in
> anyway are things emitted on the IO thread (i.e. the existing set of events).

I'm not quite sure, actually.  Do we care about the events from the proxy
resolver or not?  They occur on a worker thread and used to use a
ForwardingNetLog, but are now sent to the NetLog directly.

I've done as you suggest, for now, though I'm also a bit concerned about the
non-obvious dependency this creates between this class's implementation and
which threads certain events themselves are logged on.

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.cc (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:28: if (net_log) {
On 2010/11/16 17:51:14, eroman wrote:
> Are there any existing cases where this would be NULL?
> 
> If not we can probably just avoid this 'if' (to avoid people passing in NULL
> each time but then failing to properly update).

Never happens at the moment.  Change made (Description updated to indicate this,
too).

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:114: void ChromeNetLog::UpdateLogLevel_() {
On 2010/11/16 17:51:14, eroman wrote:
> Can you call lock_.AssertAcquired() ?

Done.

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/load_ti...
File chrome/browser/net/load_timing_observer.cc (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/load_ti...
chrome/browser/net/load_timing_observer.cc:69: AutoLock lock(lock_);
On 2010/11/16 17:51:14, eroman wrote:
> I don't believe we need any locking in this class.
> 
> Rather, how about just:
> 
> if (!BrowserThread::CurrentlyOn(BrowserThread::IO))
>   return;
> 
> Since it looks like every one of the events this observer is interested in are
> generated on the IO thread anyway, so no need to handle those from other
> threads.

You're right, this is just me being paranoid about future changes.  Reverted the
file and added the check.  Same reservations as with the DevToolsNetLogObserver,
however.

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/net_log...
File chrome/browser/net/net_log_logger.cc (right):

http://codereview.chromium.org/4118004/diff/114002/chrome/browser/net/net_log...
chrome/browser/net/net_log_logger.cc:24: LOG(INFO) << json;
On 2010/11/16 17:51:14, eroman wrote:
> Is this change intentional?

No.  Had been thinking of it (Though not with this CL), but decided adding a
"-v=1" to "--log-net-log --enable-logging" isn't exactly a big deal.

Change removed.

[eroman, 2010-11-17 05:58:58]

The overall approach looks good, but I do have a number of comments on the
specifics.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
File chrome/browser/dom_ui/net_internals_ui.cc (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:155: // allocated and destroyed on the
UI thread, its methods are expected to be
Could you updating this language to mention the OnEntryAdded?

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:189: // Sends all passive log entries
in |entries| to Javascript handler.
nit: "to the javascript handler" (added "the").

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:616:
io_thread_->net_log()->AddObserverAndGetAllCapturedEvents(this, &entries);
The impact of threading here is fairly subtle.

I don't remember, can you check whether the javascript cares if it receives
active events BEFORE receiving the passively captured events?

I don't think it will matter, but it is worth checking and additionally noting
here that it can happen (although unlikely).

Basically I am thinking that right after we attach the observer and grab the
passively logged entries, the observer might be called on some other thread, and
in turn queue up a task in the UI thread. Then we reach the next line
(SendPassiveLogEntries) which also posts a task to the UI thread, this time to
send the renderer the passively logged entries.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:907: io_thread_->net_log());
indentation is off by one.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:915: net::NetLog::EventParameters*
params) {
Could you add a big comment in this function noting that we could be called from
any thread?

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:916: DCHECK(is_observing_log_);
I wander if we need a memory barrier or something to read the bool (since it
could have been just written on a different thread).

I suggest just deleting this DCHECK to be safe.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/io_thread.cc
File chrome/browser/io_thread.cc (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/io_thread.c...
chrome/browser/io_thread.cc:210: : net_log_(net_log),
I am not sure what the style guide says, but I think intuitively the
superclass's initializer should be first. (i.e. move this below
BrowserProcessSubThread()).

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.cc (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:50: : last_id_(0),
Where is log_level_ initialized? (it may still be accessed even though there are
no observers).

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:56: const CommandLine& command_line =
*CommandLine::ForCurrentProcess();
Just to check -- Since ChromeNetLog is now being constructed in
BrowserProcessImpl(), is it guaranteed taht CommandLine has already been setup
by the time we reach this?

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:88: base::subtle::Atomic32 log_level =
base::subtle::NoBarrier_Load(&log_level_);
I need to buff up on my concurrency... what is the implication between doing it
with/without memory barrier?

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.h (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:30: // TODO(eroman): Move this default
observer out of ChromeNetLog.
Could you do me a favor and delete this comment while you are here? I think it
is stale, as it doesn't make sense to me :)

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:37: struct Entry {
I see, you moved this out of PassiveLogCollector because of
AddObserverAndGetAllCapturedEvents() needing to reference it.

It feels a bit out of place here, since we don't use it as the parameter to
OnAddEntry() or anything. I might suggest forward declaring this as
"PassiveLogCollectorEntry", but maybe that is more trouble that it is worth.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:57: class Observer {
I suggest renaming this to "ThreadSafeObserver".

That will emphasize to future consumers that they must support being called from
multiple threads (since it is easy for tests to not cover that case).

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:66: // and may cause PassiveLogCollector to
use more memory than anticipated.
thanks for fixing the typo!

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:75: // ChromeNetLog::Observer functions in
response to a call to OnAddEntry.
I suggest additionaly re-iterating the threading model here.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:85: void SetLogLevel(LogLevel log_level,
ChromeNetLog* net_log);
Taking the ChromeNetLog* here isn't very intuitive.

What if Observer instead had a ChromeNetLog* member variable that tracked the
current NetLog it was observing?

ChromeNetLog could update it as part of the AddObserver/RemoveObserver methods.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:110: void
AddObserverAndGetAllCapturedEvents(Observer* observer,
I have a reputation for writing incredibly long function names... in that
spirit, I suggest adding "Passive" to this name :-)

As in: AddObserverAndGetAllPassivelyCapturedEvents().

If you find that too unpleasant to bear, I will understand.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:135: ObserverList<Observer, true>
observers_;
Can you mention that |lock_| must be held whenever reading/writing this?

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/load_ti...
File chrome/browser/net/load_timing_observer.cc (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/load_ti...
chrome/browser/net/load_timing_observer.cc:90: if (!(request->load_flags() &
net::LOAD_ENABLE_LOAD_TIMING))
I suggest adding assertions to all the other functions that:

DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));

(Just in case).

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/passive...
File chrome/browser/net/passive_log_collector.h (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/passive...
chrome/browser/net/passive_log_collector.h:75: virtual void OnAddEntry(const
ChromeNetLog::Entry& entry) = 0;
See earlier comment about forward declaring. To ease refactor could also have a
typedef like:

typedef PassiveLogCollectorEntry Entry;

I dunno, starting to hallucinate right now I'll have to double check tomorow.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/passive...
chrome/browser/net/passive_log_collector.h:346: Lock lock_;
So I have been thinking about this, and I don't think we need this lock.

Basically what I am thinking is, any time we enter into PassiveLogCollector we
are already guaranteed that we hold ChromeNetLog::lock_ (since we hold it while
iterating observers).

As such regular accesses are protected.

So I think all we need is a way to get at that lock for things like "Clear()"
and we are in business.

It may seem like over-optimization, but in testing some other bug (where I had
to load 50 tabs at once), I watched as we dispatched 60,000 events in a short
period of time!!! So having each operation be as fast as possible is worthwhile.

http://codereview.chromium.org/4118004/diff/176002/net/proxy/multi_threaded_p...
File net/proxy/multi_threaded_proxy_resolver.cc (left):

http://codereview.chromium.org/4118004/diff/176002/net/proxy/multi_threaded_p...
net/proxy/multi_threaded_proxy_resolver.cc:258: BoundNetLog
bound_worker_log(NetLog::Source(), worker_log_.get());
Niiiiiiiice. glad to see this go.

[mmenke, 2010-11-17 21:42:14]

Noticed a bug in refreshing the net-internals page and fixed it.  Would do it in
another CL, but as it's a result of how the treading is set up, think it's
simplest just to fix it here (And it's not a complicated fix).

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
File chrome/browser/dom_ui/net_internals_ui.cc (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:616:
io_thread_->net_log()->AddObserverAndGetAllCapturedEvents(this, &entries);
On 2010/11/17 05:59:02, eroman wrote:
> The impact of threading here is fairly subtle.
> 
> I don't remember, can you check whether the javascript cares if it receives
> active events BEFORE receiving the passively captured events?
> 
> I don't think it will matter, but it is worth checking and additionally noting
> here that it can happen (although unlikely).
> 
> Basically I am thinking that right after we attach the observer and grab the
> passively logged entries, the observer might be called on some other thread,
and
> in turn queue up a task in the UI thread. Then we reach the next line
> (SendPassiveLogEntries) which also posts a task to the UI thread, this time to
> send the renderer the passively logged entries.

Thanks for catching that.  I hadn't thought about that case.  It looks to me
like there is actually an issue: All events within a source are assumed to be
received in the order they occurred.  I've updated the JS code to hold onto
actively logged events until passively logged ones are received.

Could try to fix it C++-side, but the Javascript solution seems a lot simpler.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:916: DCHECK(is_observing_log_);
On 2010/11/17 05:59:02, eroman wrote:
> I wander if we need a memory barrier or something to read the bool (since it
> could have been just written on a different thread).
> 
> I suggest just deleting this DCHECK to be safe.

I don't think we do, since we set it before adding ourselves as an Observer
(Which requires we acquire a lock before we're actually added), and we never set
it to false.  Still seems like it's safer to remove the DCHECK, though.  Done.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/io_thread.cc
File chrome/browser/io_thread.cc (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/io_thread.c...
chrome/browser/io_thread.cc:210: : net_log_(net_log),
On 2010/11/17 05:59:02, eroman wrote:
> I am not sure what the style guide says, but I think intuitively the
> superclass's initializer should be first. (i.e. move this below
> BrowserProcessSubThread()).

Done.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.cc (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:50: : last_id_(0),
On 2010/11/17 05:59:02, eroman wrote:
> Where is log_level_ initialized? (it may still be accessed even though there
are
> no observers).

It's actually initialized on the first call to AddObserver, a couple lines down.
 That having been said, initializing it explicitly seems a pretty reasonable
idea.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:56: const CommandLine& command_line =
*CommandLine::ForCurrentProcess();
On 2010/11/17 05:59:02, eroman wrote:
> Just to check -- Since ChromeNetLog is now being constructed in
> BrowserProcessImpl(), is it guaranteed taht CommandLine has already been setup
> by the time we reach this?

Yes, it is.  It's initialized really early in the main function.  There's also a
DCHECK to make sure it's been initialized.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:88: base::subtle::Atomic32 log_level =
base::subtle::NoBarrier_Load(&log_level_);
On 2010/11/17 05:59:02, eroman wrote:
> I need to buff up on my concurrency... what is the implication between doing
it
> with/without memory barrier?

I'm pretty weak here, too, but the barrier will make sure no reads/writes will
be reordered from before the instruction to after it by the compiler or the CPU.
 This applies across CPUs, and should handle issues both relating to caching
data in registers and cache coherency issues as well.

As we don't have any data that could have concurrency issues (Other than what
we're using the NoBarrier operations on), we shouldn't need barriers.

If we depended on data set before we last modified |log_level_|, for example, we
would need a barrier, if we weren't using a mutex (Mutexes always come with
their own implicit memory barriers, I believe).

Having a barrier is, of course, slower than not having one, but other than that,
using one when you don't need one shouldn't cause any issues, in general.

If you want to solicit a more informed opinion on the issue, I would not be
offended in the least.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.h (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:37: struct Entry {
On 2010/11/17 05:59:02, eroman wrote:
> I see, you moved this out of PassiveLogCollector because of
> AddObserverAndGetAllCapturedEvents() needing to reference it.
> 
> It feels a bit out of place here, since we don't use it as the parameter to
> OnAddEntry() or anything. I might suggest forward declaring this as
> "PassiveLogCollectorEntry", but maybe that is more trouble that it is worth.

Reason I didn't do that is because EntryList is an array of them (Not of
pointers to them, as that wouldn't be threadsafe), so couldn't create the
typedef EntryList if they were forward declared.  EntryList itself cannot be
forward declared either.

We also can't just declare it in passive_log_collector.h and include the file
here, as its a child class of ObserverThreadSafe.

I'm not sure there's a clean way to get Entry out of this file, other than
putting it in its own file and including it in this one.  If you think that's a
better solution, happy to go ahead and do it.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:57: class Observer {
On 2010/11/17 05:59:02, eroman wrote:
> I suggest renaming this to "ThreadSafeObserver".
> 
> That will emphasize to future consumers that they must support being called
from
> multiple threads (since it is easy for tests to not cover that case).

Done.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:85: void SetLogLevel(LogLevel log_level,
ChromeNetLog* net_log);
On 2010/11/17 05:59:02, eroman wrote:
> Taking the ChromeNetLog* here isn't very intuitive.
> 
> What if Observer instead had a ChromeNetLog* member variable that tracked the
> current NetLog it was observing?
> 
> ChromeNetLog could update it as part of the AddObserver/RemoveObserver
methods.

Done.  Only thing I don't like about that is that it allows things to
theoretically be in an inconsistent state.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:110: void
AddObserverAndGetAllCapturedEvents(Observer* observer,
On 2010/11/17 05:59:02, eroman wrote:
> I have a reputation for writing incredibly long function names... in that
> spirit, I suggest adding "Passive" to this name :-)
> 
> As in: AddObserverAndGetAllPassivelyCapturedEvents().
> 
> If you find that too unpleasant to bear, I will understand.

I'm fine with it, actually.  Only thing I have against long function names is
that they force their parameters onto the next line.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/load_ti...
File chrome/browser/net/load_timing_observer.cc (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/load_ti...
chrome/browser/net/load_timing_observer.cc:90: if (!(request->load_flags() &
net::LOAD_ENABLE_LOAD_TIMING))
On 2010/11/17 05:59:02, eroman wrote:
> I suggest adding assertions to all the other functions that:
> 
> DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
> 
> (Just in case).

Wasn't sure if this would break unittests.  Done.

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/passive...
File chrome/browser/net/passive_log_collector.h (right):

http://codereview.chromium.org/4118004/diff/176002/chrome/browser/net/passive...
chrome/browser/net/passive_log_collector.h:346: Lock lock_;
On 2010/11/17 05:59:02, eroman wrote:
> So I have been thinking about this, and I don't think we need this lock.
> 
> Basically what I am thinking is, any time we enter into PassiveLogCollector we
> are already guaranteed that we hold ChromeNetLog::lock_ (since we hold it
while
> iterating observers).
> 
> As such regular accesses are protected.
> 
> So I think all we need is a way to get at that lock for things like "Clear()"
> and we are in business.
> 
> It may seem like over-optimization, but in testing some other bug (where I had
> to load 50 tabs at once), I watched as we dispatched 60,000 events in a short
> period of time!!! So having each operation be as fast as possible is
worthwhile.

This strikes me as a pretty reasonable idea, actually.  Think the simplest way
to enforce that is to remove the passive_log_collector() function from
ChromeNetLog(), and force all calls to go through it.

Could make the ChromeNetLog's lock_ acquireable by its observers instead, but
think it's just safest to let ChromeNetLog handle all the lock management
itself.

[eroman, 2010-11-18 18:04:03]

I would like to do one more review pass after these comments are addressed
before officially signing off, but otherwise looks good so far!

One final thing though: could you add some multi-threaded test for ChromeNetLog?
I am thinking something really simple, which just emits some random events from
random threads, and maybe calls "Clear" and/or the
AddObserverAndGetPassivelyBlaBlaBla.

I don't think the test even needs to assert on the results (i.e. we don't need
to worry on the particular thread orderings). I envision such a test as really
just exercising the multithreaded codepaths, in order to give our DCHECKs a
chance to run, and to let threadsanitizer have a chance at doing its magic in a
controlled fashion (we can't be sure that the current unit tests will exercise
multithreaded scenarios reliably).

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/dom_ui/net_...
File chrome/browser/dom_ui/net_internals_ui.cc (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:191: // Sends all passive log entries
in |entries| to the Javascript handler,
|passive_entries|

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:993: if (handler_ &&
!was_domui_deleted_) {
ah! so this was why we were getting javascript errors on refresh? good find.

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.h (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:77: // It is illegal for an Observer to call
any ChromeNetLog or
nit: "an Observer" --> either:
   "an observer" or "a ThreadsafeObserver"

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:88: void set_net_log(ChromeNetLog* net_log);
Can you make it private? (outter classes have direct access to private members
of their inner classes)

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:131: // Called whenever an Observer is added
or removed, or changes its log level.
same comment regarding the capitlized "Observer".

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:137: base::subtle::Atomic32 last_id_;
Could you add a brief comment for this? (I realize it didn't have one before, my
bad).

Perhaps:

// The ID number of the most recently added NetLog::Source

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/passive...
File chrome/browser/net/passive_log_collector.cc (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/passive...
chrome/browser/net/passive_log_collector.cc:82: void
PassiveLogCollector::OnAddEntry(
Because the threadsafety contract is fairly fragile here, I suggest adding an
assertion similar to this at the start of *each* method.

Maybe to keep this simple, could add a method to
ChromeNetLog::ThreadSafeObserver similar to:

void ChromeNetLog::ThreadSafeObserver::AssertNetLogLockAcquired() {
  if (net_log_)
    net_log_->lock_.AssertAcquired();
}

Which will help catch problems if people add new entry points.

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/policy/devi...
File chrome/browser/policy/device_management_backend_impl.cc (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/policy/devi...
chrome/browser/policy/device_management_backend_impl.cc:54: explicit
DeviceManagementBackendRequestContext(net::NetLog* net_log,
remove "explicit".

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/resources/n...
File chrome/browser/resources/net_internals/main.js (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/resources/n...
chrome/browser/resources/net_internals/main.js:319: if
(!this.receivedPassivelyCapturedEvents_) {
What I don't like about this approach, is we pay a cost on every entry added,
for a situation which is unlikely to happen.

Would it be possible instead to just add the logic to
receivedPassiveLogEntries()?

I reckon how that would work, is in receivedPassiveLogEntries(), we would check
the length of capturedEvents. If it is 0, then everything is peachy (and that is
the common case).

However if it is not 0, then we would swap out capturedEvents, and call the
deleteAllEvents() method to reset state.

Next we would play back the received passive events, and then play back the old
capturedEvents.

WDYT?

(I find it easier to read when the special casing code is localized at the
problem area, as opposed to in other methods).

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log.cc
File net/base/capturing_net_log.cc (right):

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.cc:38: return
base::subtle::NoBarrier_AtomicIncrement(&next_id_, 1)-1;
I suggest doing what you did in the other file for consistency, and just have
this be "last_id_"

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.cc:71: void CapturingBoundNetLog::AppendTo(const
BoundNetLog& net_log) const {
See earlier comment -- i don't think this is needed anymore now that you made
proxy stuff happen on the same thread.

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log.h
File net/base/capturing_net_log.h (right):

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.h:67: base::subtle::Atomic32 next_id_;
nit: For consistency with ChromeNetLog, you should either call this last_event_
or call ChromeNetLog's one next_id_.

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.h:82: scoped_refptr<CapturingNetLog>& net_log);
I didn't think CapturingNetLog was refcounted?

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.h:93: // Returns the list of all entries in the log.
nit: "Returns" --> "Fills" ?

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.h:100: void AppendTo(const BoundNetLog& net_log)
const;
I wander if we still need this method now?

[mmenke, 2010-11-23 16:48:45]

In terms of performance, we're able to log about 30 entries per millisecond in a
debug build with debugger attached under Windows, in the new unit test (10
threads logging 10000 messages each - unittest normally only does 100 each, but
I upped it for a speed test).

If we have extra observers attached, it would be slower, but generally we don't,
except when debugging.  Also, other than the NetLogLogger, the other observers
all just post a message to another thread, at most.

I'll do a speed test on a release build before landing anything, and don't
intend to commit until after the mstone 9 branch point.

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/dom_ui/net_...
File chrome/browser/dom_ui/net_internals_ui.cc (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/dom_ui/net_...
chrome/browser/dom_ui/net_internals_ui.cc:993: if (handler_ &&
!was_domui_deleted_) {
On 2010/11/18 18:04:03, eroman wrote:
> ah! so this was why we were getting javascript errors on refresh? good find.

Yea.  Since refresh keeps the same RenderView, and the handler_ is only deleted
after the new page is committed, events related to loading the net_internals_ui
page itself were being passed to the old domui, but only being handled after the
new page was committed...  Or something like that.

We actually still occasionally get Javascript errors from it, but only before
g_browser is instantiated, so the errors don't affect anything.

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.h (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:77: // It is illegal for an Observer to call
any ChromeNetLog or
On 2010/11/18 18:04:03, eroman wrote:
> nit: "an Observer" --> either:
>    "an observer" or "a ThreadsafeObserver"

Thought I caught all of those.

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:88: void set_net_log(ChromeNetLog* net_log);
On 2010/11/18 18:04:03, eroman wrote:
> Can you make it private? (outter classes have direct access to private members
> of their inner classes)

I tried that initially, but was getting a compile error...  Also tried accessing
it directly.  Same is true if I make it protected instead of private.

It looks like inner classes *can* access private members of their outer class,
however.  Only problem with switching to something like
ObserverThreadSafe::StartObserving(ChromeNetLog*) is
AddObserverAndGetAllPassivelyCapturedEvents().

I've made ChromeNetLog a friend of ObserverThreadSafe.  friend doesn't seem to
be used too heavily in the Chrome code base, but it is used, and seems the
simplest workaround.

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/passive...
File chrome/browser/net/passive_log_collector.cc (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/net/passive...
chrome/browser/net/passive_log_collector.cc:82: void
PassiveLogCollector::OnAddEntry(
On 2010/11/18 18:04:03, eroman wrote:
> Because the threadsafety contract is fairly fragile here, I suggest adding an
> assertion similar to this at the start of *each* method.
> 
> Maybe to keep this simple, could add a method to
> ChromeNetLog::ThreadSafeObserver similar to:
> 
> void ChromeNetLog::ThreadSafeObserver::AssertNetLogLockAcquired() {
>   if (net_log_)
>     net_log_->lock_.AssertAcquired();
> }
> 
> Which will help catch problems if people add new entry points.

Sounds like a good idea to me.

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/resources/n...
File chrome/browser/resources/net_internals/main.js (right):

http://codereview.chromium.org/4118004/diff/275001/chrome/browser/resources/n...
chrome/browser/resources/net_internals/main.js:319: if
(!this.receivedPassivelyCapturedEvents_) {
On 2010/11/18 18:04:03, eroman wrote:
> What I don't like about this approach, is we pay a cost on every entry added,
> for a situation which is unlikely to happen.
> 
> Would it be possible instead to just add the logic to
> receivedPassiveLogEntries()?
> 
> I reckon how that would work, is in receivedPassiveLogEntries(), we would
check
> the length of capturedEvents. If it is 0, then everything is peachy (and that
is
> the common case).
> 
> However if it is not 0, then we would swap out capturedEvents, and call the
> deleteAllEvents() method to reset state.
> 
> Next we would play back the received passive events, and then play back the
old
> capturedEvents.
> 
> WDYT?
> 
> (I find it easier to read when the special casing code is localized at the
> problem area, as opposed to in other methods).

Don't really like the idea of starting to populate the events pane and then
clearing it.  Know it will almost never happen, but it just seems wrong...  I
can live with it, though.  Good point about the localized special case code.

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log.h
File net/base/capturing_net_log.h (right):

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.h:67: base::subtle::Atomic32 next_id_;
On 2010/11/18 18:04:03, eroman wrote:
> nit: For consistency with ChromeNetLog, you should either call this
last_event_
> or call ChromeNetLog's one next_id_.

ChromeNetLog's is the id of the last event that occurred, meaning the next id is
last_id_+1, while this is the id of the next event.  The difference is because
they're both initialized to 0, but ChromeNetLog starts with an id of 0, while
CapturingNetLog starts with an id of 1.  I'll go ahead and rename
CapturingNetLog's and initialize it to -1.

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.h:82: scoped_refptr<CapturingNetLog>& net_log);
On 2010/11/18 18:04:03, eroman wrote:
> I didn't think CapturingNetLog was refcounted?

Thanks.  Holdover from the first pass.

http://codereview.chromium.org/4118004/diff/275001/net/base/capturing_net_log...
net/base/capturing_net_log.h:100: void AppendTo(const BoundNetLog& net_log)
const;
On 2010/11/18 18:04:03, eroman wrote:
> I wander if we still need this method now?

I can't see a use for it.

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.h (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:24: // All methods are thread safe, with the
exception that no ChromeNetLog or
Looks like "thread safe" is a little more common than "threadsafe" in comments.

It's also the term wikipedia uses.

[eroman, 2010-11-30 01:43:37]

LGTM

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.cc (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:124: DCHECK(!observer->net_log_);
nit: perhaps you could extract the shared logic from AddObserver. Say a private
AddObserverWhileLockHeld()

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.h (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:26: // OnAddEntry() method.
Might be useful to mention that doing so will result in a deadlock (as opposed
to some weird corruption).

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:140: // PassiveLogCollector needs access
this for debu assertions.  Should not, in
typo: debug

nit: I would prefer if this comment said something about how |lock_| protects
access to |observers_| and indirectly |passive_collector_|.

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/load_ti...
File chrome/browser/net/load_timing_observer_unittest.cc (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/load_ti...
chrome/browser/net/load_timing_observer_unittest.cc:87: BrowserThread
io_thread(BrowserThread::IO, &message_loop);
I suggest using a test fixture instead.

If I am remembering correctly, it will look something like this:


class LoadTimingObserverTest : public testing::Test {
 public:
  LoadTimingObserverTest() : io_loop_(...) {
  }
 ...
};


Then change each TEST(LoadingTimeObserverTest, ...) to:

TEST_F(LoadingTimeObserverTest, ...).

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/resources/n...
File chrome/browser/resources/net_internals/main.js (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/resources/n...
chrome/browser/resources/net_internals/main.js:388: // Due to a race condition,
it is possible to receive actively captured log
nit: I suggest adding "known" or "expected" so this doesn't sound like a
workaround for a bug.

http://codereview.chromium.org/4118004/diff/390004/net/proxy/multi_threaded_p...
File net/proxy/multi_threaded_proxy_resolver.cc (right):

http://codereview.chromium.org/4118004/diff/390004/net/proxy/multi_threaded_p...
net/proxy/multi_threaded_proxy_resolver.cc:279: // Must only be used on the
"origin" thread.
This comment is no longer accurate (since |net_log_| is accessed from the worker
thread).

The assumption is that BoundNetLog is also thread safe; please update the
comment accordingly.

http://codereview.chromium.org/4118004/diff/390004/net/proxy/proxy_service.cc
File net/proxy/proxy_service.cc (right):

http://codereview.chromium.org/4118004/diff/390004/net/proxy/proxy_service.cc...
net/proxy/proxy_service.cc:159: // Both |async_host_resolver| and |net_log| will
only be operated on
Please update this comment.

[mmenke, 2010-11-30 18:59:04]

Performance Note:  I experimentally loaded 5 websites (news.google.com, youtube,
cnn, bbc.co.uk, and hulu), and that resulted in about 28000 log entries, so
about 6k entries each, on average.  Release version of the unit test logs about
250 entries per millisecond, for an estimated average of about 24 ms logging
time for each of those queries.

Switching the unittest to log a bunch of entries with a single source (As
opposed to a new source for every entry) results in about 1400 entries per
millisecond, so 250 is probably on the conservative side.

While it would be nice to do better, I don't think performance is going to be a
huge concern.

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.cc (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:124: DCHECK(!observer->net_log_);
On 2010/11/30 01:43:37, eroman wrote:
> nit: perhaps you could extract the shared logic from AddObserver. Say a
private
> AddObserverWhileLockHeld()

Done.

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.h (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:26: // OnAddEntry() method.
On 2010/11/30 01:43:37, eroman wrote:
> Might be useful to mention that doing so will result in a deadlock (as opposed
> to some weird corruption).

Done.

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.h:140: // PassiveLogCollector needs access
this for debu assertions.  Should not, in
On 2010/11/30 01:43:37, eroman wrote:
> typo: debug
> 
> nit: I would prefer if this comment said something about how |lock_| protects
> access to |observers_| and indirectly |passive_collector_|.

Done.

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/load_ti...
File chrome/browser/net/load_timing_observer_unittest.cc (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/net/load_ti...
chrome/browser/net/load_timing_observer_unittest.cc:87: BrowserThread
io_thread(BrowserThread::IO, &message_loop);
On 2010/11/30 01:43:37, eroman wrote:
> I suggest using a test fixture instead.
> 
> If I am remembering correctly, it will look something like this:
> 
> 
> class LoadTimingObserverTest : public testing::Test {
>  public:
>   LoadTimingObserverTest() : io_loop_(...) {
>   }
>  ...
> };
> 
> 
> Then change each TEST(LoadingTimeObserverTest, ...) to:
> 
> TEST_F(LoadingTimeObserverTest, ...).

Done.

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/resources/n...
File chrome/browser/resources/net_internals/main.js (right):

http://codereview.chromium.org/4118004/diff/390004/chrome/browser/resources/n...
chrome/browser/resources/net_internals/main.js:388: // Due to a race condition,
it is possible to receive actively captured log
On 2010/11/30 01:43:37, eroman wrote:
> nit: I suggest adding "known" or "expected" so this doesn't sound like a
> workaround for a bug.

Done.

http://codereview.chromium.org/4118004/diff/390004/net/proxy/multi_threaded_p...
File net/proxy/multi_threaded_proxy_resolver.cc (right):

http://codereview.chromium.org/4118004/diff/390004/net/proxy/multi_threaded_p...
net/proxy/multi_threaded_proxy_resolver.cc:279: // Must only be used on the
"origin" thread.
On 2010/11/30 01:43:37, eroman wrote:
> This comment is no longer accurate (since |net_log_| is accessed from the
worker
> thread).
> 
> The assumption is that BoundNetLog is also thread safe; please update the
> comment accordingly.

Added a commend that net_log_ and url_ can be used from either thread, and left
in the old comment for results_.  url_ was mislabeled before.

http://codereview.chromium.org/4118004/diff/390004/net/proxy/proxy_service.cc
File net/proxy/proxy_service.cc (right):

http://codereview.chromium.org/4118004/diff/390004/net/proxy/proxy_service.cc...
net/proxy/proxy_service.cc:159: // Both |async_host_resolver| and |net_log| will
only be operated on
On 2010/11/30 01:43:37, eroman wrote:
> Please update this comment.

Done.

[eroman, 2010-11-30 19:15:38]

lgtm

[eroman, 2010-11-30 19:20:20]

http://codereview.chromium.org/4118004/diff/429002/chrome/browser/net/chrome_...
File chrome/browser/net/chrome_net_log.cc (right):

http://codereview.chromium.org/4118004/diff/429002/chrome/browser/net/chrome_...
chrome/browser/net/chrome_net_log.cc:10: #include "base/lock.h"
nit: include lock.h from the header file instead (since it has a lock member).

[mmenke, 2010-11-30 20:39:12]

A couple more speed results, for posterity (Passive log collector logging when
entries are cleared now turned off).  Already talked a bit with eroman about
them, but thought I'd post them anyways.

While I've tried to get numbers more accurate than before, time taken can vary
quite a bit between runs of identical binaries (Sometimes can take as much as
twice as long), so these are just rough averages:

1) With everything:  340/ms
2) With no passive log collector:  910/ms
3) With no load timing observer:  400/ms
4) With no observers:  1500/ms
5) With both observers, but only one source id per thread:  2000/ms

The last is likely only faster than the second to last because of random runtime
variations.

So it looks like the passive log collector adding/clearing sources may currently
the limiting factor, in terms of speed (Or possibly searching through old
sources for duplicates).  In real world situations, I'm not sure if things look
more like 1) or 5).

I'm planning to go ahead and commit tomorrow morning/early afternoon, as it's a
big change, and things tend to be a little less active earlier in the day.

On 2010/11/30 19:20:20, eroman wrote:
>
http://codereview.chromium.org/4118004/diff/429002/chrome/browser/net/chrome_...
> File chrome/browser/net/chrome_net_log.cc (right):
> 
>
http://codereview.chromium.org/4118004/diff/429002/chrome/browser/net/chrome_...
> chrome/browser/net/chrome_net_log.cc:10: #include "base/lock.h"
> nit: include lock.h from the header file instead (since it has a lock member).

Fixed.