SimpleCache: histogram queuing delays and I/O portion of more ops.

net/disk_cache/simple/simple_synchronous_entry.cc

Index: net/disk_cache/simple/simple_synchronous_entry.cc
diff --git a/net/disk_cache/simple/simple_synchronous_entry.cc b/net/disk_cache/simple/simple_synchronous_entry.cc
index 3ae0d27f595c0e2160472283944635da88743d19..8241238d4aa84424f4af117fd7dedb3213029a49 100644
--- a/net/disk_cache/simple/simple_synchronous_entry.cc
+++ b/net/disk_cache/simple/simple_synchronous_entry.cc
@@ -258,8 +258,12 @@ void SimpleSynchronousEntry::OpenEntry(
     const std::string& key,
     const uint64_t entry_hash,
     const bool had_index,
+    const base::TimeTicks& start_time,
     SimpleEntryCreationResults* out_results) {
-  base::ElapsedTimer open_time;
+  base::TimeTicks start_sync_open_entry = base::TimeTicks::Now();
+  SIMPLE_CACHE_UMA(TIMES, "QueueLatency.OpenEntry", cache_type,
+                   (start_sync_open_entry - start_time));
+
   SimpleSynchronousEntry* sync_entry =
       new SimpleSynchronousEntry(cache_type, path, key, entry_hash, had_index);
   out_results->result = sync_entry->InitializeForOpen(
@@ -272,7 +276,8 @@ void SimpleSynchronousEntry::OpenEntry(
     out_results->stream_0_data = NULL;
     return;
   }
-  UMA_HISTOGRAM_TIMES("SimpleCache.DiskOpenLatency", open_time.Elapsed());
+  UMA_HISTOGRAM_TIMES("SimpleCache.DiskOpenLatency",

[xunjieli, 2017/05/02 18:21:29]

I think it makes sense for DiskOpenLatency to be split by cache subtype like
other SimpleCache stats. One benefit is that on UMA dashboard, you could
associate this with other histograms. If you do not split, you might need to use
filters to make the data comparable, because the number of samples for the
histograms (e.g. SimpleCache.DiskOpenLatency vs
SimpleCache.Http.QueueLatency.CreateEntry) are not the same.


Do we care about the failure case ("result != net::OK") ?

[Maks Orlovich, 2017/05/02 19:49:20]

This is convincing, thanks. (And suggests that I may be missing some
functionality)
Those seem to happen a negligible amount of time. (Except creates on Android
which... is probably worth following up on).

[xunjieli, 2017/05/02 21:25:18]

Acknowledged.

+                      base::TimeTicks::Now() - start_sync_open_entry);
   out_results->sync_entry = sync_entry;
 }
 
@@ -283,8 +288,13 @@ void SimpleSynchronousEntry::CreateEntry(
     const std::string& key,
     const uint64_t entry_hash,
     const bool had_index,
+    const base::TimeTicks& start_time,
     SimpleEntryCreationResults* out_results) {
   DCHECK_EQ(entry_hash, GetEntryHashKey(key));
+  base::TimeTicks start_sync_create_entry = base::TimeTicks::Now();
+  SIMPLE_CACHE_UMA(TIMES, "QueueLatency.CreateEntry", cache_type,
+                   (start_sync_create_entry - start_time));
+
   SimpleSynchronousEntry* sync_entry =
       new SimpleSynchronousEntry(cache_type, path, key, entry_hash, had_index);
   out_results->result =
@@ -297,6 +307,8 @@ void SimpleSynchronousEntry::CreateEntry(
     return;
   }
   out_results->sync_entry = sync_entry;
+  SIMPLE_CACHE_UMA(TIMES, "DiskCreateLatency", cache_type,
+                   base::TimeTicks::Now() - start_sync_create_entry);

[xunjieli, 2017/05/02 18:21:29]

Same here. Do we care about the failure case?

[Maks Orlovich, 2017/05/02 19:49:20]

Acknowledged.

 }
 
 // static