Do we have chrome logs with the trace file?

From the trace, there are a few big tasks (4) blocking UI thread for 10+ seconds:

[{src_file: "../../../../../../../home/chrome-bot/chrome_root/src/dbus/object_proxy.cc",
  src_func: "OnPendingCallIsComplete"}]
MessageLoop::RunTask 4,789.849 ms	

[{src_file: "../../../../../../../home/chrome-bot/chrome_root/src/dbus/object_proxy.cc",
  src_func: "OnPendingCallIsComplete"}]
MessageLoop::RunTask 2,572.784 ms	

[{src_file: "../../../../../../../home/chrome-bot/chrome_root/src/dbus/object_proxy.cc",
  src_func: "OnPendingCallIsComplete"}]
MessageLoop::RunTask 2,875.297 ms	

[{src_file: "../../../../../../../home/chrome-bot/chrome_root/src/dbus/object_proxy.cc",
  src_func: "OnPendingCallIsComplete"}]
MessageLoop::RunTask 2,895.171 ms	

They are all tagged as originated from ObjectProxy::OnPendingCallIsComplete. Not sure which dbus code is causing that though.

re #2: why would these block UI thread?

btw, i am running 68.0.3440.25

Think the current DBus code works like this:
1. Calling a dbus method via ObjectProxy on a thread;
2. The actual dbus call happens on DBus thread and response received there;
3. The dbus response is processed and posted as a task on the original thread in step 1.

We often call dbus on UI thread and hence processing the response on the UI thread. e.g. we call CryptohomeClient::GetSystemSalt on the UI thread and provide a callback to handle the response. The callback will then be invoked on UI thread with the response.

Unfortunately, trace file does not tells more about the callback to find out who that is. :(

Zel filed feedback at https://listnr.corp.google.com/product/208/report/85510052321?dateRange=All

It is likely to be related to ble. Tethering, or (arc) network might also play part in it. I wonder whether turning of magic tether would help.

Looking at the chrome user log in the feedback, searching for "Long response time on the UI thread". There are 4 of them and two of them warns with 10+ seconds. All of them are surrounded with ble log lines.

The first one "Long response time on the UI thread: 11.782 s":
[11165:11165:0620/094516.090405:INFO:bluetooth_low_energy_weave_client_connection.cc(234)] Creating GATT connection with {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094516.290729:INFO:ble_scanner_impl.cc(261)] Stopped discovery session successfully.
[11165:11165:0620/094516.691847:INFO:bluetooth_low_energy_weave_client_connection.cc(527)] Finding GATT characteristics for {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094517.107325:INFO:bluetooth_low_energy_weave_client_connection.cc(613)] Starting notification session for {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094517.163292:INFO:bluetooth_low_energy_weave_client_connection.cc(650)] Sending "connection request" uWeave packet to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}
[11165:11165:0620/094517.163357:INFO:bluetooth_low_energy_weave_client_connection.cc(668)] Writing 7 bytes to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094517.185154:INFO:bluetooth_low_energy_weave_client_connection.cc(484)] Received uWeave "connection response" packet; connection is now fully initialized for {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}. Max packet size: 514
[11165:11165:0620/094517.185205:INFO:ble_connection_manager.cc(605)] Status change - Device ID: "CAESR...KTw==": [connecting] => [connected], State change detail: [none]
[11165:11165:0620/094517.185310:INFO:ble_connection_manager.cc(605)] Status change - Device ID: "CAESR...KTw==": [connected] => [authenticating], State change detail: [none]
[11165:11165:0620/094517.186698:INFO:device_to_device_authenticator.cc(137)] Sending [Initiator Hello] message.
[11165:11165:0620/094517.186752:INFO:bluetooth_low_energy_weave_client_connection.cc(668)] Writing 203 bytes to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094517.391009:VERBOSE1:arc_net_host_impl.cc(759)] New default network: /service/94 (wifi)
[11165:11165:0620/094517.472093:VERBOSE1:arc_net_host_impl.cc(759)] New default network: /service/94 (wifi)
[11165:11165:0620/094524.793901:WARNING:device_to_device_authenticator.cc(199)] Authentication failed: Timed out waiting for [Responder Auth]
[11165:11165:0620/094524.793996:WARNING:secure_channel.cc(293)] Failed to authenticate connection to device with ID CAESR...KTw==
[11165:11165:0620/094524.794067:INFO:ble_connection_manager.cc(605)] Status change - Device ID: "CAESR...KTw==": [authenticating] => [disconnecting], State change detail: [none]
[11165:11165:0620/094524.794127:INFO:bluetooth_low_energy_weave_client_connection.cc(252)] Disconnection requested; sending "connection close" uWeave packet to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094524.794169:INFO:bluetooth_low_energy_weave_client_connection.cc(851)] Sending a "connection close" uWeave packet to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094524.794210:INFO:bluetooth_low_energy_weave_client_connection.cc(668)] Writing 3 bytes to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11207:0620/094530.250040:WARNING:thread_watcher.cc(171)] Long response time on the UI thread: 11.782 s
[11165:11165:0620/094530.318776:ERROR:bluetooth_low_energy_weave_client_connection.cc(322)] Timed out waiting during SubStatus [connected and sending message]. Destroying connection.

The second lone one "Long response time on the UI thread: 15.253 s":
[11165:11165:0620/094535.276189:INFO:device_to_device_authenticator.cc(137)] Sending [Initiator Hello] message.
[11165:11165:0620/094535.276222:INFO:bluetooth_low_energy_weave_client_connection.cc(668)] Writing 203 bytes to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094535.928176:INFO:device_to_device_authenticator.cc(238)] Received [Responder Auth] message, payload_size=341
[11165:11165:0620/094535.944825:INFO:device_to_device_authenticator.cc(166)] Successfully validated [Responder Auth]! Sending [Initiator Auth]...
[11165:11165:0620/094535.953006:INFO:bluetooth_low_energy_weave_client_connection.cc(668)] Writing 255 bytes to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094535.972343:INFO:device_to_device_authenticator.cc(211)] Authentication succeeded!
[11165:11165:0620/094535.972374:INFO:ble_connection_manager.cc(605)] Status change - Device ID: "CAESR...KTw==": [authenticating] => [authenticated], State change detail: [none]
[11165:11165:0620/094535.972391:INFO:message_transfer_operation.cc(252)] Starting timer for operation with message type 1 from device with ID CAESR...KTw==.
[11165:11165:0620/094535.972412:INFO:ble_connection_manager.cc(320)] SendMessage(): Device ID: "CAESR...KTw==", Message: "{"data":"","type":1}"
[11165:11165:0620/094535.972421:INFO:secure_channel.cc(252)] Sending message to 7d:3f:8e:00:00:03: {feature: "magic_tether", payload: "{"data":"","type":1}"}
[11165:11165:0620/094535.974344:INFO:bluetooth_low_energy_weave_client_connection.cc(668)] Writing 179 bytes to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094536.001725:INFO:ble_connection_manager.cc(216)] Message sent successfully to device with ID "CAESR...KTw=="; message sequence number: 0
[11165:11165:0620/094536.070347:INFO:secure_channel.cc(274)] Received message from 7d:3f:8e:00:00:03: {feature: "magic_tether", payload: "{"type":2,"data":"CAESJQg6EgpGaSBOZXR3b3JrGAQiEQgBEg0iR29vZ2xlR3Vlc3QiMAE="}"}
[11165:11165:0620/094536.070380:INFO:ble_connection_manager.cc(593)] Message received - Device ID: "CAESR...KTw==", Message: "{"type":2,"data":"CAESJQg6EgpGaSBOZXR3b3JrGAQiEQgBEg0iR29vZ2xlR3Vlc3QiMAE="}".
[11165:11165:0620/094536.070410:INFO:host_scanner_operation.cc(209)] Received TetherAvailabilityResponse from device with ID CAESR...KTw== which indicates that tethering is available. setup_required = 0
[11165:11165:0620/094536.070518:INFO:network_host_scan_cache.cc(49)] Updated scan result for Tether network with GUID CAESRQogVU8/kKtXbYfiBNDastSkwwcaunGZu8LVFe9L5KsCl18SIQDpYv1LWyRNyy3215/nQLj4gRrRe5ul7UJXFgZTkL5KTw==. New carrier: Fi Network, new battery percentage: 58, new signal strength: 100
[11165:11165:0620/094536.070559:INFO:master_host_scan_cache.cc(168)] Starting host scan cache timer for Tether network with GUID "CAESRQogVU8/kKtXbYfiBNDastSkwwcaunGZu8LVFe9L5KsCl18SIQDpYv1LWyRNyy3215/nQLj4gRrRe5ul7UJXFgZTkL5KTw==". Will fire in 120 minutes.
[11165:11165:0620/094536.070608:INFO:ble_connection_manager.cc(278)] Unregister - Device ID: "CAESR...KTw==", Request ID: (983DBBAE50D4015366D09C119836F01A)
[11165:11165:0620/094536.070623:INFO:ble_connection_manager.cc(605)] Status change - Device ID: "CAESR...KTw==": [authenticated] => [disconnecting], State change detail: [none]
[11165:11165:0620/094536.070640:INFO:bluetooth_low_energy_weave_client_connection.cc(252)] Disconnection requested; sending "connection close" uWeave packet to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094536.070653:INFO:bluetooth_low_energy_weave_client_connection.cc(851)] Sending a "connection close" uWeave packet to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094536.070667:INFO:bluetooth_low_energy_weave_client_connection.cc(668)] Writing 3 bytes to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}.
[11165:11165:0620/094536.070832:INFO:network_host_scan_cache.cc(49)] Updated scan result for Tether network with GUID CAESRQogVU8/kKtXbYfiBNDastSkwwcaunGZu8LVFe9L5KsCl18SIQDpYv1LWyRNyy3215/nQLj4gRrRe5ul7UJXFgZTkL5KTw==. New carrier: Fi Network, new battery percentage: 58, new signal strength: 100
[11165:11165:0620/094536.070865:INFO:master_host_scan_cache.cc(168)] Starting host scan cache timer for Tether network with GUID "CAESRQogVU8/kKtXbYfiBNDastSkwwcaunGZu8LVFe9L5KsCl18SIQDpYv1LWyRNyy3215/nQLj4gRrRe5ul7UJXFgZTkL5KTw==". Will fire in 120 minutes.
[11165:11165:0620/094536.070894:INFO:host_scanner_impl.cc(239)] Finished Tether host scan. 1 potential host(s) were found.
[11165:11165:0620/094536.094787:INFO:bluetooth_low_energy_weave_client_connection.cc(728)] uWeave "connection close" packet sent to {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}. Destroying connection.
[11165:11165:0620/094536.094884:INFO:bluetooth_low_energy_weave_client_connection.cc(282)] Disconnecting from {id: "CAESR...KTw==", addr: "7d:3f:8e:00:00:03"}
[11165:11165:0620/094536.094974:INFO:ble_connection_manager.cc(605)] Status change - Device ID: "CAESR...KTw==": [disconnecting] => [disconnected], State change detail: [device was unregistered]
[11165:11165:0620/094537.875186:WARNING:arc_bluetooth_bridge.cc(1340)] OnGattDisconnected called, but no gatt connection was found
[11165:11165:0620/094539.786710:ERROR:event_rewriter_chromeos.cc(416)] Device ID 1 is unknown.
[11165:11165:0620/094550.367438:VERBOSE1:arc_net_host_impl.cc(759)] New default network: /service/94 (wifi)
[11165:11165:0620/094557.204701:VERBOSE1:component_updater_service.cc(306)] CheckForUpdates: automatic updatecheck for components.
[11165:11165:0620/094558.136500:VERBOSE1:component_updater_service.cc(383)] Update completed with error 0
[11165:11165:0620/094558.136640:VERBOSE1:component_updater_service.cc(383)] Update completed with error 3
[11165:11184:0620/094603.108042:WARNING:monitor.cc(413)] Request to <URL: 6> had (at least) two NEL headers: "{"failure-fraction":1" and ""include-subdomains":false".
[11165:11165:0620/094603.648243:ERROR:media_internals.cc(103)] Cannot get RenderProcessHost
[11165:11165:0620/094603.648368:ERROR:media_internals.cc(103)] Cannot get RenderProcessHost
[11165:11165:0620/094615.034084:VERBOSE1:arc_net_host_impl.cc(759)] New default network: /service/94 (wifi)
[11165:11209:0620/094621.183908:WARNING:event_reader_libevdev_cros.cc(129)] libevdev: Event_Abs_MT():686: ABS_MT[34] = -65110 : value out of range [-90 .. 90]
[11165:11209:0620/094621.397965:WARNING:event_reader_libevdev_cros.cc(129)] libevdev: Event_Abs_MT():686: ABS_MT[34] = -65114 : value out of range [-65110 .. 90]
[11165:11165:0620/094622.159933:VERBOSE1:arc_net_host_impl.cc(759)] New default network: /service/94 (wifi)
[11165:11207:0620/094629.355794:WARNING:thread_watcher.cc(171)] Long response time on the UI thread: 6.24136 s
[11165:11165:0620/094629.390058:VERBOSE1:arc_net_host_impl.cc(759)] New default network: /service/94 (wifi)
[11165:11165:0620/094629.390785:VERBOSE1:arc_net_host_impl.cc(759)] New default network: /service/94 (wifi)
[11165:11165:0620/094645.603266:INFO:host_scan_scheduler_impl.cc(206)] Logging host scan batch duration. Duration was 20 seconds.
[11165:11207:0620/094645.609003:WARNING:thread_watcher.cc(171)] Long response time on the UI thread: 15.253 s

i will try to disable instant tether to see if it goes away...

I turned BT off, tried to sign in again - this mega jank is still there. Here is the feedback report with BT off:

https://listnr.corp.google.com/product/208/report/85510370789

The "Long response time on the UI thread" line does not show up in #9 feedback. I don't see much abnormal lines except for one big timestamp jump close to the end of chrome user log:

[430:430:0620/150608.656392:INFO:remote_commands_service.cc(160)] Remote commands fetched.
[430:430:0620/150631.141227:VERBOSE1:arc_net_host_impl.cc(759)] New default network: /service/1045 (ethernet)

But I don't see anything obviously wrong around that time.

One more thing to try is to use "Alt+Vol_up+X" to generate a dump when the jank happens again. It might be easier to see who is holding up UI thread this way.

+jhawkins@ & omrilio@ triage owners for the UI>Shell>Networking>Tethering component

Based on Zel's response in comments 8 and 9, this doesn't seem related to Instant Tethering or even bluetooth. I don't think I'm the right owner here.

This bug has an owner, thus, it's been triaged. Changing status to "assigned".

Is this still happening?  If so can we get the report xiyuan asked for in #12?

i don't see those anymore (i am on 70.0.3538.22)