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

Original alerts at time of bug-filing:
  https://chromeperf.appspot.com/group_report?keys=agxzfmNocm9tZXBlcmZyFAsSB0Fub21hbHkYgIDA3-XZoQoM


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

chromium-rel-mac-retina

=== Auto-CCing suspected CL author rockot@chromium.org ===

Hi rockot@chromium.org, the bisect results pointed to your CL below as possibly
causing a regression. Please have a look at this info and see whether
your CL be related.


===== BISECT JOB RESULTS =====
Status: completed


===== SUSPECTED CL(s) =====
Subject : Reland: Bootstrap Mojo IPC independent of Chrome IPC
Author  : rockot
Commit description:
  
The original CL:
https://crrev.com/eb199fbaecd8e5d294010dfbe8897b7d83aeab07

broke NaCL integration tests on some bots. After some
extensive investigation this is somehow tied to an
obscure dependency on the value of kIPCDescriptorMax.
Moving kMojoIPCChannel to content_descriptors.h allows
us to avoid changing that value and thus avoid the
mysterious breakage. :|

Original CL description follows:

This initializes Mojo IPC very early in child process
startup so we can start using cross-process pipes in
content without a dependency on Chrome IPC.

On all supported platforms, a new OS pipe handle is
passed through ChildProcessLauncher and hooked up to
the EDK on ChildThreadImpl startup to establish a
Mojo IPC channel to the parent.

A command-line argument is also to used to share a
unique pipe token with the child, and this token is
exchanged over the Mojo IPC channel to bootstrap a
primordial message pipe.

While this CL establishes these facilities in a way
that can be used for all child processes, only
render processes are brought up in this way for now.

BUG= 583557 
TEST=Chrome still runs in mash with Mus-in-renderer support.
TBR=ben@chromium.org,jschuh@chromium.org

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

Cr-Commit-Position: refs/heads/master@{#378704}
Commit  : e8b8da4b8f513b7ab03bb2e2eb9156bc828267a5
Date    : Wed Mar 02 06:21:38 2016


===== TESTED REVISIONS =====
Revision                Mean Value  Std. Dev.   Num Values  Good?
chromium@378698         506.884211  3.633562    5           good
chromium@378702         527.094737  5.923146    5           good
chromium@378703         508.326316  1.142481    5           good
chromium@378704         565.4       3.612958    5           bad
chromium@378705         569.873684  9.197555    5           bad

Bisect job ran on: mac_retina_perf_bisect
Bug ID: 591742

Test Command: src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --also-run-disabled-tests startup.warm.blank_page
Test Metric: first_non_empty_paint_time/first_non_empty_paint_time
Relative Change: 12.43%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1195
Job details: https://chromeperf.appspot.com/buildbucket_job_status/9019187104231990640


| O O | Visit http://www.chromium.org/developers/speed-infra/perf-bug-faq
|  X  | for more information addressing perf regression bugs. For feedback,
| / \ | file a bug with label Cr-Tests-AutoBisect.  Thank you!

Probably a legitimate regression due to the fact that we block renderer startup on shell connection initialization.

If we really have to, we could start the connection with a cheap buffering proxy and initialize the real connection asynchronously in the background.

I'm going to wait to see how lower bindings latency impacts this regression though. I suspect we'll see this drop back down a good bit once https://codereview.chromium.org/1759783003 lands.

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

commit fcf7354b33a5df1f26cee7c2da9b7c4864897679
Author: rockot <rockot@chromium.org>
Date: Tue Mar 08 00:55:13 2016

Add histogram to track Mojo shell / renderer connection init

Renderer startup blocks on initializing its shell connection, so this
needs to be fast. Here's some data to monitor.

BUG= 591742 

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

Cr-Commit-Position: refs/heads/master@{#379691}

[modify] https://crrev.com/fcf7354b33a5df1f26cee7c2da9b7c4864897679/content/renderer/renderer_main.cc
[modify] https://crrev.com/fcf7354b33a5df1f26cee7c2da9b7c4864897679/tools/metrics/histograms/histograms.xml

To my surprise, shell connection setup isn't the problem. 99.78% of the time it takes < 1 ms. Worst case (0.07%) it takes 5 ms. This is IMHO a totally acceptable situation so I'm not going to change it.

The perf hit is clearly attached to this CL - it even spiked and recovered when the patch first landed and was subsequently reverted - but the rest of the changes are pretty straightforward and don't do anything expensive that could block first load. Also, digging through the graphs, Mac is the only affected platform.

My current guesses are that either duping file descriptors to a child is unreasonably expensive on Mac, in which case we have to eat this cost until we can drop the primary IPC fd (this would be surprising but +cc erikchen@ for input); or there's some other code somewhere which only runs when MojoShellConnection is available, and that's slowing down Mac. Investigating the latter possibility for now.

Were you able to reproduce the regression locally when running the benchmark?

There are two possibilities here:
1. The magnitude of the regression is exaggerated by Telemetry, if there is a regression at all.
2. Your CL non-trivially harms startup performance.

+ sullivan, since this may be one of the rare instances where a startup test is catching a regression, or it may end up being more noise, and yet another reason to get rid of startup tests.

Thanks for cc-ing me, this is an interesting case for our startup benchmarks. We see this regression across our entire suite of Mac perfbots, EXCEPT for the very slow HDD bot. In this graph, you can see a clear regression from ~2800ms to ~3100ms on the mac10 bot, but it's completely drowned out in the noise of the 20000ms startup of the HDD bot: https://chromeperf.appspot.com/report?sid=ac48f9df815078fa288203b0cf1d4ade9fa9d02973e936c21fc03c4a6973f583&rev=378709

In the charts linked from #1, we see a 50-200ms regression across the board on the faster bots. Because they're so fast, it's likely that they're not real-world representative and thus exaggerating the regression. But at the same time, I believe they're catching a real regression that more representative bots wouldn't see.

However, it's also likely that this is going to be a ~200ms regression in the real world, and not a ~10% regression across the board. So the graphs are likely misleading in that respect.

Erik, how do you think we should handle cases like this?

I've run the startup.warm.blank_page benchmarks locally on OS X 10 many times with and without the CL in question, and I've been unable to reproduce these regressions. The results aren't even particularly noisy. They're consistent across runs and the CL doesn't seem to make a difference.

I've got some old/slow Macs sitting around my deck. I'd suggest trying to get a local repro on one of those. If the regression is reproducible, rockot@ can dig into the root cause.

If the regression is not reproducible, then there is something fundamentally broken about startup tests and/or telemetry infrastructure. Some type of configuration difference between the fleet, which clearly sees a regression, and real machines, which don't? The Infra-Speed team should probably investigate that.

Re #8: what type of Mac are you running on locally? What times do you see the startup tests getting?

This is a mid 2012 Mac Pro. Some numbers with and without the patch look roughly like:

first_main_frame_load_time: 590-610 ms avg, ~5 ms std dev
first_non_empty_paint_time: 610-690 ms avg, ~90 ms std dev
foreground_tab_load_complete: 740-760 ms avg, ~24 ms std dev

Ned, this is pretty interesting, see comments 7 and 11--the regression reproduces on the bots but not a Mac Pro with similar performance characteristics. It seems related to bug 571877 -- do you think you could take a look at the same time you look at that one? (We should probably make a separate bug for investigating when this does/doesn't repro)

My previous tests were done from ToT with the CL reverted or not reverted. If I actually roll back my checkout to the CL and flip it on and off, I do see a difference and it's more pronounced on the slower MBP I borrowed from Erik.

Hmhh, to comment #13, does that mean the regression is recovered at TOT?

gabadie@ can we remove these non trace-based startup benchmark & replace them with TimelineBasedMeasurement ones yet?

While I would expect that to indicate the regression is recovered at ToT, that does not appear to be the case when looking at the dashboard.

Either:
1) There's a CL between his CL and ToT that mitigates the negative performance of rockot's CL.
2) There's a CL between his CL and ToT that has the same, negative effect. Thus, adding rockot's CL to ToT has no /further/ negative effect.

I'm having trouble parsing comment #15, but I think we're observing (2)?

Fortunately my personal Macbook repros this nicely. TL;DR: It's a real regression, I know what's causing it, and I'm working on a fix.


As it turns out I did a very dumb thing and instrumented the wrong call: in child processes we want to measure MojoShellConnectionImpl::BindToMessagePipe(), not MojoShellConnection::Create().

On my test device first_main_frame_load_time is regressed by about 9-10%, and omitting BindToMessagePipe completely eliminates the regression. This call spawns a new background thread and then blocks the main thread until the background thread signals some event. This happens very quickly, and it's a bit surprising (to me, anyway) that it would have this much impact on OS X without also affecting other platforms.

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

commit c7b3190c0ecd5b88688aa5e55d3085f0fbd40e11
Author: rockot <rockot@chromium.org>
Date: Fri Mar 11 06:17:34 2016

Instrument MojoShellConnectionImpl::BindToMessagePipe

This adds a histogram to measure the duration of calls to
MojoShellConnectionImpl::BindToMessagePipe in child processes.

The new histogram replaces a useless one which was recently added
to measure uninteresting calls to MojoShellConnection::Create()
in renderers.

BindToMessagePipe cost should be significantly reduced in a
follow-up CL, but it will still need to do some non-trivial
amount of work. This metric will help us detect if it remains
problematic or regresses.

BUG= 591742 
R=ben@chromium.org

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

Cr-Commit-Position: refs/heads/master@{#380555}

[modify] https://crrev.com/c7b3190c0ecd5b88688aa5e55d3085f0fbd40e11/content/child/child_thread_impl.cc
[modify] https://crrev.com/c7b3190c0ecd5b88688aa5e55d3085f0fbd40e11/content/renderer/renderer_main.cc
[modify] https://crrev.com/c7b3190c0ecd5b88688aa5e55d3085f0fbd40e11/tools/metrics/histograms/histograms.xml

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

commit 35f7270e84da5abb0f7895304a53d632efbbfe71
Author: rockot <rockot@chromium.org>
Date: Sun Mar 13 23:42:41 2016

Remove ShellConnection::WaitForInitialize

This changes ShellClient::Initialize to expect a
response with an optional Connector request rather
than a ConnectorPtr being passed in with the call.
This allows clients to create their own Connector
pipe and lazily connect it to the shell thus
avoiding any practical need to wait for an
Initialize message.

Additionally:

 - Client instances no longer die on the first
   Connector pipe error: instead an Instance is
   kept alive by the shell as long as either the
   ShellClient pipe is connected OR any Connector
   pipes are connected.

 - ShellClientFactory endpoints are now strongly
   typed instead of being raw message pipe
   handles.

 - Some uses of MessagePumpMojo near other changes
   in this CL have been opportunistically removed.

BUG= 591742 

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

Cr-Commit-Position: refs/heads/master@{#380909}

[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/chrome/app/mash/mash_runner.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/components/mus/ws/window_tree_client_unittest.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/browser/BUILD.gn
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/browser/browser_main_loop.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/browser/renderer_host/render_process_host_impl.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/child/BUILD.gn
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/child/child_thread_impl.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/common/mojo/mojo_shell_connection_impl.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/common/mojo/mojo_shell_connection_impl.h
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/content_browser.gypi
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/content_child.gypi
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/public/common/content_switches.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/content/public/common/content_switches.h
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mash/example/window_type_launcher/main.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/edk/embedder/embedder.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/edk/embedder/embedder.h
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/background/tests/background_shell_unittest.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/public/cpp/lib/application_test_base.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/public/cpp/lib/shell_connection.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/public/cpp/lib/shell_test.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/public/cpp/shell_connection.h
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/public/interfaces/shell_client.mojom
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/runner/child/BUILD.gn
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/runner/child/runner_connection.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/runner/child/runner_connection.h
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/runner/child/test_native_main.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/shell.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/mojo/shell/tests/shell/shell_unittest.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/ui/views/mus/platform_test_helper_mus.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/ui/views/mus/screen_mus.cc
[modify] https://crrev.com/35f7270e84da5abb0f7895304a53d632efbbfe71/ui/views/mus/screen_mus.h

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

commit b1e74df4227184deaaee4d192a5fb3c48116f081
Author: rockot <rockot@chromium.org>
Date: Mon Mar 14 13:18:30 2016

[mojo] Implement pipe fusion API

Sometimes it's desirable to fuse two pipes together. This is
particularly useful when a service provides some kind of interface
pipe later than its consumers would like to have such a pipe
available. Rather than require the service to be rewritten to
accommodate such cases, a consumer could create its own
disconnected pipe and fuse it lazily with a service endpoint.

BUG= 591742 

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

Cr-Commit-Position: refs/heads/master@{#380964}

[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/embedder/entrypoints.cc
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/core.cc
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/core.h
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/message_pipe_dispatcher.cc
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/message_pipe_dispatcher.h
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/message_pipe_unittest.cc
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/node_controller.cc
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/node_controller.h
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/ports/node.cc
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/edk/system/ports/node.h
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/public/c/system/message_pipe.h
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/public/cpp/bindings/interface_request.h
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/public/cpp/bindings/tests/interface_ptr_unittest.cc
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/public/cpp/system/message_pipe.h
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/public/interfaces/bindings/tests/sample_interfaces.mojom
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/public/platform/native/system_thunks.cc
[modify] https://crrev.com/b1e74df4227184deaaee4d192a5fb3c48116f081/mojo/public/platform/native/system_thunks.h

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

commit 018a4e46c477ada7307ed5c7dad7eb58b7da75b5
Author: rockot <rockot@chromium.org>
Date: Fri Mar 18 07:34:30 2016

[mojo-edk] Stop using the sync broker on OS X

The sync broker is only needed for sandboxed shared
buffer allocation on POSIX, but it's not needed for
Mach shared buffers.

This stops using the broker on OS X.

BUG= 591742 , 590979 

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

Cr-Commit-Position: refs/heads/master@{#381908}

[modify] https://crrev.com/018a4e46c477ada7307ed5c7dad7eb58b7da75b5/mojo/edk/system/node_controller.cc
[modify] https://crrev.com/018a4e46c477ada7307ed5c7dad7eb58b7da75b5/mojo/edk/system/node_controller.h

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

commit c326671407f8790fbb7ee14ca59ac37aa25afa87
Author: rockot <rockot@chromium.org>
Date: Fri Mar 18 13:50:35 2016

Instrument EDK sync Broker initialization

Bringing up Mojo at process startup caused a regression
on OS X renderer startup times. At least half of the
regression seems to be attributable to blocking on
getting the parent pipe handle from the sync broker
channel.

We can eliminate this behavior on OS X now that we're
using Mach shm, but let's also make sure it's not causing
problems elsewhere in the wild.

BUG= 591742 

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

Cr-Commit-Position: refs/heads/master@{#381953}

[modify] https://crrev.com/c326671407f8790fbb7ee14ca59ac37aa25afa87/mojo/edk/system/node_controller.cc
[modify] https://crrev.com/c326671407f8790fbb7ee14ca59ac37aa25afa87/tools/metrics/histograms/histograms.xml

I believe all of my regressions have recovered; some were fixed by r380909 and the rest by r381908.

I can confirm that first_non_empty_paint graph is recovered:
https://chromeperf.appspot.com/group_report?keys=agxzfmNocm9tZXBlcmZyFAsSB0Fub21hbHkYgIDA3-XZoQoM