Extract trace from TaskAnnotator::RunTask to its call sites

Extract trace from TaskAnnotator::RunTask to its call sites

This extracts TRACE_EVENT() that brackets the task being executed
from TaskAnnotator::RunTask() to its call sites, so that it covers
time spent in the task observers on the top level (i.e. in MessageLoop).

BUG=508005
TBR=chirantan

Committed: https://crrev.com/596ad0cca35be6b20afba297d3e8c26ae52e3ec2
Cr-Commit-Position: refs/heads/master@{#339091}

[caseq, 2015-07-15 17:35:14]

caseq@chromium.org changed reviewers:
+ danakj@chromium.org, dsinclair@chromium.org

[caseq, 2015-07-15 17:35:15]

Dana, ptal -- this is the "plan b" that we discussed in
https://codereview.chromium.org/1225333002, as the original CL has indeed
regressed the performance.

Note that this only includes task observers that run in MessageLoop, but I think
this is fine^W a reasonable compromise -- the objective is to have better
coverage for the top level of run loop and the task observers are supposed to
either be fast or be additionally instrumented.

[Sami, 2015-07-15 17:44:00]

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

[Sami, 2015-07-15 17:44:00]

https://codereview.chromium.org/1237283006/diff/1/base/debug/task_annotator.cc
File base/debug/task_annotator.cc (left):

https://codereview.chromium.org/1237283006/diff/1/base/debug/task_annotator.c...
base/debug/task_annotator.cc:42: // When tracing memory for posted tasks it's
more valuable to attribute the
Drive-by: would it work if we split this into TRACE_EVENT_BEGIN and
TRACE_EVENT_END which could be called from different spots in the message loop
(and other call sites)? We could change the macros in trace_event.h if they
don't currently allow this.

https://codereview.chromium.org/1237283006/diff/1/base/debug/task_annotator.h
File base/debug/task_annotator.h (right):

https://codereview.chromium.org/1237283006/diff/1/base/debug/task_annotator.h...
base/debug/task_annotator.h:28: // passed into |DidQueueTask| for this task.
|run_function| is used as the
Please update this comment.

[dsinclair, 2015-07-15 17:58:28]

lgtm

https://codereview.chromium.org/1237283006/diff/1/base/debug/task_annotator.cc
File base/debug/task_annotator.cc (left):

https://codereview.chromium.org/1237283006/diff/1/base/debug/task_annotator.c...
base/debug/task_annotator.cc:42: // When tracing memory for posted tasks it's
more valuable to attribute the
On 2015/07/15 17:44:00, Sami wrote:
> Drive-by: would it work if we split this into TRACE_EVENT_BEGIN and
> TRACE_EVENT_END which could be called from different spots in the message loop
> (and other call sites)? We could change the macros in trace_event.h if they
> don't currently allow this.

You'd need to use an async event or something other then a regular event to do
that. Otherwise, we're going to think the slice is the total time between the
two points which isn't correct.

[danakj, 2015-07-15 18:03:23]

https://codereview.chromium.org/1237283006/diff/1/components/scheduler/child/...
File components/scheduler/child/task_queue_manager.cc (right):

https://codereview.chromium.org/1237283006/diff/1/components/scheduler/child/...
components/scheduler/child/task_queue_manager.cc:694:
TRACE_EVENT_WITH_MEMORY_TAG2(
Why don't you include WillProcessTask here?

https://codereview.chromium.org/1237283006/diff/1/components/timers/alarm_tim...
File components/timers/alarm_timer_chromeos.cc (right):

https://codereview.chromium.org/1237283006/diff/1/components/timers/alarm_tim...
components/timers/alarm_timer_chromeos.cc:431: TRACE_EVENT_WITH_MEMORY_TAG2(
You want to cover the time in this function right? That's the point of moving
it? Why doesn't this trace cover the things this function is doing above then?

[Sami, 2015-07-15 18:06:52]

https://codereview.chromium.org/1237283006/diff/1/base/debug/task_annotator.cc
File base/debug/task_annotator.cc (left):

https://codereview.chromium.org/1237283006/diff/1/base/debug/task_annotator.c...
base/debug/task_annotator.cc:42: // When tracing memory for posted tasks it's
more valuable to attribute the
On 2015/07/15 17:58:28, dsinclair wrote:
> On 2015/07/15 17:44:00, Sami wrote:
> > Drive-by: would it work if we split this into TRACE_EVENT_BEGIN and
> > TRACE_EVENT_END which could be called from different spots in the message
loop
> > (and other call sites)? We could change the macros in trace_event.h if they
> > don't currently allow this.
> 
> You'd need to use an async event or something other then a regular event to do
> that. Otherwise, we're going to think the slice is the total time between the
> two points which isn't correct.

Hmm, I thought the idea here was to include those things in the duration of the
trace event, i.e., make it cover more of the execution? Or did I miss something?

[caseq, 2015-07-15 19:36:38]

On 2015/07/15 18:03:23, danakj wrote:
>
https://codereview.chromium.org/1237283006/diff/1/components/scheduler/child/...
> File components/scheduler/child/task_queue_manager.cc (right):
> 
>
https://codereview.chromium.org/1237283006/diff/1/components/scheduler/child/...
> components/scheduler/child/task_queue_manager.cc:694:
> TRACE_EVENT_WITH_MEMORY_TAG2(
> Why don't you include WillProcessTask here?

I don't mind to include them if you say we should, but I don't really need it
here (because this is is always nested within the event emitted from
MessageLoop) and the fact that we would include DidProcessTask from the previous
task may be somewhat confusing -- so since the presence of trace here is to
provide details on the origin of the task rather than accurate top-level
coverage, I thought we can omit the observer methods.
 
>
https://codereview.chromium.org/1237283006/diff/1/components/timers/alarm_tim...
> File components/timers/alarm_timer_chromeos.cc (right):
> 
>
https://codereview.chromium.org/1237283006/diff/1/components/timers/alarm_tim...
> components/timers/alarm_timer_chromeos.cc:431: TRACE_EVENT_WITH_MEMORY_TAG2(
> You want to cover the time in this function right? That's the point of moving
> it? Why doesn't this trace cover the things this function is doing above then?

No, the target is the one in MessageLoop::RunTask() and the other two are just
collateral damage, as they are always nested into the former one and my point is
to reduce non-covered top-level code to minimum (and this is why I think it's
not important whether we include observer methods for these).

[caseq, 2015-07-15 19:43:56]

On 2015/07/15 18:06:52, Sami wrote:

> Drive-by: would it work if we split this into TRACE_EVENT_BEGIN and
> TRACE_EVENT_END which could be called from different spots in the message loop
> (and other call sites)? We could change the macros in trace_event.h if they
> don't currently allow this.

+1 to what Dan says -- tracing clients critically depend on synchronous events
being properly nested, so every time we're not using scoped trace events it's a
sort of land mine, especially if the order of begin/end events is governed by
logic outside of the method. So while technically we could do this now, I'd like
to avoid this unless this is absolutely necessary on the ground of robustness
and maintainability.

> > 
> > You'd need to use an async event or something other then a regular event to
do
> > that. Otherwise, we're going to think the slice is the total time between
the
> > two points which isn't correct.
> 
> Hmm, I thought the idea here was to include those things in the duration of
the
> trace event, i.e., make it cover more of the execution? Or did I miss
something?

Yes, but this call site is different in that it is already nested into
MessageLoop::RunTask() and hence covered with a top-level trace event.

[Sami, 2015-07-15 19:53:44]

On 2015/07/15 19:43:56, caseq wrote:
> On 2015/07/15 18:06:52, Sami wrote:
> 
> > Drive-by: would it work if we split this into TRACE_EVENT_BEGIN and
> > TRACE_EVENT_END which could be called from different spots in the message
loop
> > (and other call sites)? We could change the macros in trace_event.h if they
> > don't currently allow this.
> 
> +1 to what Dan says -- tracing clients critically depend on synchronous events
> being properly nested, so every time we're not using scoped trace events it's
a
> sort of land mine, especially if the order of begin/end events is governed by
> logic outside of the method. So while technically we could do this now, I'd
like
> to avoid this unless this is absolutely necessary on the ground of robustness
> and maintainability.
> 
> > > 
> > > You'd need to use an async event or something other then a regular event
to
> do
> > > that. Otherwise, we're going to think the slice is the total time between
> the
> > > two points which isn't correct.
> > 
> > Hmm, I thought the idea here was to include those things in the duration of
> the
> > trace event, i.e., make it cover more of the execution? Or did I miss
> something?
> 
> Yes, but this call site is different in that it is already nested into
> MessageLoop::RunTask() and hence covered with a top-level trace event.

To avoid confusion, what I was proposing was that TaskAnnotator would expose a
pair like BeginTask/EndTask which MessageLoop and anyone else could use to
expand the processing scope of a task. If we're worried about misuse of that
API, we could DCHECK the calls are always balanced.

I'm not too opposed to the code duplication here, but I just wanted to throw the
alternative out there.

[danakj, 2015-07-16 01:01:42]

https://codereview.chromium.org/1237283006/diff/1/components/scheduler/child/...
File components/scheduler/child/task_queue_manager.cc (right):

https://codereview.chromium.org/1237283006/diff/1/components/scheduler/child/...
components/scheduler/child/task_queue_manager.cc:695: "toplevel",
Then does it make sense to add these other "toplevel" traces if they are nested
within the messageloop one? Maybe we should just not add them?

Otherwise, LGTM % skyostil

[caseq, 2015-07-16 07:40:18]

caseq@chromium.org changed reviewers:
+ nduca@google.com

[caseq, 2015-07-16 07:40:18]

On 2015/07/16 01:01:42, danakj wrote:
>
https://codereview.chromium.org/1237283006/diff/1/components/scheduler/child/...
> File components/scheduler/child/task_queue_manager.cc (right):
> 
>
https://codereview.chromium.org/1237283006/diff/1/components/scheduler/child/...
> components/scheduler/child/task_queue_manager.cc:695: "toplevel",
> Then does it make sense to add these other "toplevel" traces if they are
nested
> within the messageloop one? Maybe we should just not add them?

I'm all for that, but I'm afraid this could be used somewhere to track the
origin of tasks posted. Dan, Nat, what do you think, can we drop traces from
TaskQueueManager and AlarmTimer::OnTimerFired()?

[Sami, 2015-07-16 08:11:10]

On 2015/07/16 07:40:18, caseq wrote:
> I'm all for that, but I'm afraid this could be used somewhere to track the
> origin of tasks posted. Dan, Nat, what do you think, can we drop traces from
> TaskQueueManager and AlarmTimer::OnTimerFired()?

Right, the traces in the TaskQueueManager are very useful for that since the
MessageLoop one is just a generic placeholder in that case. The AlarmTimer one
looks similar.

I think what we have here works too, so lgtm % updating the comment in
task_annotator.h.

One final free idea -- feel free to ignore: we could make the trace event call a
macro in task_annotator.h so it would all be in one place.

(+cc primiano just in case this affects their plans for memory tracing.)

[caseq, 2015-07-16 10:40:58]

Patchset #2 (id:20001) has been deleted

[caseq, 2015-07-16 13:02:17]

On 2015/07/16 08:11:10, Sami wrote:
> On 2015/07/16 07:40:18, caseq wrote:
> > I'm all for that, but I'm afraid this could be used somewhere to track the
> > origin of tasks posted. Dan, Nat, what do you think, can we drop traces from
> > TaskQueueManager and AlarmTimer::OnTimerFired()?
> 
> Right, the traces in the TaskQueueManager are very useful for that since the
> MessageLoop one is just a generic placeholder in that case. The AlarmTimer one
> looks similar.
> 
> I think what we have here works too, so lgtm % updating the comment in
> task_annotator.h.
> 
> One final free idea -- feel free to ignore: we could make the trace event call
a
> macro in task_annotator.h so it would all be in one place.

Thanks, done!

[caseq, 2015-07-16 13:02:23]

The CQ bit was checked by caseq@chromium.org

[caseq, 2015-07-16 13:02:23]

The patchset sent to the CQ was uploaded after l-g-t-m from danakj@chromium.org,
dsinclair@chromium.org, skyostil@chromium.org
Link to the patchset: https://codereview.chromium.org/1237283006/#ps40001
(title: "review comments addressed")

[commit-bot: I haz the power, 2015-07-16 13:02:37]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1237283006/40001

[commit-bot: I haz the power, 2015-07-16 13:10:23]

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

[commit-bot: I haz the power, 2015-07-16 13:10:24]

Try jobs failed on following builders:
  chromium_presubmit on tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/chromium_presub...)

[caseq, 2015-07-16 13:52:22]

The CQ bit was checked by caseq@chromium.org

[caseq, 2015-07-16 13:52:23]

The patchset sent to the CQ was uploaded after l-g-t-m from danakj@chromium.org,
dsinclair@chromium.org, skyostil@chromium.org
Link to the patchset: https://codereview.chromium.org/1237283006/#ps60001
(title: "fixed a test")

[commit-bot: I haz the power, 2015-07-16 13:53:55]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1237283006/60001

[commit-bot: I haz the power, 2015-07-16 14:18:40]

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

[commit-bot: I haz the power, 2015-07-16 14:18:41]

Try jobs failed on following builders:
  linux_chromium_chromeos_compile_dbg_ng on tryserver.chromium.linux
(JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

(exceeded global retry quota)

[caseq, 2015-07-16 14:21:37]

Patchset #3 (id:60001) has been deleted

[caseq, 2015-07-16 14:21:50]

The CQ bit was checked by caseq@chromium.org

[caseq, 2015-07-16 14:21:50]

The patchset sent to the CQ was uploaded after l-g-t-m from danakj@chromium.org,
dsinclair@chromium.org, skyostil@chromium.org
Link to the patchset: https://codereview.chromium.org/1237283006/#ps80001
(title: "fixed ChromeOS builds")

[commit-bot: I haz the power, 2015-07-16 14:22:36]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1237283006/80001

[commit-bot: I haz the power, 2015-07-16 14:48:05]

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

[commit-bot: I haz the power, 2015-07-16 14:48:06]

Try jobs failed on following builders:
  linux_chromium_chromeos_compile_dbg_ng on tryserver.chromium.linux
(JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

(exceeded global retry quota)

[caseq, 2015-07-16 15:22:27]

The CQ bit was checked by caseq@chromium.org

[caseq, 2015-07-16 15:22:28]

The patchset sent to the CQ was uploaded after l-g-t-m from danakj@chromium.org,
dsinclair@chromium.org, skyostil@chromium.org
Link to the patchset: https://codereview.chromium.org/1237283006/#ps100001
(title: "Fixed cros build (now for real)")

[commit-bot: I haz the power, 2015-07-16 15:23:44]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1237283006/100001

[commit-bot: I haz the power, 2015-07-16 15:46:05]

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

[commit-bot: I haz the power, 2015-07-16 15:46:07]

Try jobs failed on following builders:
  linux_chromium_chromeos_compile_dbg_ng on tryserver.chromium.linux
(JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

(exceeded global retry quota)

[caseq, 2015-07-16 16:14:15]

Patchset #4 (id:100001) has been deleted

[caseq, 2015-07-16 16:14:21]

The CQ bit was checked by caseq@chromium.org

[caseq, 2015-07-16 16:14:22]

The patchset sent to the CQ was uploaded after l-g-t-m from danakj@chromium.org,
dsinclair@chromium.org, skyostil@chromium.org
Link to the patchset: https://codereview.chromium.org/1237283006/#ps120001
(title: "Fixed cros build (now for real)")

[commit-bot: I haz the power, 2015-07-16 16:16:04]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1237283006/120001

[Chirantan Ekbote, 2015-07-16 18:08:17]

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

[Chirantan Ekbote, 2015-07-16 18:08:18]

components/timers/ lgtm

[commit-bot: I haz the power, 2015-07-16 19:13:30]

Committed patchset #4 (id:120001)

[commit-bot: I haz the power, 2015-07-16 19:14:36]

Patchset 4 (id:??) landed as
https://crrev.com/596ad0cca35be6b20afba297d3e8c26ae52e3ec2
Cr-Commit-Position: refs/heads/master@{#339091}