New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 744555 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Jul 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug-Regression



Sign in to add a comment

8% regression in tracing_perftests at 483598:483687

Project Member Reported by primiano@chromium.org, Jul 17 2017

Issue description

seems to be linux-only
 
Project Member

Comment 1 by 42576172...@developer.gserviceaccount.com, Jul 17 2017

All graphs for this bug:
  https://chromeperf.appspot.com/group_report?bug_id=744555

(For debugging:) Original alerts at time of bug-filing:
  https://chromeperf.appspot.com/group_report?sid=583d8ac056277ccbd7de704f272918e1750b675f63d077497aea706508f2ba0a


Bot(s) for this bug's original alert(s):

linux-release
Project Member

Comment 4 by 42576172...@developer.gserviceaccount.com, Jul 17 2017


=== BISECT JOB RESULTS ===
NO Perf regression found, tests failed to produce values

Bisect Details
  Configuration: linux_perf_bisect
  Benchmark    : tracing_perftests
  Metric       : TraceEventPerfTest.Submit_10000_TRACE_EVENT0_in_traceable_tasks/flush


To Run This Test
  src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=flush tracing_perftests

More information on addressing performance regressions:
  http://g.co/ChromePerformanceRegressions

Debug information about this bisect:
  https://chromeperf.appspot.com/buildbucket_job_status/8973825649874190048


For feedback, file a bug with component Speed>Bisection
Project Member

Comment 5 by 42576172...@developer.gserviceaccount.com, Jul 17 2017


=== BISECT JOB RESULTS ===
NO Perf regression found, tests failed to produce values

Bisect Details
  Configuration: linux_perf_bisect
  Benchmark    : tracing_perftests
  Metric       : TraceEventPerfTest.Submit_10000_TRACE_EVENT0_in_traceable_tasks/flush


To Run This Test
  src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=flush tracing_perftests

More information on addressing performance regressions:
  http://g.co/ChromePerformanceRegressions

Debug information about this bisect:
  https://chromeperf.appspot.com/buildbucket_job_status/8973825896232875296


For feedback, file a bug with component Speed>Bisection
Cc: thomasanderson@chromium.org fmea...@chromium.org kraynov@chromium.org
Based on pure speculation while scrolling the commit log, I think this might be due to 
https://codereview.chromium.org/2963223003 (Reland of Switch Chrome on Linux to libc++)
as no other platform was affected.

Started a bisect on https://chromeperf.appspot.com/buildbucket_job_status/8973825649874190048 , but I think bisect doesn't non-TBM tracing_perftests.
+kraynov can you see if you can reproduce getting the build artifacts from the CL before and the same cl?
Nice find, Primiano.
I've got consistent numbers on my workstation.
@805944 (after CL) TraceEventPerfTest.Submit_10000_TRACE_EVENT0_in_traceable_tasks: flush= 53 ms
@7777a1 (right before the CL) TraceEventPerfTest.Submit_10000_TRACE_EVENT0_in_traceable_tasks: flush= 49 ms
Components: Speed>Tracing
Owner: thomasanderson@chromium.org
Status: Assigned (was: Untriaged)
Thanks, moving this to thomasanderson as the theory is confirmed
Cc: thakis@chromium.org
Status: Started (was: Assigned)
Thanks to cachegrind, I was able to find the source of the slowdown.  Looks like libc++'s std::string::push_back is about 3.4x slower than libstdc++'s.  Note that almost all tests seem to be 1-2% faster with libc++; this is just the one case that isn't :)

I'll see if there are any optimizations that can be done here.
out of curiosity, does that come from TraceEvent::AppendValueAsJSON ?
If that's the case I think the most rationale thing to do is rewrite that using a stringbuf and not leverage on string's operator +=.
WDYT? If that's the cause and the idea sgtm I can give a stab to that.
c#10 Indeed it is!  And that sgtm.  But it would also be nice to fix the underlying issue
If it's easy to write a standalone program using op+= that shows libc++'s version to be almost 3x slower than libstdc++'s, we could report that at bugs.llvm.org and upstream might be able to fix this for us.
primiano@ Actually, it is from AppendAsJSON, but indirectly (see the attached call graph).  I think base::EscapeJSONStringImpl is the real culprit that needs to change
Screenshot from 2017-07-18 18-19-46.png
73.6 KB View Download
Found a lazy stopgap with just .reserve().
Don't know why I suggested stringbuf yesterday, it was too late and coffeine level dropped down.

Adding a capacity() reservation should bring us back to the original value (at least it does on my Z620*). One interesting thing I realized is that this is not about just capacity expansion policies. If I add the reservation, libstdc++ is still faster (see data below). So looks like push_back is really slower, regardless of the capacity expansion.

libstdc++ without reserve(): 129ms
libcxx    without reserve(): 135ms

libstdc++ with reserve(): 123ms
libcxx    with reserve(): 129ms


(and when I say libstdc++ / libcxx I actually mean adding use_custom_libcxx=false to GN args.)

* Using this trick to stabilize numbers: https://groups.google.com/a/chromium.org/d/msg/memory-dev/uhtD-UIvjLA/RtAd1k6KBQAJ
Project Member

Comment 16 by bugdroid1@chromium.org, Jul 19 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/f0d3f8eb3974e36ebb8116c15df45fccacb580ff

commit f0d3f8eb3974e36ebb8116c15df45fccacb580ff
Author: Primiano Tucci <primiano@chromium.org>
Date: Wed Jul 19 11:58:49 2017

tracing: string.reserve() before serializing to JSON

After the switch to libc++, flush time of tracing regressed.
A cachegrind analysis suggests most time is spent in
std::string::push_back().
Pre-reserving the string capacity seems to alleviate the
regression and bring us back to the old values (although
libstdc++ would be still faster after this CL.

Running on a Z620
TraceEventPerfTest.Submit_10000_TRACE_EVENT0_in_traceable_tasks

libstdc++ before this CL: 129ms
libcxx    before this CL: 135ms

libstdc++ after this CL: 123ms
libcxx    after this CL: 129ms


BUG= 744555 

Change-Id: I9ebcbf432a983307e508327da0de8c4b82c41208
Reviewed-on: https://chromium-review.googlesource.com/576176
Reviewed-by: Hector Dearman <hjd@chromium.org>
Commit-Queue: Primiano Tucci <primiano@chromium.org>
Cr-Commit-Position: refs/heads/master@{#487827}
[modify] https://crrev.com/f0d3f8eb3974e36ebb8116c15df45fccacb580ff/base/trace_event/trace_log.cc

Status: Fixed (was: Started)
Marking this as fixed since this specific regression is fixed, and upstream is aware of the issue
Maybe EscapeJSONStringImpl itself should do a dest->reserve(str.length())?

Because a call from somewhere else ( DevToolsUIBindings::DispatchProtocolMessage -> content::RenderFrameHostImpl::ExecuteJavaScript ) is slowing down android debugging for me (when there are lots of tabs, confirmed by ETW trace)

Sign in to add a comment