reapply r70628. It was wrongly blamed for breaking Linux valgrind bots.

The revert was r70688.

original author: Matt Menke
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.

Review URL: http://codereview.chromium.org/6150002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@70716 0039d316-1c4b-4281-b951-d872f2087c98

6 files changed, 114 insertions, 8 deletions

diff --git a/net/base/capturing_net_log.cc b/net/base/capturing_net_log.cc
index fccd5ae..c6d34240 100644
--- a/net/base/capturing_net_log.cc
+++ b/net/base/capturing_net_log.cc
@@ -18,7 +18,9 @@ CapturingNetLog::Entry::Entry(EventType type,
 CapturingNetLog::Entry::~Entry() {}
 
 CapturingNetLog::CapturingNetLog(size_t max_num_entries)
-    : last_id_(-1), max_num_entries_(max_num_entries) {
+    : last_id_(-1),
+      max_num_entries_(max_num_entries),
+      log_level_(LOG_ALL_BUT_BYTES) {
 }
 
 CapturingNetLog::~CapturingNetLog() {}
@@ -39,7 +41,8 @@ uint32 CapturingNetLog::NextID() {
 }
 
 NetLog::LogLevel CapturingNetLog::GetLogLevel() const {
-  return LOG_ALL_BUT_BYTES;
+  AutoLock lock(lock_);
+  return log_level_;
 }
 
 void CapturingNetLog::GetEntries(EntryList* entry_list) const {
@@ -52,6 +55,11 @@ void CapturingNetLog::Clear() {
   entries_.clear();
 }
 
+void CapturingNetLog::SetLogLevel(NetLog::LogLevel log_level) {
+  AutoLock lock(lock_);
+  log_level_ = log_level;
+}
+
 CapturingBoundNetLog::CapturingBoundNetLog(const NetLog::Source& source,
                                            CapturingNetLog* net_log)
     : source_(source), capturing_net_log_(net_log) {
@@ -71,4 +79,8 @@ void CapturingBoundNetLog::Clear() {
   capturing_net_log_->Clear();
 }
 
+void CapturingBoundNetLog::SetLogLevel(NetLog::LogLevel log_level) {
+  capturing_net_log_->SetLogLevel(log_level);
+}
+
 }  // namespace net
diff --git a/net/base/capturing_net_log.h b/net/base/capturing_net_log.h
index 9254725..193d641 100644
--- a/net/base/capturing_net_log.h
+++ b/net/base/capturing_net_log.h
@@ -61,6 +61,8 @@ class CapturingNetLog : public NetLog {
 
   void Clear();
 
+  void SetLogLevel(NetLog::LogLevel log_level);
+
  private:
   // Needs to be "mutable" so can use it in GetEntries().
   mutable Lock lock_;
@@ -71,6 +73,8 @@ class CapturingNetLog : public NetLog {
   size_t max_num_entries_;
   EntryList entries_;
 
+  NetLog::LogLevel log_level_;
+
   DISALLOW_COPY_AND_ASSIGN(CapturingNetLog);
 };
 
@@ -97,6 +101,9 @@ class CapturingBoundNetLog {
 
   void Clear();
 
+  // Sets the log level of the underlying CapturingNetLog.
+  void SetLogLevel(NetLog::LogLevel log_level);
+
  private:
   NetLog::Source source_;
   scoped_ptr<CapturingNetLog> capturing_net_log_;
diff --git a/net/base/net_log.cc b/net/base/net_log.cc
index c9e7319..0f1bac4 100644
--- a/net/base/net_log.cc
+++ b/net/base/net_log.cc
@@ -3,11 +3,13 @@
 // found in the LICENSE file.
 
 #include "net/base/net_log.h"
+
 #include "base/logging.h"
 #include "base/string_number_conversions.h"
 #include "base/time.h"
 #include "base/utf_string_conversions.h"
 #include "base/values.h"
+#include "net/base/net_errors.h"
 
 namespace net {
 
@@ -157,6 +159,18 @@ void BoundNetLog::EndEvent(
   AddEntry(event_type, NetLog::PHASE_END, params);
 }
 
+void BoundNetLog::EndEventWithNetErrorCode(NetLog::EventType event_type,
+                                           int net_error) const {
+  DCHECK_NE(net_error, net::ERR_IO_PENDING);
+  if (net_error >= 0) {
+    EndEvent(event_type, NULL);
+  } else {
+    EndEvent(
+        event_type,
+        make_scoped_refptr(new NetLogIntegerParameter("net_error", net_error)));
+  }
+}
+
 // static
 BoundNetLog BoundNetLog::Make(NetLog* net_log,
                               NetLog::SourceType source_type) {
diff --git a/net/base/net_log.h b/net/base/net_log.h
index b8f903d..1d37129 100644
--- a/net/base/net_log.h
+++ b/net/base/net_log.h
@@ -34,6 +34,8 @@ namespace net {
 // TODO(eroman): Remove the 'const' qualitifer from the BoundNetLog methods.
 // TODO(eroman): Start a new Source each time net::URLRequest redirects
 //               (simpler to reason about each as a separate entity).
+// TODO(mmenke): Replace EndEvent calls with EndEventWithNetErrorCode, where
+//               appropriate.
 
 class NetLog {
  public:
@@ -193,6 +195,13 @@ class BoundNetLog {
   void EndEvent(NetLog::EventType event_type,
                 const scoped_refptr<NetLog::EventParameters>& params) const;
 
+  // Just like EndEvent, except |net_error| is a net error code.  If it's
+  // negative, a parameter called "net_error" with a value of |net_error| is
+  // associated with the event.  Otherwise, the end event has no parameters.
+  // |net_error| must not be ERR_IO_PENDING, as it's not a true error.
+  void EndEventWithNetErrorCode(NetLog::EventType event_type,
+                                int net_error) const;
+
   NetLog::LogLevel GetLogLevel() const;
 
   // Returns true if the log level is LOG_ALL.
diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index f1bc4f8..0f1eecf 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -501,22 +501,85 @@ EVENT_TYPE(URL_REQUEST_REDIRECTED)
 // HttpCache
 // ------------------------------------------------------------------------
 
+// Measures the time while getting a reference to the back end.
+EVENT_TYPE(HTTP_CACHE_GET_BACKEND)
+
 // Measures the time while opening a disk cache entry.
 EVENT_TYPE(HTTP_CACHE_OPEN_ENTRY)
 
 // Measures the time while creating a disk cache entry.
 EVENT_TYPE(HTTP_CACHE_CREATE_ENTRY)
 
+// Measures the time it takes to add a HttpCache::Transaction to an http cache
+// entry's list of active Transactions.
+EVENT_TYPE(HTTP_CACHE_ADD_TO_ENTRY)
+
 // Measures the time while deleting a disk cache entry.
 EVENT_TYPE(HTTP_CACHE_DOOM_ENTRY)
 
-// Measures the time while reading the response info from a disk cache entry.
+// Measures the time while reading/writing a disk cache entry's response headers
+// or metadata.
 EVENT_TYPE(HTTP_CACHE_READ_INFO)
+EVENT_TYPE(HTTP_CACHE_WRITE_INFO)
+
+// Measures the time while reading/writing a disk cache entry's body.
+EVENT_TYPE(HTTP_CACHE_READ_DATA)
+EVENT_TYPE(HTTP_CACHE_WRITE_DATA)
+
+// ------------------------------------------------------------------------
+// Disk Cache
+// ------------------------------------------------------------------------
+
+// The creation/destruction of a disk_cache::EntryImpl object.  The "creation"
+// is considered to be the point at which an Entry is first considered to be
+// good and associated with a key.
+//
+// For the BEGIN phase, the following parameters are attached:
+//   {
+//     "created": <true if the Entry was created, rather than being opened>;
+//     "key": <The Entry's key>;
+//   }
+EVENT_TYPE(DISK_CACHE_ENTRY)
+
+// Logs the time required to read/write data from/to a cache entry.
+//
+// For the BEGIN phase, the following parameters are attached:
+//   {
+//     "index": <Index being read/written>;
+//     "offset": <Offset being read/written>;
+//     "buf_len": <Length of buffer being read to/written from>;
+//     "truncate": <If present for a write, the truncate flag is set to true.
+//                  Not present in reads or writes where it is false>
+//   }
+//
+// For the END phase, the following parameters are attached:
+//   {
+//     "bytes_copied": <Number of bytes copied.  Not present on error>;
+//     "net_error": <Network error code.  Only present on error>;
+//   }
+EVENT_TYPE(DISK_CACHE_READ_DATA)
+EVENT_TYPE(DISK_CACHE_WRITE_DATA)
+
+// Logged when SparseControl starts/stops handling IO for an Entry.
+EVENT_TYPE(SPARSE_CONTROL)
+
+// Logged when SparseControl starts/stops reading/writing a child Entry's data
+//
+// For the BEGIN phase, the following parameters are attached:
+//   {
+//     "source_dependency": <Source id of the child entry>
+//   }
+EVENT_TYPE(SPARSE_CONTROL_READ)
+EVENT_TYPE(SPARSE_CONTROL_WRITE)
+
+// Indicates the time taken by a sparse control to get a range.
+EVENT_TYPE(SPARSE_CONTROL_GET_RANGE)
+
+// Logged when an entry is closed.
+EVENT_TYPE(DISK_CACHE_CLOSE)
 
-// Measures the time that an HttpCache::Transaction is stalled waiting for
-// the cache entry to become available (for example if we are waiting for
-// exclusive access to an existing entry).
-EVENT_TYPE(HTTP_CACHE_WAITING)
+// Logged when an entry is doomed.
+EVENT_TYPE(DISK_CACHE_DOOM)
 
 // ------------------------------------------------------------------------
 // HttpNetworkTransaction
diff --git a/net/base/net_log_source_type_list.h b/net/base/net_log_source_type_list.h
index 231ecd2..ba34955 100644
--- a/net/base/net_log_source_type_list.h
+++ b/net/base/net_log_source_type_list.h
@@ -15,5 +15,6 @@ SOURCE_TYPE(SOCKET, 5)
 SOURCE_TYPE(SPDY_SESSION, 6)
 SOURCE_TYPE(HOST_RESOLVER_IMPL_REQUEST, 7)
 SOURCE_TYPE(HOST_RESOLVER_IMPL_JOB, 8)
+SOURCE_TYPE(DISK_CACHE_ENTRY, 9)
 
-SOURCE_TYPE(COUNT, 9) // Always keep this as the last entry.
+SOURCE_TYPE(COUNT, 10)  // Always keep this as the last entry.