Add trace events for disk_cache BackendImpl for slow-reports

Adding standard trace events to help investigating net::disk_cache
from the field using slow-reports.

R=morlovich@chromium.org, gab@chromium.org

Bug: 1065004
Change-Id: I0e2d2a87cc8071ae722ee163d7591d002c93caaf
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2122390
Commit-Queue: Etienne Bergeron <etienneb@chromium.org>
Reviewed-by: oysteine <oysteine@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Reviewed-by: Maksim Orlovich <morlovich@chromium.org>
Cr-Commit-Position: refs/heads/master@{#753813}

base/trace_event/builtin_categories.h

@@ -60,6 +60,7 @@
   X("devtools")                                                          \
   X("devtools.timeline")                                                 \
   X("devtools.timeline.async")                                           \
+  X("disk_cache")                                                        \
   X("download")                                                          \
   X("download_service")                                                  \
   X("drm")                                                               \

net/disk_cache/blockfile/backend_impl.cc

@@ -31,6 +31,7 @@
 #include "base/time/time.h"
 #include "base/timer/timer.h"
 #include "base/trace_event/process_memory_dump.h"
+#include "base/trace_event/trace_event.h"
 #include "net/base/net_errors.h"
 #include "net/disk_cache/backend_cleanup_tracker.h"
 #include "net/disk_cache/blockfile/disk_format.h"
@@ -172,7 +173,9 @@ BackendImpl::BackendImpl(
       consider_evicting_at_op_end_(false),
       net_log_(net_log),
       done_(base::WaitableEvent::ResetPolicy::MANUAL,
-            base::WaitableEvent::InitialState::NOT_SIGNALED) {}
+            base::WaitableEvent::InitialState::NOT_SIGNALED) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::BackendImpl");
+}
 
 BackendImpl::BackendImpl(
     const base::FilePath& path,
@@ -200,9 +203,12 @@ BackendImpl::BackendImpl(
       consider_evicting_at_op_end_(false),
       net_log_(net_log),
       done_(base::WaitableEvent::ResetPolicy::MANUAL,
-            base::WaitableEvent::InitialState::NOT_SIGNALED) {}
+            base::WaitableEvent::InitialState::NOT_SIGNALED) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::BackendImpl");
+}
 
 BackendImpl::~BackendImpl() {
+  TRACE_EVENT0("disk_cache", "BackendImpl::~BackendImpl");
   if (user_flags_ & kNoRandom) {
     // This is a unit test, so we want to be strict about not leaking entries
     // and completing all the work.
@@ -232,6 +238,8 @@ net::Error BackendImpl::Init(CompletionOnceCallback callback) {
 }
 
 int BackendImpl::SyncInit() {
+  TRACE_EVENT0("disk_cache", "BackendImpl::SyncInit");
+
 #if defined(NET_BUILD_STRESS_CACHE)
   // Start evictions right away.
   up_ticks_ = kTrimDelay * 2;
@@ -342,6 +350,8 @@ int BackendImpl::SyncInit() {
 
 void BackendImpl::CleanupCache() {
   DCHECK(background_queue_.BackgroundIsCurrentSequence());
+  TRACE_EVENT0("disk_cache", "BackendImpl::CleanupCache");
+
   eviction_.Stop();
   timer_.reset();
 
@@ -414,6 +424,8 @@ int BackendImpl::SyncDoomAllEntries() {
 
 int BackendImpl::SyncDoomEntriesBetween(const base::Time initial_time,
                                         const base::Time end_time) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::SyncDoomEntriesBetween");
+
   DCHECK_NE(net::APP_CACHE, GetCacheType());
   if (end_time.is_null())
     return SyncDoomEntriesSince(initial_time);
@@ -446,6 +458,8 @@ int BackendImpl::SyncDoomEntriesBetween(const base::Time initial_time,
 }
 
 int BackendImpl::SyncCalculateSizeOfAllEntries() {
+  TRACE_EVENT0("disk_cache", "BackendImpl::SyncCalculateSizeOfAllEntries");
+
   DCHECK_NE(net::APP_CACHE, GetCacheType());
   if (disabled_)
     return net::ERR_FAILED;
@@ -456,6 +470,8 @@ int BackendImpl::SyncCalculateSizeOfAllEntries() {
 // We use OpenNextEntryImpl to retrieve elements from the cache, until we get
 // entries that are too old.
 int BackendImpl::SyncDoomEntriesSince(const base::Time initial_time) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::SyncDoomEntriesSince");
+
   DCHECK_NE(net::APP_CACHE, GetCacheType());
   if (disabled_)
     return net::ERR_FAILED;
@@ -482,6 +498,8 @@ int BackendImpl::SyncDoomEntriesSince(const base::Time initial_time) {
 
 int BackendImpl::SyncOpenNextEntry(Rankings::Iterator* iterator,
                                    scoped_refptr<EntryImpl>* next_entry) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::SyncOpenNextEntry");
+
   *next_entry = OpenNextEntryImpl(iterator);
   return (*next_entry) ? net::OK : net::ERR_FAILED;
 }
@@ -504,6 +522,8 @@ void BackendImpl::SyncOnExternalCacheHit(const std::string& key) {
 }
 
 scoped_refptr<EntryImpl> BackendImpl::OpenEntryImpl(const std::string& key) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::OpenEntryImpl");
+
   if (disabled_)
     return nullptr;
 
@@ -542,6 +562,8 @@ scoped_refptr<EntryImpl> BackendImpl::OpenEntryImpl(const std::string& key) {
 }
 
 scoped_refptr<EntryImpl> BackendImpl::CreateEntryImpl(const std::string& key) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::CreateEntryImpl");
+
   if (disabled_ || key.empty())
     return nullptr;
 
@@ -738,6 +760,7 @@ base::WeakPtr<InFlightBackendIO> BackendImpl::GetBackgroundQueue() {
 }
 
 bool BackendImpl::CreateExternalFile(Addr* address) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::CreateExternalFile");
   int file_number = data_->header.last_file + 1;
   Addr file_address(0);
   bool success = false;
@@ -1513,6 +1536,8 @@ void BackendImpl::StoreStats() {
 }
 
 void BackendImpl::RestartCache(bool failure) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::RestartCache");
+
   int64_t errors = stats_.GetCounter(Stats::FATAL_ERROR);
   int64_t full_dooms = stats_.GetCounter(Stats::DOOM_CACHE);
   int64_t partial_dooms = stats_.GetCounter(Stats::DOOM_RECENT);
@@ -1633,6 +1658,8 @@ scoped_refptr<EntryImpl> BackendImpl::MatchEntry(const std::string& key,
                                                  bool find_parent,
                                                  Addr entry_addr,
                                                  bool* match_error) {
+  TRACE_EVENT0("disk_cache", "BackendImpl::MatchEntry");
+
   Addr address(data_->table[hash & mask_]);
   scoped_refptr<EntryImpl> cache_entry, parent_entry;
   bool found = false;

net/disk_cache/blockfile/eviction.cc

@@ -41,6 +41,7 @@
 #include "base/strings/string_util.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/time/time.h"
+#include "base/trace_event/trace_event.h"
 #include "net/disk_cache/blockfile/backend_impl.h"
 #include "net/disk_cache/blockfile/disk_format.h"
 #include "net/disk_cache/blockfile/entry_impl.h"
@@ -112,6 +113,7 @@ void Eviction::Stop() {
 }
 
 void Eviction::TrimCache(bool empty) {
+  TRACE_EVENT0("disk_cache", "Eviction::TrimCache");
   if (backend_->disabled_ || trimming_)
     return;
 
@@ -203,6 +205,8 @@ void Eviction::SetTestMode() {
 }
 
 void Eviction::TrimDeletedList(bool empty) {
+  TRACE_EVENT0("disk_cache", "Eviction::TrimDeletedList");
+
   DCHECK(test_mode_ && new_eviction_);
   TrimDeleted(empty);
 }
@@ -306,6 +310,8 @@ bool Eviction::EvictEntry(CacheRankingsBlock* node, bool empty,
 // -----------------------------------------------------------------------
 
 void Eviction::TrimCacheV2(bool empty) {
+  TRACE_EVENT0("disk_cache", "Eviction::TrimCacheV2");
+
   trimming_ = true;
   TimeTicks start = TimeTicks::Now();
 
@@ -482,6 +488,8 @@ Rankings::List Eviction::GetListForEntryV2(EntryImpl* entry) {
 // This is a minimal implementation that just discards the oldest nodes.
 // TODO(rvargas): Do something better here.
 void Eviction::TrimDeleted(bool empty) {
+  TRACE_EVENT0("disk_cache", "Eviction::TrimDeleted");
+
   if (backend_->disabled_)
     return;