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

net/disk_cache/simple/simple_synchronous_entry.cc

 // Copyright (c) 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/disk_cache/simple/simple_synchronous_entry.h"
 
 #include <algorithm>
 #include <cstring>
 #include <functional>
 #include <limits>
@@ skipping 240 matching lines @@
     int buf_len_p)
     : sparse_offset(sparse_offset_p), buf_len(buf_len_p) {}
 
 // static
 void SimpleSynchronousEntry::OpenEntry(
     net::CacheType cache_type,
     const FilePath& path,
     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(
       &out_results->entry_stat, &out_results->stream_0_data,
       &out_results->stream_0_crc32);
   if (out_results->result != net::OK) {
     sync_entry->Doom();
     delete sync_entry;
     out_results->sync_entry = NULL;
     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;
 }
 
 // static
 void SimpleSynchronousEntry::CreateEntry(
     net::CacheType cache_type,
     const FilePath& path,
     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 =
       sync_entry->InitializeForCreate(&out_results->entry_stat);
   if (out_results->result != net::OK) {
     if (out_results->result != net::ERR_FILE_EXISTS)
       sync_entry->Doom();
     delete sync_entry;
     out_results->sync_entry = NULL;
     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
 int SimpleSynchronousEntry::DoomEntry(const FilePath& path,
                                       uint64_t entry_hash) {
   const bool deleted_well = DeleteFilesForEntryHash(path, entry_hash);
   return deleted_well ? net::OK : net::ERR_FAILED;
 }
 
 // static
@@ skipping 1290 matching lines @@
   range.offset = offset;
   range.length = len;
   range.data_crc32 = data_crc32;
   range.file_offset = data_file_offset;
   sparse_ranges_.insert(std::make_pair(offset, range));
 
   return true;
 }
 
 }  // namespace disk_cache