First pass at adding http/backend cache to NetLog

First pass at adding http/backend cache events to the NetLog. 

Adds sources and events for ActiveCacheEntry and EntryImpl 
objects, as well as adding cache read/write events to 
HttpCacheTransactions. Most new read/write events are 
only logged when NetLog logging mode is set to log all events. 

Also, net-internals now merges begin and end events that have 
parameters, as long as only one of them has parameters. 
I think this increases readability, at the cost of making 
it a little more difficult to follow timings with just the "st" 
values. 

BUG=59382
TEST=none yet, other than updates to existing tests.


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

[mmenke, 2010-12-10 19:09:11]

It's not showing up for some reason, but first patch set was green on all tests.

[rvargas (doing something else), 2010-12-11 00:29:00]

I have only reviewed a few files so far...

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache.h
File net/http/http_cache.h (right):

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache.h#newc...
net/http/http_cache.h:91: NetLog* net_log) = 0;
nit: this should be the first argument.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache.h#newc...
net/http/http_cache.h:218: BoundNetLog        net_log;
I'm not convinced that making ActiveEntry a source of log events is actually
something that we want.

I'd say that tracking what happens at the HttpCache::Transaction level + at the
disk cache level should be enough for practical purposes. The ActiveEntry is
intended to be just a simple structure in the middle that simplifies bonding
transactions to cache entries.

I think doing this adds too much noise to the log and the code, for the actual
value that provides.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
File net/http/http_cache_transaction.cc (right):

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1024:
net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, NULL);
This one is most likely redundant.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1137: if (net_log_.IsLoggingAllEvents())
You should probably move this before the previous test so that the begin is
always paired with an end.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1199:
net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_DATA, NULL);
Isn't this a little excessive? I'd expect a lot of noise from this one.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1233:
net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, NULL);
same here.

[mmenke, 2010-12-11 01:51:05]

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache.h
File net/http/http_cache.h (right):

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache.h#newc...
net/http/http_cache.h:218: BoundNetLog        net_log;
On 2010/12/11 00:29:01, rvargas wrote:
> I'm not convinced that making ActiveEntry a source of log events is actually
> something that we want.
> 
> I'd say that tracking what happens at the HttpCache::Transaction level + at
the
> disk cache level should be enough for practical purposes. The ActiveEntry is
> intended to be just a simple structure in the middle that simplifies bonding
> transactions to cache entries.
> 
> I think doing this adds too much noise to the log and the code, for the actual
> value that provides.

I wasn't sure if they were worth logging or not.  They seem pretty
uninteresting...Until you end up with cache contention, which, admittedly, isn't
too common, though I could see it being useful in those cases.  It's pretty
clearly useless most cases, however.

I'll go ahead and remove them, though I think I might log an event for the
transaction when it's queued/dequeued (Rather than instantly become an active
reader/writer), just to draw attention to it, in the cases where it actually
happens.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
File net/http/http_cache_transaction.cc (right):

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1137: if (net_log_.IsLoggingAllEvents())
On 2010/12/11 00:29:01, rvargas wrote:
> You should probably move this before the previous test so that the begin is
> always paired with an end.

Both write events check for entry_'s existence before logging, and I don't
believe it can be destroyed between the two events.  Figure when nothing's
written, probably shouldn't log anything.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1199:
net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_DATA, NULL);
On 2010/12/11 00:29:01, rvargas wrote:
> Isn't this a little excessive? I'd expect a lot of noise from this one.

There is indeed a lot of noise, but it all ends up at the bottom, when nothing
else is happening (And nothing too useful is logged afterwards).  Part of the
purpose behind NetLog is to locate performance issues, and I thought this might
be a useful indicator of cache contention issues.  The same goes for the
WRITE_DATA events.  On the other hand, timings of other events and the disk
cache entries may be enough.

We log equivalent events when we receive data, rather than reading from the
cache.

I'm not sure you're wrong about this, but feel I should explain before removing
it.  If you feel it's not worth it effort, I'm happy to remove it (Also, I'm not
sure how familiar you are with the NetLog, but IsLoggingAllEvents() is only true
when about:net-internals is currently open, so shouldn't have much performance
impact, normally).

[rvargas (doing something else), 2010-12-13 23:34:38]

Looks good.

We also need similar logs for the memory only version: mem_backend_impl.cc and
mem_entry_impl.cc, but that certainly can wait for another CL. The same thing
can be said for eviction.cc.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
File net/http/http_cache_transaction.cc (right):

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1137: if (net_log_.IsLoggingAllEvents())
On 2010/12/11 01:51:05, Matt Menke wrote:
> On 2010/12/11 00:29:01, rvargas wrote:
> > You should probably move this before the previous test so that the begin is
> > always paired with an end.
> 
> Both write events check for entry_'s existence before logging, and I don't
> believe it can be destroyed between the two events.  Figure when nothing's
> written, probably shouldn't log anything.

DoCacheWriteResponse and DoCacheWriteTruncatedResponse log fist and then check
to see if entry_ is null (inside WriteResponseInfoToEntry())

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1199:
net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_DATA, NULL);
OK, I didn't notice before that we log bytes received at the socket layer. This
seems equivalent.

On 2010/12/11 01:51:05, Matt Menke wrote:
> On 2010/12/11 00:29:01, rvargas wrote:
> > Isn't this a little excessive? I'd expect a lot of noise from this one.
> 
> There is indeed a lot of noise, but it all ends up at the bottom, when nothing
> else is happening (And nothing too useful is logged afterwards).  Part of the
> purpose behind NetLog is to locate performance issues, and I thought this
might
> be a useful indicator of cache contention issues.  The same goes for the
> WRITE_DATA events.  On the other hand, timings of other events and the disk
> cache entries may be enough.
> 
> We log equivalent events when we receive data, rather than reading from the
> cache.
> 
> I'm not sure you're wrong about this, but feel I should explain before
removing
> it.  If you feel it's not worth it effort, I'm happy to remove it (Also, I'm
not
> sure how familiar you are with the NetLog, but IsLoggingAllEvents() is only
true
> when about:net-internals is currently open, so shouldn't have much performance
> impact, normally).

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl.cc
File net/disk_cache/entry_impl.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:28: class EntryCreationParameters : public
net::NetLog::EventParameters {
nit: Add a short description.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:46: class ReadWriteDataParams : public
net::NetLog::EventParameters {
nit: same here.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:99: if (entry_->net_log().IsLoggingAllEvents())
This should be moved down, under the "if (callback_)", to avoid calling EndEvent
twice.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:389:
net_log_.EndEvent(net::NetLog::TYPE_DISK_CACHE_ENTRY, NULL);
Please move this line before the call to OnEntryDestroyEnd()

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:537:
net_log_.AddEvent(net::NetLog::TYPE_DISK_CACHE_DOOM, NULL);
Given the log at InternalDoom(), this one is not needed.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/in_flight_b...
File net/disk_cache/in_flight_backend_io.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/in_flight_b...
net/disk_cache/in_flight_backend_io.cc:142:
entry->net_log().AddEvent(net::NetLog::TYPE_DISK_CACHE_QUEUE_READ_DATA,
I'd actually remove all logging from this file.

This results in three logs for the same event: Read started at the http cache
level, read received at the backend and read received at the backend entry...
each with the closing event.

I don't think this is *that* interesting :)

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/in_flight_b...
net/disk_cache/in_flight_backend_io.cc:172:
entry->net_log().AddEvent(net::NetLog::TYPE_DISK_CACHE_QUEUE_READ_SPARSE,
Read/Write sparse should probably be logged directly from the entry.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
File net/disk_cache/sparse_control.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:226:
entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
It would be nice to log |op| here.

Actually, probably it is good enough now. Do you have a sample of how it looks?

http://codereview.chromium.org/4067002/diff/251001/net/http/http_cache.cc
File net/http/http_cache.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/http/http_cache.cc#new...
net/http/http_cache.cc:745: NetLog::TYPE_ACTIVE_ENTRY_QUEUE,
This seems to do the same as TYPE_HTTP_CACHE_ADD_TO_ENTRY. If we want the size
of the queue, maybe we can just add it to the log at the transaction level and
remove this one.

[mmenke, 2010-12-14 00:04:43]

Just a pair of quick responses.  I'll update the code tomorrow.

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
File net/http/http_cache_transaction.cc (right):

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1137: if (net_log_.IsLoggingAllEvents())
On 2010/12/13 23:34:38, rvargas wrote:
> On 2010/12/11 01:51:05, Matt Menke wrote:
> > On 2010/12/11 00:29:01, rvargas wrote:
> > > You should probably move this before the previous test so that the begin
is
> > > always paired with an end.
> > 
> > Both write events check for entry_'s existence before logging, and I don't
> > believe it can be destroyed between the two events.  Figure when nothing's
> > written, probably shouldn't log anything.
> 
> DoCacheWriteResponse and DoCacheWriteTruncatedResponse log fist and then check
> to see if entry_ is null (inside WriteResponseInfoToEntry())

Which is why in DoCacheWriteResponse and DoCacheWriteTruncatedResponse I use:

if (net_log_.IsLoggingAllEvents() && entry_)

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
File net/disk_cache/sparse_control.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:226:
entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
On 2010/12/13 23:34:39, rvargas wrote:
> It would be nice to log |op| here.
> 
> Actually, probably it is good enough now. Do you have a sample of how it
looks?

I should have mentioned this earlier...But I'm not quite sure how to easily test
the sparse control.

[rvargas (doing something else), 2010-12-14 00:14:26]

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
File net/http/http_cache_transaction.cc (right):

http://codereview.chromium.org/4067002/diff/182003/net/http/http_cache_transa...
net/http/http_cache_transaction.cc:1137: if (net_log_.IsLoggingAllEvents())
On 2010/12/14 00:04:43, Matt Menke wrote:
> On 2010/12/13 23:34:38, rvargas wrote:
> > On 2010/12/11 01:51:05, Matt Menke wrote:
> > > On 2010/12/11 00:29:01, rvargas wrote:
> > > > You should probably move this before the previous test so that the begin
> is
> > > > always paired with an end.
> > > 
> > > Both write events check for entry_'s existence before logging, and I don't
> > > believe it can be destroyed between the two events.  Figure when nothing's
> > > written, probably shouldn't log anything.
> > 
> > DoCacheWriteResponse and DoCacheWriteTruncatedResponse log fist and then
check
> > to see if entry_ is null (inside WriteResponseInfoToEntry())
> 
> Which is why in DoCacheWriteResponse and DoCacheWriteTruncatedResponse I use:
> 
> if (net_log_.IsLoggingAllEvents() && entry_)

And that just shows how blind I am!

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
File net/disk_cache/sparse_control.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:226:
entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
On 2010/12/14 00:04:43, Matt Menke wrote:
> On 2010/12/13 23:34:39, rvargas wrote:
> > It would be nice to log |op| here.
> > 
> > Actually, probably it is good enough now. Do you have a sample of how it
> looks?
> 
> I should have mentioned this earlier...But I'm not quite sure how to easily
test
> the sparse control.

Just go to a page with HTML5 <video> or <audio>... or view PDFs with our
internal plugin.

That reminds me that at some point we should add disk cache tests that verify
that the net log has roughly what we want it to have.

[mmenke, 2010-12-14 17:53:43]

I will indeed add logging for the memory stuff in another CL.  Skimming over the
eviction code, I'm not quite sure what should be logged there.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl.cc
File net/disk_cache/entry_impl.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:28: class EntryCreationParameters : public
net::NetLog::EventParameters {
On 2010/12/13 23:34:39, rvargas wrote:
> nit: Add a short description.

Done

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:46: class ReadWriteDataParams : public
net::NetLog::EventParameters {
On 2010/12/13 23:34:39, rvargas wrote:
> nit: same here.

Done

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:99: if (entry_->net_log().IsLoggingAllEvents())
On 2010/12/13 23:34:39, rvargas wrote:
> This should be moved down, under the "if (callback_)", to avoid calling
EndEvent
> twice.

You're right.  Done.  Not sure there's any reason we'd ever end up here with a
null callback_, but definitely a bug.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:389:
net_log_.EndEvent(net::NetLog::TYPE_DISK_CACHE_ENTRY, NULL);
On 2010/12/13 23:34:39, rvargas wrote:
> Please move this line before the call to OnEntryDestroyEnd()

Done

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:537:
net_log_.AddEvent(net::NetLog::TYPE_DISK_CACHE_DOOM, NULL);
On 2010/12/13 23:34:39, rvargas wrote:
> Given the log at InternalDoom(), this one is not needed.

Done (Well, deleted this one.  Accidentally was logging on both).  Wasn't sure
which one would be the most useful.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/in_flight_b...
File net/disk_cache/in_flight_backend_io.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/in_flight_b...
net/disk_cache/in_flight_backend_io.cc:142:
entry->net_log().AddEvent(net::NetLog::TYPE_DISK_CACHE_QUEUE_READ_DATA,
On 2010/12/13 23:34:39, rvargas wrote:
> I'd actually remove all logging from this file.
> 
> This results in three logs for the same event: Read started at the http cache
> level, read received at the backend and read received at the backend entry...
> each with the closing event.
> 
> I don't think this is *that* interesting :)

All DISK_CACHE_QUEUE events removed.  Wasn't sure if they were worth tracking
for easy latency checking or not.

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
File net/disk_cache/sparse_control.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:226:
entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
On 2010/12/14 00:14:26, rvargas wrote:
> On 2010/12/14 00:04:43, Matt Menke wrote:
> > On 2010/12/13 23:34:39, rvargas wrote:
> > > It would be nice to log |op| here.
> > > 
> > > Actually, probably it is good enough now. Do you have a sample of how it
> > looks?
> > 
> > I should have mentioned this earlier...But I'm not quite sure how to easily
> test
> > the sparse control.
> 
> Just go to a page with HTML5 <video> or <audio>... or view PDFs with our
> internal plugin.
> 
> That reminds me that at some point we should add disk cache tests that verify
> that the net log has roughly what we want it to have.

I thought about doing that with this CL, but thought it'd be better to iron out
just what should be logged, first.

Here's a sample entry - might be nice to have a little more information on
sparse control events, now that I look at it, though it is already pretty noisy
as it is:


t=1292341087479 [st=  0] +DISK_CACHE_ENTRY                [dt=211]
                          --> created = false           
                          --> key =
"http://cdn.kaltura.org/apis/html5lib/kplayer-examples/media/bbb_trailer_360p.webm"
t=1292341087482 [st=  3]     DISK_CACHE_READ_DATA         [dt=  0]
                             --> buf_len = 353          
                             --> index = 0              
                             --> offset = 0             
t=1292341087484 [st=  5]     DISK_CACHE_READ_DATA         [dt=  0]
                             --> buf_len = 64           
                             --> index = 2              
                             --> offset = 0             
t=1292341087484 [st=  5]     DISK_CACHE_READ_DATA         [dt=  1]
                             --> buf_len = 128          
                             --> index = 2              
                             --> offset = 64            
t=1292341087485 [st=  6]    +SPARSE_CONTROL               [dt= 17]
t=1292341087487 [st=  8]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
t=1292341087502 [st= 23]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
t=1292341087502 [st= 23]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
t=1292341087502 [st= 23]    -SPARSE_CONTROL               
t=1292341087537 [st= 58]     DISK_CACHE_WRITE_DATA        [dt=  1]
                             --> buf_len = 353          
                             --> index = 0              
                             --> offset = 0             
                             --> truncate = true        
t=1292341087549 [st= 70]    +SPARSE_CONTROL               [dt=  4]
t=1292341087552 [st= 73]        SPARSE_CONTROL_WRITE      [dt=  0]
                                --> source_dependency = {"id":458,"type":9}
t=1292341087553 [st= 74]    -SPARSE_CONTROL               
t=1292341087557 [st= 78]    +SPARSE_CONTROL               [dt=  2]
t=1292341087557 [st= 78]        SPARSE_CONTROL_WRITE      [dt=  2]
                                --> source_dependency = {"id":458,"type":9}
t=1292341087559 [st= 80]    -SPARSE_CONTROL               
t=1292341087562 [st= 83]    +SPARSE_CONTROL               [dt=  2]
t=1292341087562 [st= 83]        SPARSE_CONTROL_WRITE      [dt=  1]
                                --> source_dependency = {"id":458,"type":9}
t=1292341087564 [st= 85]    -SPARSE_CONTROL               
t=1292341087566 [st= 87]    +SPARSE_CONTROL               [dt=  3]
t=1292341087567 [st= 88]        SPARSE_CONTROL_WRITE      [dt=  2]
                                --> source_dependency = {"id":458,"type":9}
t=1292341087569 [st= 90]    -SPARSE_CONTROL               
t=1292341087572 [st= 93]    +SPARSE_CONTROL               [dt=  2]
t=1292341087572 [st= 93]        SPARSE_CONTROL_WRITE      [dt=  2]
                                --> source_dependency = {"id":458,"type":9}
t=1292341087574 [st= 95]    -SPARSE_CONTROL               
t=1292341087577 [st= 98]    +SPARSE_CONTROL               [dt=  3]
t=1292341087577 [st= 98]        SPARSE_CONTROL_WRITE      [dt=  2]
                                --> source_dependency = {"id":458,"type":9}
t=1292341087580 [st=101]    -SPARSE_CONTROL               
t=1292341087593 [st=114]     DISK_CACHE_READ_DATA         [dt=  1]
                             --> buf_len = 353          
                             --> index = 0              
                             --> offset = 0             
t=1292341087597 [st=118]    +SPARSE_CONTROL               [dt=  6]
t=1292341087603 [st=124]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
t=1292341087603 [st=124]    -SPARSE_CONTROL               
t=1292341087636 [st=157]     DISK_CACHE_WRITE_DATA        [dt=  1]
                             --> buf_len = 353          
                             --> index = 0              
                             --> offset = 0             
                             --> truncate = true        
t=1292341087649 [st=170]    +SPARSE_CONTROL               [dt=  3]
t=1292341087651 [st=172]        SPARSE_CONTROL_WRITE      [dt=  1]
                                --> source_dependency = {"id":461,"type":9}
t=1292341087652 [st=173]    -SPARSE_CONTROL               
t=1292341087656 [st=177]    +SPARSE_CONTROL               [dt=  2]
t=1292341087656 [st=177]        SPARSE_CONTROL_WRITE      [dt=  2]
                                --> source_dependency = {"id":461,"type":9}
t=1292341087658 [st=179]    -SPARSE_CONTROL               
t=1292341087666 [st=187]     DISK_CACHE_WRITE_DATA        [dt=  1]
                             --> buf_len = 128          
                             --> index = 2              
                             --> offset = 64            
t=1292341087667 [st=188]     DISK_CACHE_CLOSE             
t=1292341087690 [st=211] -DISK_CACHE_ENTRY

http://codereview.chromium.org/4067002/diff/251001/net/http/http_cache.cc
File net/http/http_cache.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/http/http_cache.cc#new...
net/http/http_cache.cc:745: NetLog::TYPE_ACTIVE_ENTRY_QUEUE,
On 2010/12/13 23:34:39, rvargas wrote:
> This seems to do the same as TYPE_HTTP_CACHE_ADD_TO_ENTRY. If we want the size
> of the queue, maybe we can just add it to the log at the transaction level and
> remove this one.

Removed.  If we decide we really want queue length, can add it later.

[rvargas (doing something else), 2010-12-14 19:48:57]

LGTM (fell free to leave the small changes to sparse control for another CL).

For eviction.cc, basically we just need to know when we are evicting entries.
Look for current Trace() statements in the code.

One last thing that may be interesting is logging when we delete sparse
entries... SparseControl::DeleteChildren and ChildrenDeleter

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
File net/disk_cache/sparse_control.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:226:
entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
On 2010/12/14 17:53:43, Matt Menke wrote:
> On 2010/12/14 00:14:26, rvargas wrote:
> > On 2010/12/14 00:04:43, Matt Menke wrote:
> > > On 2010/12/13 23:34:39, rvargas wrote:
> > > > It would be nice to log |op| here.
> > > > 
> > > > Actually, probably it is good enough now. Do you have a sample of how it
> > > looks?
> > > 
> > > I should have mentioned this earlier...But I'm not quite sure how to
easily
> > test
> > > the sparse control.
> > 
> > Just go to a page with HTML5 <video> or <audio>... or view PDFs with our
> > internal plugin.
> > 
> > That reminds me that at some point we should add disk cache tests that
verify
> > that the net log has roughly what we want it to have.
> 
> I thought about doing that with this CL, but thought it'd be better to iron
out
> just what should be logged, first.

Sure, that's the right thing to do.

> 
> Here's a sample entry - might be nice to have a little more information on
> sparse control events, now that I look at it, though it is already pretty
noisy
> as it is:

Yeah, no (real) need to have |op|, but unless we add logs to ReadSparseData(),
we need to log here the offset and buf_len... and that is simpler than adding
logs at the EntryImpl level, at the small cost of not stating obviously that the
second and third reads are part of a top level operation.


> 
> 
> t=1292341087479 [st=  0] +DISK_CACHE_ENTRY                [dt=211]
>                           --> created = false           
>                           --> key =
>
"http://cdn.kaltura.org/apis/html5lib/kplayer-examples/media/bbb_trailer_360p.webm"
> t=1292341087482 [st=  3]     DISK_CACHE_READ_DATA         [dt=  0]
>                              --> buf_len = 353          
>                              --> index = 0              
>                              --> offset = 0             
> t=1292341087484 [st=  5]     DISK_CACHE_READ_DATA         [dt=  0]
>                              --> buf_len = 64           
>                              --> index = 2              
>                              --> offset = 0             
> t=1292341087484 [st=  5]     DISK_CACHE_READ_DATA         [dt=  1]
>                              --> buf_len = 128          
>                              --> index = 2              
>                              --> offset = 64            
> t=1292341087485 [st=  6]    +SPARSE_CONTROL               [dt= 17]
> t=1292341087487 [st=  8]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
> t=1292341087502 [st= 23]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
> t=1292341087502 [st= 23]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
> t=1292341087502 [st= 23]    -SPARSE_CONTROL               
> t=1292341087537 [st= 58]     DISK_CACHE_WRITE_DATA        [dt=  1]
>                              --> buf_len = 353          
>                              --> index = 0              
>                              --> offset = 0             
>                              --> truncate = true        
> t=1292341087549 [st= 70]    +SPARSE_CONTROL               [dt=  4]
> t=1292341087552 [st= 73]        SPARSE_CONTROL_WRITE      [dt=  0]
>                                 --> source_dependency = {"id":458,"type":9}
> t=1292341087553 [st= 74]    -SPARSE_CONTROL               
> t=1292341087557 [st= 78]    +SPARSE_CONTROL               [dt=  2]
> t=1292341087557 [st= 78]        SPARSE_CONTROL_WRITE      [dt=  2]
>                                 --> source_dependency = {"id":458,"type":9}
> t=1292341087559 [st= 80]    -SPARSE_CONTROL               
> t=1292341087562 [st= 83]    +SPARSE_CONTROL               [dt=  2]
> t=1292341087562 [st= 83]        SPARSE_CONTROL_WRITE      [dt=  1]
>                                 --> source_dependency = {"id":458,"type":9}
> t=1292341087564 [st= 85]    -SPARSE_CONTROL               
> t=1292341087566 [st= 87]    +SPARSE_CONTROL               [dt=  3]
> t=1292341087567 [st= 88]        SPARSE_CONTROL_WRITE      [dt=  2]
>                                 --> source_dependency = {"id":458,"type":9}
> t=1292341087569 [st= 90]    -SPARSE_CONTROL               
> t=1292341087572 [st= 93]    +SPARSE_CONTROL               [dt=  2]
> t=1292341087572 [st= 93]        SPARSE_CONTROL_WRITE      [dt=  2]
>                                 --> source_dependency = {"id":458,"type":9}
> t=1292341087574 [st= 95]    -SPARSE_CONTROL               
> t=1292341087577 [st= 98]    +SPARSE_CONTROL               [dt=  3]
> t=1292341087577 [st= 98]        SPARSE_CONTROL_WRITE      [dt=  2]
>                                 --> source_dependency = {"id":458,"type":9}
> t=1292341087580 [st=101]    -SPARSE_CONTROL               
> t=1292341087593 [st=114]     DISK_CACHE_READ_DATA         [dt=  1]
>                              --> buf_len = 353          
>                              --> index = 0              
>                              --> offset = 0             
> t=1292341087597 [st=118]    +SPARSE_CONTROL               [dt=  6]
> t=1292341087603 [st=124]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
> t=1292341087603 [st=124]    -SPARSE_CONTROL               
> t=1292341087636 [st=157]     DISK_CACHE_WRITE_DATA        [dt=  1]
>                              --> buf_len = 353          
>                              --> index = 0              
>                              --> offset = 0             
>                              --> truncate = true        
> t=1292341087649 [st=170]    +SPARSE_CONTROL               [dt=  3]
> t=1292341087651 [st=172]        SPARSE_CONTROL_WRITE      [dt=  1]
>                                 --> source_dependency = {"id":461,"type":9}
> t=1292341087652 [st=173]    -SPARSE_CONTROL               
> t=1292341087656 [st=177]    +SPARSE_CONTROL               [dt=  2]
> t=1292341087656 [st=177]        SPARSE_CONTROL_WRITE      [dt=  2]
>                                 --> source_dependency = {"id":461,"type":9}
> t=1292341087658 [st=179]    -SPARSE_CONTROL               
> t=1292341087666 [st=187]     DISK_CACHE_WRITE_DATA        [dt=  1]
>                              --> buf_len = 128          
>                              --> index = 2              
>                              --> offset = 64            
> t=1292341087667 [st=188]     DISK_CACHE_CLOSE             
> t=1292341087690 [st=211] -DISK_CACHE_ENTRY

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:641: net::NetLog::TYPE_SPARSE_CONTROL_READ,
It would be helpful to log child_len_ here

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:652: net::NetLog::TYPE_SPARSE_CONTROL_WRITE,
and here

[rvargas (doing something else), 2010-12-14 19:49:36]

s/fell/feel

On 2010/12/14 19:48:57, rvargas wrote:
> LGTM (fell free to leave the small changes to sparse control for another CL).
> 
> For eviction.cc, basically we just need to know when we are evicting entries.
> Look for current Trace() statements in the code.
> 
> One last thing that may be interesting is logging when we delete sparse
> entries... SparseControl::DeleteChildren and ChildrenDeleter
> 
>
http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
> File net/disk_cache/sparse_control.cc (right):
> 
>
http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
> net/disk_cache/sparse_control.cc:226:
> entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
> On 2010/12/14 17:53:43, Matt Menke wrote:
> > On 2010/12/14 00:14:26, rvargas wrote:
> > > On 2010/12/14 00:04:43, Matt Menke wrote:
> > > > On 2010/12/13 23:34:39, rvargas wrote:
> > > > > It would be nice to log |op| here.
> > > > > 
> > > > > Actually, probably it is good enough now. Do you have a sample of how
it
> > > > looks?
> > > > 
> > > > I should have mentioned this earlier...But I'm not quite sure how to
> easily
> > > test
> > > > the sparse control.
> > > 
> > > Just go to a page with HTML5 <video> or <audio>... or view PDFs with our
> > > internal plugin.
> > > 
> > > That reminds me that at some point we should add disk cache tests that
> verify
> > > that the net log has roughly what we want it to have.
> > 
> > I thought about doing that with this CL, but thought it'd be better to iron
> out
> > just what should be logged, first.
> 
> Sure, that's the right thing to do.
> 
> > 
> > Here's a sample entry - might be nice to have a little more information on
> > sparse control events, now that I look at it, though it is already pretty
> noisy
> > as it is:
> 
> Yeah, no (real) need to have |op|, but unless we add logs to ReadSparseData(),
> we need to log here the offset and buf_len... and that is simpler than adding
> logs at the EntryImpl level, at the small cost of not stating obviously that
the
> second and third reads are part of a top level operation.
> 
> 
> > 
> > 
> > t=1292341087479 [st=  0] +DISK_CACHE_ENTRY                [dt=211]
> >                           --> created = false           
> >                           --> key =
> >
>
"http://cdn.kaltura.org/apis/html5lib/kplayer-examples/media/bbb_trailer_360p.webm"
> > t=1292341087482 [st=  3]     DISK_CACHE_READ_DATA         [dt=  0]
> >                              --> buf_len = 353          
> >                              --> index = 0              
> >                              --> offset = 0             
> > t=1292341087484 [st=  5]     DISK_CACHE_READ_DATA         [dt=  0]
> >                              --> buf_len = 64           
> >                              --> index = 2              
> >                              --> offset = 0             
> > t=1292341087484 [st=  5]     DISK_CACHE_READ_DATA         [dt=  1]
> >                              --> buf_len = 128          
> >                              --> index = 2              
> >                              --> offset = 64            
> > t=1292341087485 [st=  6]    +SPARSE_CONTROL               [dt= 17]
> > t=1292341087487 [st=  8]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
> > t=1292341087502 [st= 23]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
> > t=1292341087502 [st= 23]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
> > t=1292341087502 [st= 23]    -SPARSE_CONTROL               
> > t=1292341087537 [st= 58]     DISK_CACHE_WRITE_DATA        [dt=  1]
> >                              --> buf_len = 353          
> >                              --> index = 0              
> >                              --> offset = 0             
> >                              --> truncate = true        
> > t=1292341087549 [st= 70]    +SPARSE_CONTROL               [dt=  4]
> > t=1292341087552 [st= 73]        SPARSE_CONTROL_WRITE      [dt=  0]
> >                                 --> source_dependency = {"id":458,"type":9}
> > t=1292341087553 [st= 74]    -SPARSE_CONTROL               
> > t=1292341087557 [st= 78]    +SPARSE_CONTROL               [dt=  2]
> > t=1292341087557 [st= 78]        SPARSE_CONTROL_WRITE      [dt=  2]
> >                                 --> source_dependency = {"id":458,"type":9}
> > t=1292341087559 [st= 80]    -SPARSE_CONTROL               
> > t=1292341087562 [st= 83]    +SPARSE_CONTROL               [dt=  2]
> > t=1292341087562 [st= 83]        SPARSE_CONTROL_WRITE      [dt=  1]
> >                                 --> source_dependency = {"id":458,"type":9}
> > t=1292341087564 [st= 85]    -SPARSE_CONTROL               
> > t=1292341087566 [st= 87]    +SPARSE_CONTROL               [dt=  3]
> > t=1292341087567 [st= 88]        SPARSE_CONTROL_WRITE      [dt=  2]
> >                                 --> source_dependency = {"id":458,"type":9}
> > t=1292341087569 [st= 90]    -SPARSE_CONTROL               
> > t=1292341087572 [st= 93]    +SPARSE_CONTROL               [dt=  2]
> > t=1292341087572 [st= 93]        SPARSE_CONTROL_WRITE      [dt=  2]
> >                                 --> source_dependency = {"id":458,"type":9}
> > t=1292341087574 [st= 95]    -SPARSE_CONTROL               
> > t=1292341087577 [st= 98]    +SPARSE_CONTROL               [dt=  3]
> > t=1292341087577 [st= 98]        SPARSE_CONTROL_WRITE      [dt=  2]
> >                                 --> source_dependency = {"id":458,"type":9}
> > t=1292341087580 [st=101]    -SPARSE_CONTROL               
> > t=1292341087593 [st=114]     DISK_CACHE_READ_DATA         [dt=  1]
> >                              --> buf_len = 353          
> >                              --> index = 0              
> >                              --> offset = 0             
> > t=1292341087597 [st=118]    +SPARSE_CONTROL               [dt=  6]
> > t=1292341087603 [st=124]        SPARSE_CONTROL_GET_RANGE  [dt=  0]
> > t=1292341087603 [st=124]    -SPARSE_CONTROL               
> > t=1292341087636 [st=157]     DISK_CACHE_WRITE_DATA        [dt=  1]
> >                              --> buf_len = 353          
> >                              --> index = 0              
> >                              --> offset = 0             
> >                              --> truncate = true        
> > t=1292341087649 [st=170]    +SPARSE_CONTROL               [dt=  3]
> > t=1292341087651 [st=172]        SPARSE_CONTROL_WRITE      [dt=  1]
> >                                 --> source_dependency = {"id":461,"type":9}
> > t=1292341087652 [st=173]    -SPARSE_CONTROL               
> > t=1292341087656 [st=177]    +SPARSE_CONTROL               [dt=  2]
> > t=1292341087656 [st=177]        SPARSE_CONTROL_WRITE      [dt=  2]
> >                                 --> source_dependency = {"id":461,"type":9}
> > t=1292341087658 [st=179]    -SPARSE_CONTROL               
> > t=1292341087666 [st=187]     DISK_CACHE_WRITE_DATA        [dt=  1]
> >                              --> buf_len = 128          
> >                              --> index = 2              
> >                              --> offset = 64            
> > t=1292341087667 [st=188]     DISK_CACHE_CLOSE             
> > t=1292341087690 [st=211] -DISK_CACHE_ENTRY
> 
>
http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
> net/disk_cache/sparse_control.cc:641: net::NetLog::TYPE_SPARSE_CONTROL_READ,
> It would be helpful to log child_len_ here
> 
>
http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
> net/disk_cache/sparse_control.cc:652: net::NetLog::TYPE_SPARSE_CONTROL_WRITE,
> and here

[mmenke, 2010-12-14 20:10:21]

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
File net/disk_cache/sparse_control.cc (right):

http://codereview.chromium.org/4067002/diff/251001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:226:
entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
> Yeah, no (real) need to have |op|, but unless we add logs to ReadSparseData(),
> we need to log here the offset and buf_len... and that is simpler than adding
> logs at the EntryImpl level, at the small cost of not stating obviously that
the
> second and third reads are part of a top level operation.
> 

There's no obvious place to log an end event in ReadSparseData() and friends,
too, which is the primary reason I decided to do it in SparseControl instead. 
I'll add the extra parameters in another CL, as you suggest.  Logging child
deletion children also sounds like a good idea to me.

[eroman, 2010-12-23 05:18:33]

Apologies for not commenting yet! (was shortly before I went on vacation).

I'm going to try and do a pass at it tonight, or tomorrow at the latest.

Please harass me over IM if I continue to drop the ball on this :)

[mmenke, 2010-12-23 14:50:51]

On 2010/12/23 05:18:33, eroman wrote:
> Apologies for not commenting yet! (was shortly before I went on vacation).
> 
> I'm going to try and do a pass at it tonight, or tomorrow at the latest.
> 
> Please harass me over IM if I continue to drop the ball on this :)

I'm on vacation for the rest of the month, myself, so there's absolutely no
rush.

[eroman, 2011-01-05 02:39:05]

I defer to Ricardo for the caching-specific logging.
Overall looks good.

http://codereview.chromium.org/4067002/diff/271001/chrome/browser/resources/n...
File chrome/browser/resources/net_internals/logviewpainter.js (right):

http://codereview.chromium.org/4067002/diff/271001/chrome/browser/resources/n...
chrome/browser/resources/net_internals/logviewpainter.js:54:
(!beginEntry.orig.params || !beginEntry.end.orig.params) &&
Can you explain this change? Won't this make it ambiguous as to whether the
extra parameters applied to the BEGIN or END phase?

http://codereview.chromium.org/4067002/diff/271001/chrome/browser/resources/n...
chrome/browser/resources/net_internals/logviewpainter.js:86: stCell.alignRight =
true;
Did any of this, or is it all just indentation differences?

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

http://codereview.chromium.org/4067002/diff/271001/net/base/capturing_net_log...
net/base/capturing_net_log.h:64: // This function is not thread safe, so must
only be called when the
I suggest making this threadsafe -- simply read-write log_level_ while lock_ is
held.

This keeps the API consistent, and shouldnt have a measurable performance
impact.

http://codereview.chromium.org/4067002/diff/271001/net/base/capturing_net_log...
net/base/capturing_net_log.h:106: // This function is not thread safe, so must
only be called when the
Ditto to comment above.

(Also note that if you do that, should change the name to SetLogLevel() since it
is no longer a simple setter).

http://codereview.chromium.org/4067002/diff/271001/net/base/net_log.cc
File net/base/net_log.cc (right):

http://codereview.chromium.org/4067002/diff/271001/net/base/net_log.cc#newcod...
net/base/net_log.cc:169: event_type,
nit: I believe this continuation should be indented by 4. Which will of course
mess up the subsequent line break :)

http://codereview.chromium.org/4067002/diff/271001/net/base/net_log.h
File net/base/net_log.h (right):

http://codereview.chromium.org/4067002/diff/271001/net/base/net_log.h#newcode200
net/base/net_log.h:200: void EndEventWithErrorCode(NetLog::EventType event_type,
int net_error) const;
nit: I suggest calling this "WithNetErrorCode" to emphasize it isn't any-old
error.

I'll bet there are a number of other callsites that could use this, might want
to add a TODO.

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl.cc
File net/disk_cache/entry_impl.cc (right):

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:37: DictionaryValue *dict = new DictionaryValue();
nit: DictionaryValue*

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:67: int index_;
nit: can you make these all const ?

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:106:
entry_->net_log().EndEventWithErrorCode(end_event_type_, bytes_copied);
Would we want to log the actual bytes copied on non-errors? (as I understand the
code, will not log anything if net_error >= 0).

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:1024: const net::BoundNetLog& EntryImpl::net_log()
const {
Is it possible for this to be called before BeginLogging()? Is it valid?

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/sparse_cont...
File net/disk_cache/sparse_control.cc (right):

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:739: switch (operation_) {
I suggest moving this to a helper function.

[mmenke, 2011-01-05 16:32:25]

http://codereview.chromium.org/4067002/diff/271001/chrome/browser/resources/n...
File chrome/browser/resources/net_internals/logviewpainter.js (right):

http://codereview.chromium.org/4067002/diff/271001/chrome/browser/resources/n...
chrome/browser/resources/net_internals/logviewpainter.js:54:
(!beginEntry.orig.params || !beginEntry.end.orig.params) &&
On 2011/01/05 02:39:06, eroman wrote:
> Can you explain this change? Won't this make it ambiguous as to whether the
> extra parameters applied to the BEGIN or END phase?

Not really (To being ambiguous, not to being able to explain the change).  If we
log data for both begin and end phases, they're still kept separate.  When we
only log data for one or the other, which event the data came from tends to be
pretty clear from what the value names are.  In my opinion, this change
significantly increases readability.

As for explaining the change... I find a list of:

[st=107227]    SOCKET_IN_USE           [dt=   112]
               --> source_dependency = {"id":77499,"type":1}
[st=107227]    SOCKET_IN_USE           [dt=   112]
               --> source_dependency = {"id":77499,"type":1}
[st=107227]    SOCKET_IN_USE           [dt=   112]
               --> source_dependency = {"id":77499,"type":1}
[st=107227]    SOCKET_IN_USE           [dt=   112]
               --> source_dependency = {"id":77499,"type":1}

much easier to visually parse than:

[st=107227]   +SOCKET_IN_USE           [dt=   112]
               --> source_dependency = {"id":77499,"type":1}
[st=107339]   -SOCKET_IN_USE           
[st=107227]   +SOCKET_IN_USE           [dt=   112]
               --> source_dependency = {"id":77499,"type":1}
[st=107339]   -SOCKET_IN_USE           
[st=107227]   +SOCKET_IN_USE           [dt=   112]
               --> source_dependency = {"id":77499,"type":1}
[st=107339]   -SOCKET_IN_USE           
[st=107227]   +SOCKET_IN_USE           [dt=   112]
               --> source_dependency = {"id":77499,"type":1}
[st=107339]   -SOCKET_IN_USE           

When there are intervening events, the indentation is easy to pick up on.  When
there aren't, I find visualizing event beginnings/endings at a high level much
more difficult.

If you feel strongly that the second is the way to go, I'm willing to undo the
change, but I don't think making it slightly clearer if a parameter belongs to
the begin or end event is worth significantly increasing the level of visual
noise.

I put the change in this CL because virtually all the new DiskCache events are
paired in this fashion, and I was finding them a little painful to follow.  Of
course, since I added data for the end events of read and write operations, in
response to another of your comments, this argument isn't quite as compelling as
before.

Another option would be to use "<---" for EndEvent results.  Only issue there is
that could be a little misleading at times, since some values labelled with
"--->" would still actually be return values, particularly for events without
begin/end phases.

http://codereview.chromium.org/4067002/diff/271001/chrome/browser/resources/n...
chrome/browser/resources/net_internals/logviewpainter.js:86: stCell.alignRight =
true;
On 2011/01/05 02:39:06, eroman wrote:
> Did any of this, or is it all just indentation differences?

Wish diff handled spaces better.  No, there's absolutely no difference, other
than indentation, other than the change to the first if statement in line 74.

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

http://codereview.chromium.org/4067002/diff/271001/net/base/capturing_net_log...
net/base/capturing_net_log.h:64: // This function is not thread safe, so must
only be called when the
On 2011/01/05 02:39:06, eroman wrote:
> I suggest making this threadsafe -- simply read-write log_level_ while lock_
is
> held.
> 
> This keeps the API consistent, and shouldnt have a measurable performance
> impact.

Done, and renamed to SetLogLevel.

http://codereview.chromium.org/4067002/diff/271001/net/base/capturing_net_log...
net/base/capturing_net_log.h:106: // This function is not thread safe, so must
only be called when the
On 2011/01/05 02:39:06, eroman wrote:
> Ditto to comment above.
> 
> (Also note that if you do that, should change the name to SetLogLevel() since
it
> is no longer a simple setter).

Done.

http://codereview.chromium.org/4067002/diff/271001/net/base/net_log.cc
File net/base/net_log.cc (right):

http://codereview.chromium.org/4067002/diff/271001/net/base/net_log.cc#newcod...
net/base/net_log.cc:169: event_type,
On 2011/01/05 02:39:06, eroman wrote:
> nit: I believe this continuation should be indented by 4. Which will of course
> mess up the subsequent line break :)

Done.  The line breaking rules now haunt my dreams.  Conveniently enough, it
actually doesn't quite mess up the line break here.

http://codereview.chromium.org/4067002/diff/271001/net/base/net_log.h
File net/base/net_log.h (right):

http://codereview.chromium.org/4067002/diff/271001/net/base/net_log.h#newcode200
net/base/net_log.h:200: void EndEventWithErrorCode(NetLog::EventType event_type,
int net_error) const;
On 2011/01/05 02:39:06, eroman wrote:
> nit: I suggest calling this "WithNetErrorCode" to emphasize it isn't any-old
> error.
> 
> I'll bet there are a number of other callsites that could use this, might want
> to add a TODO.

Done and done.

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl.cc
File net/disk_cache/entry_impl.cc (right):

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:37: DictionaryValue *dict = new DictionaryValue();
DOn 2011/01/05 02:39:06, eroman wrote:
> nit: DictionaryValue*

Done.

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:67: int index_;
On 2011/01/05 02:39:06, eroman wrote:
> nit: can you make these all const ?

Done.

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:106:
entry_->net_log().EndEventWithErrorCode(end_event_type_, bytes_copied);
On 2011/01/05 02:39:06, eroman wrote:
> Would we want to log the actual bytes copied on non-errors? (as I understand
the
> code, will not log anything if net_error >= 0).

You do, indeed, understand the code.  With writes, at least, if fewer were
copied than were read, it's actually an error, which would certainly be useful
to know.  I didn't do it mostly for legibility.

Anyways change made.

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/entry_impl....
net/disk_cache/entry_impl.cc:1024: const net::BoundNetLog& EntryImpl::net_log()
const {
On 2011/01/05 02:39:06, eroman wrote:
> Is it possible for this to be called before BeginLogging()? Is it valid?

No, I don't believe it's possible.  The only two functions that create
EntryImpls call BeginLogging(), and don't call the read or write functions
directly or indirectly before then, to the extent of my knowledge.

However, it is valid.  The no-parameter BoundNetLog constructor initializes
net_log_ to NULL, and BoundNetLogs are designed to work when they have a NULL
NetLog.

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/sparse_cont...
File net/disk_cache/sparse_control.cc (right):

http://codereview.chromium.org/4067002/diff/271001/net/disk_cache/sparse_cont...
net/disk_cache/sparse_control.cc:739: switch (operation_) {
On 2011/01/05 02:39:06, eroman wrote:
> I suggest moving this to a helper function.

Done.

[eroman, 2011-01-05 19:17:48]

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

http://codereview.chromium.org/4067002/diff/289044/net/base/capturing_net_log...
net/base/capturing_net_log.cc:44: return log_level_;
Should hold |lock_| when reading this.

[mmenke, 2011-01-05 19:20:33]

Thanks.

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

http://codereview.chromium.org/4067002/diff/289044/net/base/capturing_net_log...
net/base/capturing_net_log.cc:44: return log_level_;
On 2011/01/05 19:17:48, eroman wrote:
> Should hold |lock_| when reading this.

Indeed I should be.  Done.

[eroman, 2011-01-05 19:23:36]

LGTM