Add trace to the caller of QuotaManager::GetAvailableSpace

Add trace to the caller of QuotaManager::GetAvailableSpace and its callbacks (where possible).

BUG=349708
R=kinuko@chromium.org
TBR=tzik@chromium.org

Committed: https://crrev.com/fbe0354f403ff793ccacd4d1e162583c11bd58db
Cr-Commit-Position: refs/heads/master@{#353449}

[oshima, 2015-10-07 16:33:50]

oshima@chromium.org changed reviewers:
+ tzik@chromium.org

[oshima, 2015-10-07 16:38:39]

Patchset #1 (id:1) has been deleted

[oshima, 2015-10-07 16:40:22]

I suspect that callback from one of these callers is blocking IO.

tzik -> chrome/browser/ui/webui/quota_internals/quota_internals_proxy.cc

kinuko -> everything else

[kinuko, 2015-10-08 04:08:44]

Thanks! (Looking)

(CC-ing michaeln, cmumford)

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

lgtm, some are a bit puzzling lut let's add them all for now assuming these are
temporary

Added a few more suggestions too.

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:191: int64
CallSystemGetAmountOfFreeDiskSpace(const base::FilePath& profile_path) {
Let's have a trace here too

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:413: void
DidGetAvailableSpace(QuotaStatusCode status, int64 space) {
Let's add trace here too

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:963: return;
Maybe have a trace here too?

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:1608: void
QuotaManager::DidGetAvailableSpace(int64 space) {
Let's have trace here too

[michaeln, 2015-10-09 00:51:42]

michaeln@chromium.org changed reviewers:
+ michaeln@chromium.org

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

https://codereview.chromium.org/1394563002/diff/20001/content/browser/appcach...
File content/browser/appcache/appcache_storage_impl.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/content/browser/appcach...
content/browser/appcache/appcache_storage_impl.cc:681: void
AppCacheStorageImpl::StoreGroupAndCacheTask::OnQuotaCallback(
If i understand the trace properly, the time is being spent in completion
callbacks rather than in the quotamgr proper. I think tracing methods like this
OnQuotaCallback method are the more interesting ones to trace.

We want to trace anything reachable thru DidGetAvailableSpace(). Given how the
quotamgr works (aggregates completion of multiple internal tasks to finally
complete an external callers request), i think the completion routines of most
async quotamgr api calls are reachable.

https://codereview.chromium.org/1394563002/diff/20001/content/browser/quota_d...
File content/browser/quota_dispatcher_host.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/content/browser/quota_d...
content/browser/quota_dispatcher_host.cc:87: void DidQueryStorageUsageAndQuota(
and this

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:1608: void
QuotaManager::DidGetAvailableSpace(int64 space) {
On 2015/10/08 09:08:44, kinuko wrote:
> Let's have trace here too

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?

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
File storage/browser/quota/storage_monitor.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
storage/browser/quota/storage_monitor.cc:51: void
StorageObserverList::MaybeDispatchEvent(
and this

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
storage/browser/quota/storage_monitor.cc:79:
it->first->OnStorageEvent(dispatch_event);
and these

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
storage/browser/quota/storage_monitor.cc:199: void
HostStorageObservers::GotHostUsageAndQuota(
trace this

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
storage/browser/quota/storage_monitor.cc:220: observers_.OnStorageChange(event);
and these

[oshima, 2015-10-09 16:36:53]

Patchset #2 (id:40001) has been deleted

[oshima, 2015-10-09 16:37:02]

The CQ bit was checked by oshima@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2015-10-09 16:38:55]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1394563002/60001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1394563002/60001

[oshima, 2015-10-09 16:41:06]

Patchset #2 (id:60001) has been deleted

[oshima, 2015-10-09 16:41:31]

The CQ bit was checked by oshima@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2015-10-09 16:42:26]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1394563002/80001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1394563002/80001

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

https://codereview.chromium.org/1394563002/diff/20001/content/browser/appcach...
File content/browser/appcache/appcache_storage_impl.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/content/browser/appcach...
content/browser/appcache/appcache_storage_impl.cc:681: void
AppCacheStorageImpl::StoreGroupAndCacheTask::OnQuotaCallback(
On 2015/10/09 00:51:42, michaeln wrote:
> If i understand the trace properly, the time is being spent in completion
> callbacks rather than in the quotamgr proper. I think tracing methods like
this
> OnQuotaCallback method are the more interesting ones to trace.
> 
> We want to trace anything reachable thru DidGetAvailableSpace(). Given how the
> quotamgr works (aggregates completion of multiple internal tasks to finally
> complete an external callers request), i think the completion routines of most
> async quotamgr api calls are reachable.

That's the theory. I was adding the caller side as some calls are simply
providing callback.
Because QuotaManager calls the callback on IO thread, this can identify which
path is blocking IO.

I added the trace to the callback side where makes sense though.

https://codereview.chromium.org/1394563002/diff/20001/content/browser/quota_d...
File content/browser/quota_dispatcher_host.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/content/browser/quota_d...
content/browser/quota_dispatcher_host.cc:87: void DidQueryStorageUsageAndQuota(
On 2015/10/09 00:51:42, michaeln wrote:
> and this

Done.

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:1608: void
QuotaManager::DidGetAvailableSpace(int64 space) {
On 2015/10/09 00:51:43, michaeln wrote:
> On 2015/10/08 09:08:44, kinuko wrote:
> > Let's have trace here too
> 
> 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?

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

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
File storage/browser/quota/storage_monitor.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
storage/browser/quota/storage_monitor.cc:51: void
StorageObserverList::MaybeDispatchEvent(
On 2015/10/09 00:51:43, michaeln wrote:
> and this

Done.

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
storage/browser/quota/storage_monitor.cc:199: void
HostStorageObservers::GotHostUsageAndQuota(
On 2015/10/09 00:51:43, michaeln wrote:
> trace this

I added trace in OnStorageChange and MaybeDispatchEvent instead.

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/s...
storage/browser/quota/storage_monitor.cc:220: observers_.OnStorageChange(event);
On 2015/10/09 00:51:43, michaeln wrote:
> and these

ditto

[commit-bot: I haz the power, 2015-10-09 17:32:25]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-10-09 17:32:26]

Dry run: This issue passed the CQ dry run.

[michaeln, 2015-10-09 19:00:06]

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:1608: void
QuotaManager::DidGetAvailableSpace(int64 space) {
On 2015/10/09 17:14:09, oshima wrote:
> On 2015/10/09 00:51:43, michaeln wrote:
> > On 2015/10/08 09:08:44, kinuko wrote:
> > > Let's have trace here too
> > 
> > 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?
> 
> Yes. I thought so adding trace here doesn't help much, but I added anyway.

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

https://codereview.chromium.org/1394563002/diff/80001/storage/browser/quota/q...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/80001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:1476: TRACE_EVENT0("io",
"QuotaManager::GetUsageAndQuotaForEviction");
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:00:29]

The CQ bit was checked by oshima@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2015-10-09 21:03:10]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1394563002/100001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1394563002/100001

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

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/20001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:1608: void
QuotaManager::DidGetAvailableSpace(int64 space) {
On 2015/10/09 19:00:05, michaeln wrote:
> On 2015/10/09 17:14:09, oshima wrote:
> > On 2015/10/09 00:51:43, michaeln wrote:
> > > On 2015/10/08 09:08:44, kinuko wrote:
> > > > Let's have trace here too
> > > 
> > > 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?
> > 
> > Yes. I thought so adding trace here doesn't help much, but I added anyway.
> 
> 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

Done.

https://codereview.chromium.org/1394563002/diff/80001/storage/browser/quota/q...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/80001/storage/browser/quota/q...
storage/browser/quota/quota_manager.cc:1476: TRACE_EVENT0("io",
"QuotaManager::GetUsageAndQuotaForEviction");
On 2015/10/09 19:00:05, michaeln wrote:
> 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?

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

[commit-bot: I haz the power, 2015-10-09 21:13:23]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-10-09 21:13:24]

Dry run: Try jobs failed on following builders:
  mac_chromium_gn_rel on tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/mac_chromium_gn_r...)

[oshima, 2015-10-09 21:47:16]

The CQ bit was checked by oshima@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2015-10-09 21:48:53]

Dry run: CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1394563002/120001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1394563002/120001

[michaeln, 2015-10-09 22:10:39]

i'm not sure about all of these either, lgtm with the understanding that some of
these are tempory

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
storage/browser/quota/quota_manager.cc:193: TRACE_EVENT0("io",
"QuotaManager::GetUsageAndQuotaForEviction");
the label s/b "CallSystemGetAmountOfFreeDiskSpace"

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
storage/browser/quota/quota_manager.cc:487: TRACE_EVENT0("io",
"QuotaManager::GetUsageInfoTask::Completed");
label should say "::Run"

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
File storage/browser/quota/quota_task.cc (right):

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
storage/browser/quota/quota_task.cc:14: #include
"base/trace_event/trace_event.h"
use it or lose it

[oshima, 2015-10-09 22:36:48]

I'll remove them once we identify the cause.

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
File storage/browser/quota/quota_manager.cc (right):

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
storage/browser/quota/quota_manager.cc:193: TRACE_EVENT0("io",
"QuotaManager::GetUsageAndQuotaForEviction");
On 2015/10/09 22:10:39, michaeln wrote:
> the label s/b "CallSystemGetAmountOfFreeDiskSpace"

Done.

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
storage/browser/quota/quota_manager.cc:487: TRACE_EVENT0("io",
"QuotaManager::GetUsageInfoTask::Completed");
On 2015/10/09 22:10:39, michaeln wrote:
> label should say "::Run"

Done.

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
File storage/browser/quota/quota_task.cc (right):

https://codereview.chromium.org/1394563002/diff/120001/storage/browser/quota/...
storage/browser/quota/quota_task.cc:14: #include
"base/trace_event/trace_event.h"
On 2015/10/09 22:10:39, michaeln wrote:
> use it or lose it

removed

[oshima, 2015-10-09 23:54:56]

tbr'ing tzik@ as the change is trivial.

[oshima, 2015-10-10 00:09:52]

The CQ bit was checked by oshima@chromium.org

[oshima, 2015-10-10 00:09:52]

The patchset sent to the CQ was uploaded after l-g-t-m from kinuko@chromium.org,
michaeln@chromium.org
Link to the patchset: https://codereview.chromium.org/1394563002/#ps180001
(title: " ")

[commit-bot: I haz the power, 2015-10-10 00:11:56]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1394563002/180001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1394563002/180001

[commit-bot: I haz the power, 2015-10-10 01:16:59]

Committed patchset #7 (id:180001)

[commit-bot: I haz the power, 2015-10-10 01:17:35]

Patchset 7 (id:??) landed as
https://crrev.com/fbe0354f403ff793ccacd4d1e162583c11bd58db
Cr-Commit-Position: refs/heads/master@{#353449}