Trace MessageLoop::RunTask execution

Trace MessageLoop::RunTask execution

Previously, we were only issuing trace events around the task execution
within TaskAnnotator::RunTask. However, this does not include time spent
in observers (see bug for details on how it bites).

BUG=508005
Committed: https://crrev.com/87a2c639ff073ed3194a788ee1eaf82aabe77bab
Cr-Commit-Position: refs/heads/master@{#338492}

[caseq, 2015-07-09 15:23:06]

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

[danakj, 2015-07-09 17:45:47]

Last time we tried to put a trace in message loop it caused performance
problems, cuz it's just such hot code. Can you convince me this is ok?

[caseq, 2015-07-10 15:46:52]

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

[caseq, 2015-07-10 15:46:52]

+Nat for a question below.

On 2015/07/09 17:45:47, danakj wrote:
> Last time we tried to put a trace in message loop it caused performance
> problems, cuz it's just such hot code. Can you convince me this is ok?

We do have a trace in message loop already, just a bit down the stack so it does
not cover task observers. I've done some stats on a trace with almost all
categories enabled, and here are the top events by frequency:

101316 ParseHTML
61977 MessageLoop::PostTask
52821 V8.Execute
30928 RunTaskWithObservers <--- The one I'm adding
30928 MessageLoop::RunTask <--- The one we already have
15212 IPC
11411 View::Paint
10905 View::PaintChildren
10046 V8.CompileFullCode
8406 V8.ParseLazyMicroSeconds
7919 ChannelReader::DispatchInputData
7502 TaskQueueManager::PostTask
6923 KeyedServiceFactory::GetServiceForContext
6247 MessagePumpLibevent::OnLibeventNotification
5468 LayoutObject::invalidatePaintIfNeeded()
...
547859 total

So we're talking about ~5% of all the trace events. We can probably just move
the existing trace event outside of TaskAnnotator. Nat, I wonder if we're doing
any special processing on flow events that expects particular nesting order of
toplevel vs. flow events, e.g. would it be safe to emit the two events in
TaskAnnotator
(https://code.google.com/p/chromium/codesearch#chromium/src/base/debug/task_an...)
in reverse order?

[danakj, 2015-07-10 18:25:07]

I think I'm remembering wrong actually, I can't find the revert that I thought I
remembered... not sure what my brain is doing. LGTM. But if you can
consolidate/clean up that would be nice.

https://codereview.chromium.org/1225333002/diff/1/base/message_loop/message_l...
File base/message_loop/message_loop.cc (right):

https://codereview.chromium.org/1225333002/diff/1/base/message_loop/message_l...
base/message_loop/message_loop.cc:458: TRACE_EVENT0("toplevel",
"RunTaskWithObservers");
Can you put MessageLoop::RunTask in this name so it's more easy to locate?

[caseq, 2015-07-13 09:24:56]

On 2015/07/10 18:25:07, danakj wrote:
> I think I'm remembering wrong actually, I can't find the revert that I thought
I
> remembered... not sure what my brain is doing. LGTM. But if you can
> consolidate/clean up that would be nice.

Cool, thanks! I'm landing this with just the trace name changed per your
suggestion below,
as I think it may be useful to have pure task timings and I'm not sure what the
effect
of reversing the order & nesting of traces currently emitted from by
TaskAnnotator may be.
If this proves to be a perf regression, we can extract the trace from
TaskAnnotator::RunTask()
to the trace site.

>
https://codereview.chromium.org/1225333002/diff/1/base/message_loop/message_l...
> File base/message_loop/message_loop.cc (right):
> 
>
https://codereview.chromium.org/1225333002/diff/1/base/message_loop/message_l...
> base/message_loop/message_loop.cc:458: TRACE_EVENT0("toplevel",
> "RunTaskWithObservers");
> Can you put MessageLoop::RunTask in this name so it's more easy to locate?

done.

[caseq, 2015-07-13 09:25:01]

The CQ bit was checked by caseq@chromium.org

[caseq, 2015-07-13 09:25:01]

The patchset sent to the CQ was uploaded after l-g-t-m from danakj@chromium.org
Link to the patchset: https://codereview.chromium.org/1225333002/#ps20001
(title: "review comment addressed")

[commit-bot: I haz the power, 2015-07-13 09:25:15]

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

[commit-bot: I haz the power, 2015-07-13 10:45:04]

Committed patchset #2 (id:20001)

[commit-bot: I haz the power, 2015-07-13 10:46:12]

Patchset 2 (id:??) landed as
https://crrev.com/87a2c639ff073ed3194a788ee1eaf82aabe77bab
Cr-Commit-Position: refs/heads/master@{#338492}

[caseq, 2015-07-14 13:30:15]

A revert of this CL (patchset #2 id:20001) has been created in
https://codereview.chromium.org/1234573005/ by caseq@chromium.org.

The reason for reverting is: Regressed perf on Nexus 7
BUG=509982,508005.