First pass at adding http/backend cache to NetLog

net/disk_cache/sparse_control.cc

Index: net/disk_cache/sparse_control.cc
===================================================================
--- net/disk_cache/sparse_control.cc	(revision 68857)
+++ net/disk_cache/sparse_control.cc	(working copy)
@@ -223,6 +223,7 @@
   finished_ = false;
   abort_ = false;
 
+  entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);

[rvargas (doing something else), 2010/12/13 23:34:39]

It would be nice to log |op| here.

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

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

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]

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 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            

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

Sure, that's the right thing to do.
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.

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

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.

   DoChildrenIO();
 
   if (!pending_) {
@@ -610,8 +611,11 @@
 void SparseControl::DoChildrenIO() {
   while (DoChildIO()) continue;
 
-  if (pending_ && finished_)
-    DoUserCallback();
+  if (finished_) {
+    entry_->net_log().EndEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
+    if (pending_)
+      DoUserCallback();
+  }
 }
 
 bool SparseControl::DoChildIO() {
@@ -632,14 +636,32 @@
   int rv = 0;
   switch (operation_) {
     case kReadOperation:
+      if (entry_->net_log().IsLoggingAllEvents()) {
+        entry_->net_log().BeginEvent(
+            net::NetLog::TYPE_SPARSE_CONTROL_READ,

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

It would be helpful to log child_len_ here

+            make_scoped_refptr(new net::NetLogSourceParameter(
+                "source_dependency",
+                child_->net_log().source())));
+      }
       rv = child_->ReadDataImpl(kSparseData, child_offset_, user_buf_,
                                 child_len_, callback);
       break;
     case kWriteOperation:
+      if (entry_->net_log().IsLoggingAllEvents()) {
+        entry_->net_log().BeginEvent(
+            net::NetLog::TYPE_SPARSE_CONTROL_WRITE,

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

and here

+            make_scoped_refptr(new net::NetLogSourceParameter(
+                "source_dependency",
+                child_->net_log().source())));
+      }
       rv = child_->WriteDataImpl(kSparseData, child_offset_, user_buf_,
                                  child_len_, callback, false);
       break;
     case kGetRangeOperation:
+      if (entry_->net_log().IsLoggingAllEvents()) {
+        entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL_GET_RANGE,
+                                     NULL);
+      }
       rv = DoGetAvailableRange();
       break;
     default:
@@ -712,6 +734,23 @@
 }
 
 void SparseControl::DoChildIOCompleted(int result) {
+  if (entry_->net_log().IsLoggingAllEvents()) {
+    net::NetLog::EventType event_type;
+    switch (operation_) {
+      case kReadOperation:
+        event_type = net::NetLog::TYPE_SPARSE_CONTROL_READ;
+        break;
+      case kWriteOperation:
+        event_type = net::NetLog::TYPE_SPARSE_CONTROL_WRITE;
+        break;
+      case kGetRangeOperation:
+        event_type = net::NetLog::TYPE_SPARSE_CONTROL_GET_RANGE;
+        break;
+      default:
+        NOTREACHED();
+    }
+    entry_->net_log().EndEventWithErrorCode(event_type, result);
+  }
   if (result < 0) {
     // We fail the whole operation if we encounter an error.
     result_ = result;
@@ -737,6 +776,8 @@
     // We'll return the current result of the operation, which may be less than
     // the bytes to read or write, but the user cancelled the operation.
     abort_ = false;
+    entry_->net_log().AddEvent(net::NetLog::TYPE_CANCELLED, NULL);
+    entry_->net_log().EndEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
     DoUserCallback();
     return DoAbortCallbacks();
   }