Commit 41bf7a18 authored by brucedawson's avatar brucedawson Committed by Commit bot

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

Review URL: https://codereview.chromium.org/1140843003

Cr-Commit-Position: refs/heads/master@{#329989}
parent 80b04173
......@@ -132,7 +132,9 @@ void TraceEventETWExport::AddEvent(
!EventEnabledChromeEvent())
return;
std::string phase_string;
const char* phase_string = nullptr;
// Space to store the phase identifier and null-terminator, when needed.
char phase_buffer[2];
switch (phase) {
case TRACE_EVENT_PHASE_BEGIN:
phase_string = "Begin";
......@@ -195,14 +197,20 @@ void TraceEventETWExport::AddEvent(
phase_string = "Phase Delete Object";
break;
default:
phase_string.push_back(phase);
phase_buffer[0] = phase;
phase_buffer[1] = 0;
phase_string = phase_buffer;
break;
}
std::string arg_values_string[3];
for (int i = 0; i < num_args; i++) {
if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) {
convertable_values[i]->AppendAsTraceFormat(arg_values_string + i);
// Temporarily do nothing here. This function consumes 1/3 to 1/2 of
// *total* process CPU time when ETW tracing, and many of the strings
// created exceed WPA's 4094 byte limit and are shown as:
// "Unable to parse data". See crbug.com/488257
//convertable_values[i]->AppendAsTraceFormat(arg_values_string + i);
} else {
TraceEvent::TraceValue trace_event;
trace_event.as_uint = arg_values[i];
......@@ -212,7 +220,7 @@ void TraceEventETWExport::AddEvent(
}
EventWriteChromeEvent(
name, phase_string.c_str(), num_args > 0 ? arg_names[0] : "",
name, phase_string, num_args > 0 ? arg_names[0] : "",
arg_values_string[0].c_str(), num_args > 1 ? arg_names[1] : "",
arg_values_string[1].c_str(), num_args > 2 ? arg_names[2] : "",
arg_values_string[2].c_str());
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment