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& time_enqueued,
     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 - time_enqueued));
+
   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());
+  SIMPLE_CACHE_UMA(TIMES, "DiskOpenLatency", cache_type,
+                   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& time_enqueued,
     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 - time_enqueued));
+
   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);
 }
 
 // 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 48 matching lines @@
   } else {
     *out_result = net::ERR_CACHE_READ_FAILURE;
     Doom();
   }
 }
 
 void SimpleSynchronousEntry::WriteData(const EntryOperationData& in_entry_op,
                                        net::IOBuffer* in_buf,
                                        SimpleEntryStat* out_entry_stat,
                                        int* out_result) {
+  base::ElapsedTimer write_time;
   DCHECK(initialized_);
   DCHECK_NE(0, in_entry_op.index);
   int index = in_entry_op.index;
   int file_index = GetFileIndexFromStreamIndex(index);
   if (header_and_key_check_needed_[file_index] &&
       !empty_file_omitted_[file_index] && !CheckHeaderAndKey(file_index)) {
     *out_result = net::ERR_FAILED;
     Doom();
     return;
   }
@@ skipping 60 matching lines @@
     int file_eof_offset =
         out_entry_stat->GetLastEOFOffsetInFile(key_.size(), index);
     if (!files_[file_index].SetLength(file_eof_offset)) {
       RecordWriteResult(cache_type_, WRITE_RESULT_TRUNCATE_FAILURE);
       Doom();
       *out_result = net::ERR_CACHE_WRITE_FAILURE;
       return;
     }
   }
 
+  SIMPLE_CACHE_UMA(TIMES, "DiskWriteLatency", cache_type_,
+                   write_time.Elapsed());
   RecordWriteResult(cache_type_, WRITE_RESULT_SUCCESS);
   base::Time modification_time = Time::Now();
   out_entry_stat->set_last_used(modification_time);
   out_entry_stat->set_last_modified(modification_time);
   *out_result = buf_len;
 }
 
 void SimpleSynchronousEntry::ReadSparseData(
     const EntryOperationData& in_entry_op,
     net::IOBuffer* out_buf,
@@ skipping 221 matching lines @@
     Doom();
     return;
   }
   RecordCheckEOFResult(cache_type_, CHECK_EOF_RESULT_SUCCESS);
 }
 
 void SimpleSynchronousEntry::Close(
     const SimpleEntryStat& entry_stat,
     std::unique_ptr<std::vector<CRCRecord>> crc32s_to_write,
     net::GrowableIOBuffer* stream_0_data) {
+  base::ElapsedTimer close_time;
   DCHECK(stream_0_data);
 
   for (std::vector<CRCRecord>::const_iterator it = crc32s_to_write->begin();
        it != crc32s_to_write->end(); ++it) {
     const int stream_index = it->index;
     const int file_index = GetFileIndexFromStreamIndex(stream_index);
     if (empty_file_omitted_[file_index])
       continue;
 
     if (stream_index == 0) {
@@ skipping 66 matching lines @@
   }
 
   if (sparse_file_open())
     sparse_file_.Close();
 
   if (files_created_) {
     const int stream2_file_index = GetFileIndexFromStreamIndex(2);
     SIMPLE_CACHE_UMA(BOOLEAN, "EntryCreatedAndStream2Omitted", cache_type_,
                      empty_file_omitted_[stream2_file_index]);
   }
+  SIMPLE_CACHE_UMA(TIMES, "DiskCloseLatency", cache_type_,
+                   close_time.Elapsed());
   RecordCloseResult(cache_type_, CLOSE_RESULT_SUCCESS);
   have_open_files_ = false;
   delete this;
 }
 
 SimpleSynchronousEntry::SimpleSynchronousEntry(net::CacheType cache_type,
                                                const FilePath& path,
                                                const std::string& key,
                                                const uint64_t entry_hash,
                                                const bool had_index)
@@ skipping 815 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