Telemetry: Use mimimum tracing for timeline benchmarks.

Telemetry: Use mimimum tracing for timeline benchmarks.

PERF SHERIFF WARNING: This will drastically change the 
thread-time benchmarks for the better. This is purely a
measurement change though, by removing overhead from traces.

Tracing adds significant overhead. We can add more details
by default as we prune the list of traces.

When details are reported, default traces are enabled again,
as otherwise there is no details to report.

BUG=331903
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=252485

[epenner, 2014-02-19 04:53:24]

Ptal.

Rather than rename 'toplevel', which is still usefull, I added a special trace
called 'Poll' for absolute minimal tracing.

[ernstm, 2014-02-19 22:18:16]

https://codereview.chromium.org/171013006/diff/30001/tools/perf/metrics/timel...
File tools/perf/metrics/timeline.py (right):

https://codereview.chromium.org/171013006/diff/30001/tools/perf/metrics/timel...
tools/perf/metrics/timeline.py:20: # "disabled-by-default-topall,"
In the comment: disabled-by-default-topall -> disabled-by-default-poll_cpu
Maybe we could just put this event into the 'benchmark' category?

[epennerAtGoogle, 2014-02-19 22:33:24]

>
https://codereview.chromium.org/171013006/diff/30001/tools/perf/metrics/timel...
> tools/perf/metrics/timeline.py:20: # "disabled-by-default-topall,"
> In the comment: disabled-by-default-topall -> disabled-by-default-poll_cpu
> Maybe we could just put this event into the 'benchmark' category?

Hmm, it's disabled-by-default, so would that work in the same category? It's
also pretty heavy-weight as it traces every task. Perhaps benchmark.poll_cpu?

[ernstm, 2014-02-19 22:37:51]

> Hmm, it's disabled-by-default, so would that work in the same category? It's
> also pretty heavy-weight as it traces every task. Perhaps benchmark.poll_cpu?

In that case, disabled-by-default is probably safer.
disabled-by-default-benchmark.poll_cpu is clunky, so maybe we just keep the
disabled-by-default-poll_gpu that you used originally.

[ernstm, 2014-02-19 22:42:09]

> In that case, disabled-by-default is probably safer.
> disabled-by-default-benchmark.poll_cpu is clunky, so maybe we just keep the
> disabled-by-default-poll_gpu that you used originally.

I'll take that back. It would be nice to have all benchmark relevant events in
'benchmark*' categories. That makes it easier to find them and might be a
warning flag for people to not change the names of these events.
disabled-by-default-benchmark.poll_cpu?

[epennerAtGoogle, 2014-02-19 22:47:43]

On 2014/02/19 22:42:09, ernstm wrote:
> > In that case, disabled-by-default is probably safer.
> > disabled-by-default-benchmark.poll_cpu is clunky, so maybe we just keep the
> > disabled-by-default-poll_gpu that you used originally.
> 
> I'll take that back. It would be nice to have all benchmark relevant events in
> 'benchmark*' categories. That makes it easier to find them and might be a
> warning flag for people to not change the names of these events.
> disabled-by-default-benchmark.poll_cpu?

Yeah I'm liking that too. Very limited set of events that shouldn't be changed.
Okay made that change. The name is clunky but mostly just due to the
disabled-by-default part.

[epenner, 2014-02-19 23:37:59]

Ptal.

New patch up with "disabled-by-default-benchmark.poll_cpu".
Minor changes to make sure details are shown in silk. Tests pass.

[ernstm, 2014-02-19 23:42:41]

LGTM

[epennerAtGoogle, 2014-02-19 23:46:28]

On 2014/02/19 23:42:41, ernstm wrote:
> LGTM

+darin/willchan for OWNERS:
base/message_loop/message_loop.cc

[willchan no longer on Chromium, 2014-02-19 23:58:45]

I know jar@ took himself out of OWNERS, but I'd like to punt this to him while
I'm out on vacation (I'm at the airport right now).

I'm concerned about performance impact of tracing so low level in MessageLoop.
If you do land this, please watch the perfbots. Nat, you know more about the
perf impact of this trace call, so I'd like to hear your input. If you and Jim
are cool with this, then epenner, feel free to TBR the change to me and land it.

[epenner, 2014-02-20 00:20:10]

On 2014/02/19 23:58:45, willchan wrote:
> I know jar@ took himself out of OWNERS, but I'd like to punt this to him while
> I'm out on vacation (I'm at the airport right now).
> 
> I'm concerned about performance impact of tracing so low level in MessageLoop.
> If you do land this, please watch the perfbots. Nat, you know more about the
> perf impact of this trace call, so I'd like to hear your input. If you and Jim
> are cool with this, then epenner, feel free to TBR the change to me and land
it.

Thanks. This trace actually uncovers a lot of CPU-time which was previously
unaccounted for, and was missing from our benchmarks. I'm guessing this is time
spent in the message-loop itself and is difficult to capture in any other way.
My guess is that this trace will more than pay for itself in terms of
optimizations resulting from it's existence ;)

However, I'll do a quick profile of the disabled traces in here see how much
they cost.

[willchan no longer on Chromium, 2014-02-20 00:26:44]

Oh I'm sure it's useful. I just want to make sure you don't regress
performance in your attempts to uncover perf issues :) So I'm
deferring to experts here. If you have data that validates performance
isn't regressing, then even better.

On Wed, Feb 19, 2014 at 4:20 PM,  <epenner@chromium.org> wrote:
> On 2014/02/19 23:58:45, willchan wrote:
>>
>> I know jar@ took himself out of OWNERS, but I'd like to punt this to him
>> while
>> I'm out on vacation (I'm at the airport right now).
>
>
>> I'm concerned about performance impact of tracing so low level in
>> MessageLoop.
>> If you do land this, please watch the perfbots. Nat, you know more about
>> the
>> perf impact of this trace call, so I'd like to hear your input. If you and
>> Jim
>> are cool with this, then epenner, feel free to TBR the change to me and
>> land
>
> it.
>
> Thanks. This trace actually uncovers a lot of CPU-time which was previously
> unaccounted for, and was missing from our benchmarks. I'm guessing this is
> time
> spent in the message-loop itself and is difficult to capture in any other
> way.
> My guess is that this trace will more than pay for itself in terms of
> optimizations resulting from it's existence ;)
>
> However, I'll do a quick profile of the disabled traces in here see how much
> they cost.
>
> https://codereview.chromium.org/171013006/

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[epenner, 2014-02-20 00:59:32]

On 2014/02/20 00:20:10, epenner wrote:
> On 2014/02/19 23:58:45, willchan wrote:
> > I know jar@ took himself out of OWNERS, but I'd like to punt this to him
while
> > I'm out on vacation (I'm at the airport right now).
> > 
> > I'm concerned about performance impact of tracing so low level in
MessageLoop.
> > If you do land this, please watch the perfbots. Nat, you know more about the
> > perf impact of this trace call, so I'd like to hear your input. If you and
Jim
> > are cool with this, then epenner, feel free to TBR the change to me and land
> it.
> 
> Thanks. This trace actually uncovers a lot of CPU-time which was previously
> unaccounted for, and was missing from our benchmarks. I'm guessing this is
time
> spent in the message-loop itself and is difficult to capture in any other way.
> My guess is that this trace will more than pay for itself in terms of
> optimizations resulting from it's existence ;)
> 
> However, I'll do a quick profile of the disabled traces in here see how much
> they cost.

Okay I profiled the two traces. They couldn't be resolved from noise (~1-2
micros) so I increased to 100X the calls. That shows up on Nexus 4 at ~10
micros. So each one takes approximately 0.05 micros or 50 nanos (100 nanos for
the pair).

From what I'm seeing there is something like 30-50 microseconds of cpu-time
spent outside of RunTask/DispatchMessage for every task. That is what we would
like to find and optimize (the cost of about 500 disabled traces).

[nduca, 2014-02-20 05:35:04]

https://codereview.chromium.org/171013006/diff/350001/tools/perf/metrics/time...
File tools/perf/metrics/timeline.py (right):

https://codereview.chromium.org/171013006/diff/350001/tools/perf/metrics/time...
tools/perf/metrics/timeline.py:13: 
eric how about pulling out the poll_cpu patch from the rest of this? the rest of
stuff here is a net improvement, even without the base edits... and though I
want the base edits, I think we will feel better having the rest landed faster.

[epenner, 2014-02-20 18:55:32]

On 2014/02/20 05:35:04, nduca wrote:
>
https://codereview.chromium.org/171013006/diff/350001/tools/perf/metrics/time...
> File tools/perf/metrics/timeline.py (right):
> 
>
https://codereview.chromium.org/171013006/diff/350001/tools/perf/metrics/time...
> tools/perf/metrics/timeline.py:13: 
> eric how about pulling out the poll_cpu patch from the rest of this? the rest
of
> stuff here is a net improvement, even without the base edits... and though I
> want the base edits, I think we will feel better having the rest landed
faster.

Good call.

Okay I'll change the 'minimal' set to only include 'toplevel' first. I preferred
to land together to minimize the perf-graphs jumping around, but that's not a
biggy.

[epenner, 2014-02-20 20:54:39]

Okay I've removed the base changes. Landing with ernstm's LGTM, but feel free to
unCQ if there is issues.

[epenner, 2014-02-20 20:54:47]

The CQ bit was checked by epenner@chromium.org

[commit-bot: I haz the power, 2014-02-20 20:55:16]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/epenner@chromium.org/171013006/530001

[commit-bot: I haz the power, 2014-02-20 21:20:25]

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

[commit-bot: I haz the power, 2014-02-20 21:20:26]

Retried try job too often on chromium_presubmit for step(s) presubmit
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...

Try jobs failed on following builders: linux_chromium_rel

[epenner, 2014-02-20 23:20:14]

On 2014/02/20 21:20:26, I haz the power (commit-bot) wrote:
> Retried try job too often on chromium_presubmit for step(s) presubmit
>
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=chromium_p...
> 
> Try jobs failed on following builders: linux_chromium_rel

Grrr.. Anyone see this pylint error before? 
E0202:298,2:ThreadTimesTimelineMetric.results_to_report: An attribute affected
in measurements.thread_times line 29 hide this method

It appears to be a pylint bug:
http://www.logilab.org/ticket/89092

Not sure how I should work around it. Also not sure why other @property setters
aren't causing this.

[epenner, 2014-02-21 00:08:57]

> Grrr.. Anyone see this pylint error before? 
> E0202:298,2:ThreadTimesTimelineMetric.results_to_report: An attribute affected
> in measurements.thread_times line 29 hide this method
> 
> It appears to be a pylint bug:
> http://www.logilab.org/ticket/89092
> 
> Not sure how I should work around it. Also not sure why other @property
setters
> aren't causing this.

Nvm. I realized I can do without the property.

[epenner, 2014-02-21 00:09:04]

The CQ bit was checked by epenner@chromium.org

[epenner, 2014-02-21 00:10:34]

The CQ bit was unchecked by epenner@chromium.org

[epenner, 2014-02-21 00:10:47]

The CQ bit was checked by epenner@chromium.org

[commit-bot: I haz the power, 2014-02-21 00:14:28]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/epenner@chromium.org/171013006/630001

[commit-bot: I haz the power, 2014-02-21 03:38:13]

Change committed as 252485