Add trace to the caller of QuotaManager::GetAvailableSpace

storage/browser/quota/quota_manager.cc

 // Copyright 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 "storage/browser/quota/quota_manager.h"
 
 #include <algorithm>
 #include <functional>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/command_line.h"
 #include "base/files/file_util.h"
 #include "base/metrics/histogram.h"
 #include "base/profiler/scoped_tracker.h"
 #include "base/sequenced_task_runner.h"
 #include "base/single_thread_task_runner.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/sys_info.h"
 #include "base/task_runner_util.h"
 #include "base/time/time.h"
+#include "base/trace_event/trace_event.h"
 #include "net/base/net_util.h"
 #include "storage/browser/quota/client_usage_tracker.h"
 #include "storage/browser/quota/quota_manager_proxy.h"
 #include "storage/browser/quota/quota_temporary_storage_evictor.h"
 #include "storage/browser/quota/storage_monitor.h"
 #include "storage/browser/quota/usage_tracker.h"
 #include "storage/common/quota/quota_types.h"
 
 #define UMA_HISTOGRAM_MBYTES(name, sample)          \
   UMA_HISTOGRAM_CUSTOM_COUNTS(                      \
@@ skipping 149 matching lines @@
 
 bool UpdateModifiedTimeOnDBThread(const GURL& origin,
                                   StorageType type,
                                   base::Time modified_time,
                                   QuotaDatabase* database) {
   DCHECK(database);
   return database->SetOriginLastModifiedTime(origin, type, modified_time);
 }
 
 int64 CallSystemGetAmountOfFreeDiskSpace(const base::FilePath& profile_path) {
+  // crbug.com/349708
+  TRACE_EVENT0("io", "QuotaManager::GetUsageAndQuotaForEviction");
+
   // Ensure the profile path exists.
   if (!base::CreateDirectory(profile_path)) {
     LOG(WARNING) << "Create directory failed for path" << profile_path.value();
     return 0;
   }
   return base::SysInfo::AmountOfFreeDiskSpace(profile_path);
 }
 
 int64 CalculateTemporaryGlobalQuota(int64 global_limited_usage,
                                     int64 available_space) {
@@ skipping 202 matching lines @@
   }
 
   void DidGetQuota(QuotaStatusCode status, int64 quota) {
     if (status_ == kQuotaStatusUnknown || status_ == kQuotaStatusOk)
       status_ = status;
     usage_and_quota_.quota = quota;
     CheckCompleted();
   }
 
   void DidGetAvailableSpace(QuotaStatusCode status, int64 space) {
+    // crbug.com/349708
+    TRACE_EVENT0(
+        "io", "UsageAndQuotaCallbackDispatcher::DidGetAvailableSpace");
+
     DCHECK_GE(space, 0);
     if (status_ == kQuotaStatusUnknown || status_ == kQuotaStatusOk)
       status_ = status;
     usage_and_quota_.available_disk_space = space;
     CheckCompleted();
   }
 
   void Run() override {
     // We initialize waiting_callbacks to 1 so that we won't run
     // the completion callback until here even some of the callbacks
@@ skipping 530 matching lines @@
   }
 
   HostDataDeleter* deleter =
       new HostDataDeleter(this, host, type, quota_client_mask, callback);
   deleter->Start();
 }
 
 void QuotaManager::GetAvailableSpace(const AvailableSpaceCallback& callback) {
   if (!available_space_callbacks_.Add(callback))
     return;
+  // crbug.com/349708
+  TRACE_EVENT0("io", "QuotaManager::GetAvailableSpace");
 
   PostTaskAndReplyWithResult(db_thread_.get(),
                              FROM_HERE,
                              base::Bind(get_disk_space_fn_, profile_path_),
                              base::Bind(&QuotaManager::DidGetAvailableSpace,
                                         weak_factory_.GetWeakPtr()));
 }
 
 void QuotaManager::GetTemporaryGlobalQuota(const QuotaCallback& callback) {
   LazyInitialize();
@@ skipping 482 matching lines @@
   eviction_context_.evicted_type = type;
   eviction_context_.evict_origin_data_callback = callback;
 
   DeleteOriginData(origin, type, QuotaClient::kAllClientsMask,
                    base::Bind(&QuotaManager::DidOriginDataEvicted,
                               weak_factory_.GetWeakPtr()));
 }
 
 void QuotaManager::GetUsageAndQuotaForEviction(
     const UsageAndQuotaCallback& callback) {
+  // crbug.com/349708
+  TRACE_EVENT0("io", "QuotaManager::GetUsageAndQuotaForEviction");

[michaeln, 2015/10/09 19:00:05]

fyi: i think many of the quota systems async apis can complete immediately
(invoke the callback prior to return) or really do it asyncly. for example, it's
possible for UsageAndQuotaCallbackDispatcher::Complete to run prior to return
from this method. we'll have to keep that in mind when interpreting the results.

it might make sense to put a trace in QuotaTask::CallCompleted to help with
distinguishing between the immediate vs async completion cases?

[oshima, 2015/10/09 21:07:00]

We can tell it from the stack in the trace. I did add traces to all Completed
implementation though.

+
   DCHECK(io_thread_->BelongsToCurrentThread());
   LazyInitialize();
 
   UsageAndQuotaCallbackDispatcher* dispatcher =
       new UsageAndQuotaCallbackDispatcher(this);
   GetUsageTracker(kStorageTypeTemporary)
       ->GetGlobalLimitedUsage(dispatcher->GetGlobalLimitedUsageCallback());
   GetTemporaryGlobalQuota(dispatcher->GetQuotaCallback());
   GetAvailableSpace(dispatcher->GetAvailableSpaceCallback());
   dispatcher->WaitForResults(callback);
@@ skipping 120 matching lines @@
                  weak_factory_.GetWeakPtr()));
 }
 
 void QuotaManager::DidInitializeTemporaryOriginsInfo(bool success) {
   DidDatabaseWork(success);
   if (success)
     StartEviction();
 }
 
 void QuotaManager::DidGetAvailableSpace(int64 space) {
+  // crbug.com/349708
+  TRACE_EVENT0("io", "QuotaManager::DidGetAvailableSpace");
+
   available_space_callbacks_.Run(kQuotaStatusOk, space);
 }
 
 void QuotaManager::DidDatabaseWork(bool success) {
   db_disabled_ = !success;
 }
 
 void QuotaManager::DeleteOnCorrectThread() const {
   if (!io_thread_->BelongsToCurrentThread() &&
       io_thread_->DeleteSoon(FROM_HERE, this)) {
@@ skipping 10 matching lines @@
   // |database_|, therefore we can be sure that database_ is alive when this
   // task runs.
   base::PostTaskAndReplyWithResult(
       db_thread_.get(),
       from_here,
       base::Bind(task, base::Unretained(database_.get())),
       reply);
 }
 
 }  // namespace storage