I further replayed CrOS 8838 on Samus. One with --use-live-site, one without (use WPR, web page replay, by default). Found that for --use-live-site case, the window_display_time value improve a lot (snapshot attached).

So it could be login flow issue. We shall have a bypass mechanism (fake login) to remove the dependency between WPR and CrOS login flow. Or at least we can provide specific login WPR for each CrOS version.

Any thought?

Deleted: Screen Shot 2016-10-20 at 1.47.11 PM.png 261 KB

	Screen Shot 2016-10-20 at 1.47.11 PM.png 261 KB View Download

Compare WPR recorded requests between Peppy 8809 (the one just before the regression) and 8968 (recent build). They are quite different. Later version with recorded WPR can alleviate the regression. But what causes the stall is still investigating.

Note that Peppy-8810 and 8811 are affected and cannot be alleviated by using --use-live-sites.

Deleted: peppy_8809.0.0_startup.cold.blank_page.record_wpr.log 3.9 KB

peppy_8809.0.0_startup.cold.blank_page.record_wpr.log 3.9 KB View Download

Deleted: peppy_8968.0.0_startup.cold.blank_page.record_wpr.log 1.7 KB

peppy_8968.0.0_startup.cold.blank_page.record_wpr.log 1.7 KB View Download

On Peppy:
CrOS 8809 + Chrome 55.0.2858.0 good
CrOS 8810 + Chrome 55.0.2862.3 bad 

CrOS CL: https://crosland.corp.google.com/log/8809.0.0..8810.0.0
Chrome CL: https://chromium.googlesource.com/chromium/src/+log/55.0.2858.0..55.0.2862.3?pretty=fuller&n=10000

I first guess the culprit is in Chrome. I tried 
CrOS 8809 image + deploy newer chrome (55.0.2862.3) good
CrOS 8810 image + deploy older chrome (55.0.2858.0) bad
So there's something wrong in CrOS or Catapult.

If it is in catapult, you can bisect it and rsync to /usr/local/telemetry on the DUT to triage.

Bisected https://chromium.googlesource.com/external/github.com/catapult-project/catapult.git/+log/9bd5b0cb2e6..7eb57a183493 and found the offending CL:
https://chromium.googlesource.com/external/github.com/catapult-project/catapult.git/+/b86cfef4b9da4749ff51e0fc4432869f8209dc42

Ned, can you help take a look? The affected benchmark is startup.cold.blank_page .

I am swarmed, and is not well-versed with CrOs to be effectively owning this.

 Issue 649255  has been merged into this issue.

Issue 670592 has been merged into this issue.

Compared to the version prior to the TsProxy change, Chrome spits lots of errors related to SSL handshake in the log:

libva info: VA-API version 0.39.2
libva info: va_getDriverName() returns 0
libva info: Trying to open /usr/lib64/va/drivers/i965_drv_video.so
libva info: Found init function __vaDriverInit_0_39
libva info: va_openDriver() returns 0
[21816:21816:0105/233146:ERROR:interface_registry.cc(99)] Failed to locate a binder for interface: mojom::ResourceUsageReporter
[21786:21786:0105/233146:ERROR:device_event_log_impl.cc(140)] [23:31:46.473] Network: network_handler_callbacks.cc:84 not-supported: /device/wlan0: org.chromium.flimflam.Error.NotSupported: This WiFi device does not support MAC address randomization
[21786:21807:0105/233147:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21807:0105/233147:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21786:0105/233148:ERROR:bluetooth_host_pairing_controller.cc(332)] net::ERR_CONNECTION_CLOSED
[21786:21786:0105/233148:ERROR:device_event_log_impl.cc(140)] [23:31:48.295] Login: homedir_methods.cc:402 HomedirMethods MountEx error: 1
[21786:21786:0105/233148:ERROR:device_event_log_impl.cc(140)] [23:31:48.295] Login: cryptohome_authenticator.cc:862 Cryptohome failure: state=1, code=32
[21786:21807:0105/233148:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21807:0105/233148:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21807:0105/233148:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21807:0105/233148:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21786:0105/233148:ERROR:gaia_screen_handler.cc(445)] Gaia webview error: ERR_CONNECTION_CLOSED
[21786:21807:0105/233148:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21807:0105/233148:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21786:0105/233148:ERROR:gaia_screen_handler.cc(445)] Gaia webview error: ERR_CONNECTION_CLOSED
[21786:21807:0105/233149:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[21786:21807:0105/233149:ERROR:ssl_client_socket_impl.cc(1146)] handshake failed; returned -1, SSL error code 1, net_error -100
[0105/233149:INFO:policy_key.cc(54)] No policy key on disk at /home/user/c0f21ae41f178dfbf87f7c6e7cbc98791492a47c/key.pub
[0105/233149:INFO:keygen_worker.cc(47)] Generating Owner key.
[0105/233150:INFO:keygen_worker.cc(54)] Writing Owner key to /home/user/c0f21ae41f178dfbf87f7c6e7cbc98791492a47c/key.pub

The SSL warnings were seen in R55-8810, but in ToT (ie R57) it is gone so I think it is the transient failure due to revert/reland of the initial TsProxy change.

In ToT R57 the 15 seconds seems related to authentication failure:

[0106/045903:INFO:keygen_worker.cc(48)] Generating Owner key.
[0106/045904:INFO:keygen_worker.cc(55)] Writing Owner key to /home/user/3cbeeb2c12e8d5325d1465d51c64bb31a6f22d29/key.pub
[7657:7657:0106/045908.287960:ERROR:gaia_screen_handler.cc(477)] Gaia webview error: ERR_SOCKS_CONNECTION_FAILED
[7657:7657:0106/045918.394057:ERROR:policy_oauth2_token_fetcher.cc(239)] Unrecoverable error or retry count max reached.

I will triage it.