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 148 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) {

[kinuko, 2015/10/08 09:08:44]

Let's have a trace here too

   // 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 201 matching lines @@
     CheckCompleted();
   }
 
   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) {

[kinuko, 2015/10/08 09:08:44]

Let's add trace here too

     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 529 matching lines @@
     return;
   }
 
   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;

[kinuko, 2015/10/08 09:08:44]

Maybe have a trace here too?

 
   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");
+
   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 119 matching lines @@
       base::Bind(&QuotaManager::DidInitializeTemporaryOriginsInfo,
                  weak_factory_.GetWeakPtr()));
 }
 
 void QuotaManager::DidInitializeTemporaryOriginsInfo(bool success) {
   DidDatabaseWork(success);
   if (success)
     StartEviction();
 }
 
 void QuotaManager::DidGetAvailableSpace(int64 space) {

[kinuko, 2015/10/08 09:08:44]

Let's have trace here too

[michaeln, 2015/10/09 00:51:43]

Yes, i think this is the root of what we want to trace. This function and each
function that can be reached herein. 

This is what the trace shows took 10 seconds, right?

[oshima, 2015/10/09 17:14:09]

Yes. I thought so adding trace here doesn't help much, but I added anyway.

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

it could help. there are at least two possibilities
1. a particular completion callback is taking a really long time
2. there are a lot of callbacks to call, none of which individually take very
long, but there is a pathologically long list of them

TRACE_EVENT1("io", "QuotaManager::DidGetAvailableSpace",
             "n_callbacks", available_space_callbacks_.size());

could tell us which it is

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

Done.

   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