Reduce overhead of Chrome's ETW tracing to make it more usable.

Reduce overhead of Chrome's ETW tracing to make it more usable.

When Chrome's ETW tracing is enabled it can consume more than half
of the total CPU time in the process, which means it is distorting
the results it is trying to measure. It also puts a lot of data into
the trace which cannot be viewed.

The biggest consumer of CPU time, by far, is AppendAsTraceFormat, which
consumes over 95% of the CPU time in TraceEventETWExport::AddEvent. Because
all categories are enabled this ends up creating many large buffers. The
cc::LayerTreeHostImpl events have been seen up to 22,500 bytes and
cc::Picture payloads have been seen up to 3,200,000 bytes! Ironically
the WPA trace viewer can't view payloads larger than 4094 bytes so all we
see for this effort and overhead is "Unable to parse data".

Truncating the payloads would let us see the partial data but would still
leave the distortion of execution time. The long-term solution is to
specify what categories are enabled in order to manage the volume of data.
Until then the prudent thing to do is to disable calls to AppendAsTraceFormat.

In addition, there is no reason for phase_string to be a std::string. This
overhead is relatively minor but measurable. It's worth fixing because the
fix is clean and simple.

The net effect is to drop the CPU overhead from 33-50% down to 1-7%.

This change makes Chrome's ETW tracing much more usable.

R=primiano@chromium.org
BUG=488257
Committed: https://crrev.com/41bf7a187137f3e13271de8062fb84382c54bff6
Cr-Commit-Position: refs/heads/master@{#329989}

[brucedawson, 2015-05-14 20:12:20]

brucedawson@chromium.org changed reviewers:
+ primiano@chromium.org
- nduca@chromium.org

[brucedawson, 2015-05-14 20:13:14]

Primiano, can you take a look? The other owners appear to be out right now.

It's a simple change that will have no effect outside of ETW tracing and it
makes ETW tracing *much* more usable.

[Primiano Tucci (use gerrit), 2015-05-14 22:12:53]

LGTM, seems reasonable to me.
Just one request about keeping track of this in crbug (see note inline below).

So, if I understand correctly here, you are skipping the dumping of the
convertable objects (CC layers, netlog,...) that ETW wouldn't be able to parse
anyways (I guess it has no idea how to parse the CC json things, right?)

https://codereview.chromium.org/1140843003/diff/1/base/trace_event/trace_even...
File base/trace_event/trace_event_etw_export_win.cc (right):

https://codereview.chromium.org/1140843003/diff/1/base/trace_event/trace_even...
base/trace_event/trace_event_etw_export_win.cc:212: // "Unable to parse data".
Can you copy and paste the (excellent) commit message into a crbug and add a
reference  to crbug.com/XXXXX here (and in BUG= in the commit message)? (git
blame history tends to get hard to follow if the file gets moved)

[brucedawson, 2015-05-14 22:41:41]

Bug opened and linked.

WPA can display *some* of the results of AppendAsTraceFormat -- all those that
are under WPA's 4094 byte limit. However the value from these is not enough to
justify the enormous cost.

There is theoretically a risk from AppendValueAsJSON as well. However in
practice it seems to be called less frequently and I have never seen it produce
enormous strings. In particular, its strings always seem to fit under WPA's 4094
byte limit, so they are always viewable in WPA. WPA doesn't understand them, but
they still add some human-readable value.

Earlier ETW trace viewers would *truncate* too long strings. This "Unable to
parse data" reaction in WPA is arguably a bug, and I reported it a few years
ago, but no luck getting it fixed. But, strings that long are cumbersome in WPA
anyway, so just disallowing them is fine.

And, a better fix will be created later.

[brucedawson, 2015-05-14 22:47:43]

The CQ bit was checked by brucedawson@chromium.org

[brucedawson, 2015-05-14 22:47:43]

The patchset sent to the CQ was uploaded after l-g-t-m from
primiano@chromium.org
Link to the patchset: https://codereview.chromium.org/1140843003/#ps20001
(title: "Add reference to tracking bug.")

[commit-bot: I haz the power, 2015-05-14 22:50:01]

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

[brucedawson, 2015-05-14 22:50:06]

Comment in the code added.

https://codereview.chromium.org/1140843003/diff/1/base/trace_event/trace_even...
File base/trace_event/trace_event_etw_export_win.cc (right):

https://codereview.chromium.org/1140843003/diff/1/base/trace_event/trace_even...
base/trace_event/trace_event_etw_export_win.cc:212: // "Unable to parse data".
On 2015/05/14 22:12:52, Primiano Tucci wrote:
> Can you copy and paste the (excellent) commit message into a crbug and add a
> reference  to crbug.com/XXXXX here (and in BUG= in the commit message)? (git
> blame history tends to get hard to follow if the file gets moved)

Done.

[commit-bot: I haz the power, 2015-05-15 00:20:56]

Committed patchset #2 (id:20001)

[commit-bot: I haz the power, 2015-05-15 00:22:49]

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