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

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

tab-switching: ctrl+tab key-event or mouse-event processing is slow

Project Member Reported by sadrul@chromium.org, Jun 29

Issue description

Attached is a trace where I pressed ctrl+tab to switch between two tabs. The browser had only two tabs open: chrome:tracing, and slashdot (which had iframes, which is why you see more than two renderer processes in the trace).

Some observations:
 (a) DesktopWindowTreeHostX11::Dispatch, which is what processes the key-event to ultimately trigger the tab-switching, takes ~17ms before it triggers the tab-switch (i.e. sends IPC to the target renderer), and takes another ~16ms before it's done processing the key event.
 (b) Views::Layout gets called 436 times (for many different View instances), and takes up ~17ms of the time.
 (c) DesktopScreenX11::GetCursorScreenPoint() gets called ~14 times. We do have an optimization here where we try to avoid calling back to X11 if we are in the middle of processing a mouse-event [1]. However, that doesn't trigger for key-events, and so we end up making synchronous calls to X11 [2] during each call.
 (d) The first View layout happens ~6ms after the event-dispatch starts. There are some sizeable gaps (~2/3 ms) between the Views being re-laid out too. It's not clear what is happening during those times.

Unfortunately, the current tab_switching latency metric in telemetry [3] does not include this, since in telemetry, the tab-switch is not triggered by generating key events. But it should not be hard to rework that, so that the event handling part of the process is also measured.

Some ideas to improve some of the things:
 1. Switching tabs does not really need to re-layout too many Views. I can think of some views that may need a re-layout (e.g. views like the security chip etc. inside the omnibox), but most other Views do not change size or position. So I think there is opportunity to avoid some of the re-layouts.
 2. To address (c), GetCursorScreenPoint() probably needs additional optimization, where we do not ask the X11 server for the cursor-location more than once every message-loop cycle (nested message-loops make this a bit tricky, but should be solvable). Although instead of doing this optimization in X11-specific code, perhaps this could live in an platform-neutral code (e.g. perhaps in aura::Env?).
 3. For (d), some more trace-events would likely be useful.

cc'ing a bunch of folks who may be interested in this. If someone is willing to pick this up, I am more than happy to help.


[1] https://cs.chromium.org/chromium/src/ui/views/widget/desktop_aura/desktop_screen_x11.cc?l=167
[2] https://cs.chromium.org/chromium/src/ui/views/widget/desktop_aura/desktop_screen_x11.cc?l=176
[3] https://chromeperf.appspot.com/report?sid=aecb01308a91a36deeabc216e26d07267118e5eec5c507a1794d4de1181415d3&start_rev=565614&end_rev=571285
 
trace_tab-switch.json.gz
730 KB Download
Cc: -thomasanderson@chromium.org kylec...@chromium.org
For (c) crbug.com/739898 is related.
Cc: thomasanderson@chromium.org
> 2. To address (c), GetCursorScreenPoint() probably needs additional optimization, where we do not ask the X11 server for the cursor-location more than once every message-loop cycle (nested message-loops make this a bit tricky, but should be solvable). Although instead of doing this optimization in X11-specific code, perhaps this could live in an platform-neutral code (e.g. perhaps in aura::Env?).

Or listen to PointerMotion and Enter/LeaveWindow events from X11 and just store the position or the fact that it's not in any window, and no need to query maybe? I'm skeptical that 14 things really need to ask for the mouse position from the server.
Yea, I suspect it's to decide whether to show hover-effect or not.
Cc: yiyix@chromium.org
Also, if we could send the IPC to make the renderer visible earlier, and delay the views layout work until later, that too would be useful to decrease the tab-switch latency (but would be ideal to actually avoid a bunch of that work altogether).
Trace on chromeos. It's pretty similar (but slightly better): the top-level event-dispatch takes ~18ms, we still do 400+ View::Layout()s taking up ~14ms of the time.
trace_tab-switching-cros.json.gz
1.7 MB Download
Cc: groby@chromium.org
+groby@
Cc: brucedaw...@chromium.org
+brucedawson@

Attached is a trace for the same use-case on Windows. Similar issues there: MessagePumpForUI::ProcessMessageHelper() is the toplevel function that processes the native events. It takes ~39ms to process one key event (ctrl+tab). There are ~400 View::Layouts() happening taking up a lot of time, and also a fair amount of time unaccounted for (e.g. what is happening other than layout during the processing of the key event?)
trace_tab-switching-win.json.gz
687 KB Download
Project Member

Comment 10 by bugdroid1@chromium.org, Jul 4

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

commit 00963a488aabf5c4187376fc0274206b617f93c4
Author: Sadrul Chowdhury <sadrul@chromium.org>
Date: Wed Jul 04 20:33:55 2018

Windows: Mark native-message handling as 'toplevel' tasks.

'toplevel' is the category telemetry tests look at when it tries to
compute cpu-usage for a particular thread. Mark the native-message
handling as 'toplevel' tasks, so that input event dispatch shows up
as a top-level entry in traces, and it is included when measuring the
cpu usage of the UI thread.

BUG=858944

Change-Id: I431e0b97df095b56b9da53ac7265cb9238127f16
Reviewed-on: https://chromium-review.googlesource.com/1124705
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Reviewed-by: danakj <danakj@chromium.org>
Cr-Commit-Position: refs/heads/master@{#572646}
[modify] https://crrev.com/00963a488aabf5c4187376fc0274206b617f93c4/base/message_loop/message_pump_win.cc

Owner: sky@chromium.org
Status: Assigned (was: Untriaged)
I'll take this, but likely won't get to it anytime soon.
Well this has been interesting...

I decided to investigate to see where the CPU time is going on Windows during tab switching. I initially hit a problem that UIforETW doesn't have a way to get the "latency" category events into the ETW event stream. I'll fix that but as a short-term workaround I hacked up a local build of Chrome to put TabSwitching::Latency into the startup category. So far so good. I then found that the latest version of WPA can't load symbols from Chrome binaries created by lld. Oops. I've filed https://bugs.llvm.org/show_bug.cgi?id=38126 and lld will be fixed and until then I'm using the previous (16299) version of WPA.

On to the actual bug...

My ETW trace records the input event and the TabSwitching::Latency events. It shows a ~20 ms delay from keyboard input to when TabSwitching::Latency Async Begin occurs. This is on a release non-component build. It then shows a 51-57 ms delay between Async Begin and Async End of TabSwitching::Latency.

Stage 1 (before Async Begin), ~20 ms:
browser process consumes ~28 ms of CPU time
renderer process 1 consumes ~22 ms of CPU time
renderer process 2 consumes ~15 ms of CPU time
Miscellaneous other Chrome processes consume ~44 ms of CPU time
Note that this means about 5.5 cores were in use, so a 2-4 core machine would be oversubscribe and would take longer.
The browser process time is mostly in chrome.dll!TabStripModel::NotifyIfActiveOrSelectionChanged and its descendants (~15.3 ms), with some time for mojo messaging, and a ms or so on chrome.dll!base::Process::SetProcessBackgrounded

Stage 2 (from Async Begin to Async End), ~51-57 ms:
browser process consumes ~55 ms of CPU time
renderer process 1 consumes ~73 ms of CPU time
renderer process 2 consumes ~7 ms of CPU time
GPU process consumes ~33 ms of CPU time
Various other renderer processes...
The CPU is still oversubscribed but not quite as bad - an average of ~4 cores in use for chrome processes
In the browser process I noticed about 5-6 ms of CPU time in ComputeThumbnailScore. UMA says this usually finishes faster than that (elapsed time) so I'm not sure why my CPU usage (sampled) would be that high. Odd. Not a big deal but most of the time is spent in the known-to-be-slow round() function so maybe worth optimizing?
The symbols for chrome_child.dll still don't load so I have no visibility into the renderer processes. Sigh... It's a pity because the call stacks look like there might be two main hot spots.

The trace I examined was this one (not attached and probably not shareable, this is for my own notes):

"2018-07-10_12-16-08 tab switching latency fast sampling.etl"



So the conclusions are:
- About twenty milliseconds of tab switch time is (as far as I can tell) not being accounted for (at least not by TabSwitching::Latency events)
- the amount of CPU time used around tab switching is large enough that on low core-count machines there will be CPU starvation that will make tab switching take longer than on high core-count machines
- Even on high core count machines the delay is not tiny (although not terrible)
- ETW profiling will be tricky until lld is fixed
- UIforETW needs some tweaks to better capture latency events

I grabbed one last trace with the symbols for chrome_child.dll preserved properly this time. In this case the TabSwitching::Latency time from Async Begin to Async End was about 96 ms, switching from slashdot.org to chrome://tracing. The biggest chunk of CPU time by far was from renderer process 17740 which corresponds to Subframe: https://googlesyndication.com and essentially all of the CPU time was in v8.

I don't know if it was on the critical path or not, although it's using enough CPU time to be a tab-switching performance issue on any machine with a modest number of cores.

Project Member

Comment 14 by bugdroid1@chromium.org, Jul 12

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

commit a5d9a9d75a9a8f7f6fb9d749c9b797eb2550d34e
Author: Bruce Dawson <brucedawson@chromium.org>
Date: Thu Jul 12 16:15:25 2018

Add "latency" to list of ETW-traceable events

The "latency" category looks like a perfect event category for ETW
tracing. In particular, TabSwitching::Latency indicates when Chrome
thinks that tab switching has started and stopped which allows it to be
profiled in detail. This has revealed where CPU time is going, and how
long the delay is from when the keyboard event is generated to when
Chrome starts officially processing it. This was helpful in
investigating tab switching latency in bug 858944.

This will require an update to UIforETW to fully enable, which I have
done locally for testing purposes.

Bug: 858944
Change-Id: I4797b804ea6d35458aa3b4e876a78172a29d5131
Reviewed-on: https://chromium-review.googlesource.com/1134516
Reviewed-by: Primiano Tucci <primiano@chromium.org>
Commit-Queue: Bruce Dawson <brucedawson@chromium.org>
Cr-Commit-Position: refs/heads/master@{#574586}
[modify] https://crrev.com/a5d9a9d75a9a8f7f6fb9d749c9b797eb2550d34e/base/trace_event/trace_event_etw_export_win.cc

Summary: tab-switching: ctrl+tab key-event or mouse-event processing is slow (was: tab-switching: ctrl+tab key-event processing is slow)
I add some more traces locally, and here is a result from that:
 1. ClearFocus() [1] takes 2+ms
 2. WebView::DetachWebContents() [2] takes ~6ms
    a- NativeViewHostAura::RemoveClippingWindow [3] takes ~3.5ms of this time
    b- WindowOcclusionTracker [4] takes ~1.5ms of this time.
 3. WebView::AttachWebContents() [5] takes ~10ms
    c- NativeViewHostAura::AddClippingWindow() [6] takes 3ms of this time
    d- WindowOcclusionTracker takes ~4.5ms of this time

We notify the renderer during step 3.d to make itself visible. So from the time of knowing that the renderer needs to be visible, to the time of telling it to make itself visible (i.e. the time of the async-begin TabSwitching::Latency trace event), we spend ~16ms of time. This time is currently not represented in the tab-switching latency metric we measure.

I also measured the time for mouse-click to switch-tabs, and the traces are very similar (i.e. ~16ms to trigger the tab-switch from the reception of the mouse-event, see (a) in the OP).

[1] https://cs.chromium.org/chromium/src/chrome/browser/ui/views/frame/browser_view.cc?l=786
[2] https://cs.chromium.org/chromium/src/ui/views/controls/webview/webview.cc?l=355
[3] https://cs.chromium.org/chromium/src/ui/views/controls/native/native_view_host_aura.cc?g=0&l=273
[4] https://cs.chromium.org/chromium/src/ui/views/controls/native/native_view_host_aura.cc?g=0&l=113
[5] https://cs.chromium.org/chromium/src/ui/views/controls/webview/webview.cc?l=332
[6] https://cs.chromium.org/chromium/src/ui/views/controls/native/native_view_host_aura.cc?l=105
We should consider simplifying NativeViewHost[Aura], so that attach/detach is less expensive.
I filed crbug.com/863135 for the ComputeThumbnailScore function.
I've been looking at the layout part of this for a while for MacViews performance (see  Issue 835983 ). I think most of them can be reduced by not triggering a full layout from a title change for a tabbed browser window.
Project Member

Comment 19 by bugdroid1@chromium.org, Jul 13

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

commit ccf2bd29c63b6449cfb22d20229fb0c93b659545
Author: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Fri Jul 13 19:44:59 2018

tab-switching: Report some additional latency times.

When switching tabs, report the time it takes for the browser to send
the request to the renderer to become visible.

BUG=858944

Change-Id: Id11569162c433a66f61a4fd8dc8ef8c8b2f70327
Reviewed-on: https://chromium-review.googlesource.com/1136217
Reviewed-by: Robert Kaplow (slow) <rkaplow@chromium.org>
Reviewed-by: Scott Violet <sky@chromium.org>
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Cr-Commit-Position: refs/heads/master@{#575025}
[modify] https://crrev.com/ccf2bd29c63b6449cfb22d20229fb0c93b659545/chrome/browser/ui/tabs/tab_strip_model.cc
[modify] https://crrev.com/ccf2bd29c63b6449cfb22d20229fb0c93b659545/tools/metrics/histograms/histograms.xml

Project Member

Comment 20 by bugdroid1@chromium.org, Jul 20

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

commit 02b33c1f9c7145169cfda0caf4b5eb0c50e471b5
Author: Leonard Grey <lgrey@chromium.org>
Date: Fri Jul 20 15:36:31 2018

Views: Don't unnecessarily invalidate layout when setting app menu button margin

Currently, we invalidate the app menu button's layout unconditionally when setting
its margin. Since invalidating layout walks up the view hierarchy, this essentially
keeps ToolbarView's layout dirty all the time.

This change exits early if the new margin is the same as the current margin.

Bug: 858944,  835983 
Change-Id: If94d3c7d29cb1476fdb268a8ece35187d0b43f4f
Reviewed-on: https://chromium-review.googlesource.com/1144222
Reviewed-by: Elly Fong-Jones <ellyjones@chromium.org>
Commit-Queue: Leonard Grey <lgrey@chromium.org>
Cr-Commit-Position: refs/heads/master@{#576873}
[modify] https://crrev.com/02b33c1f9c7145169cfda0caf4b5eb0c50e471b5/chrome/browser/ui/views/toolbar/browser_app_menu_button.cc

Project Member

Comment 21 by bugdroid1@chromium.org, Jul 23

Labels: merge-merged-3497
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/b80a747d547adbc6c364808d7596377a458a3533

commit b80a747d547adbc6c364808d7596377a458a3533
Author: Leonard Grey <lgrey@chromium.org>
Date: Mon Jul 23 18:33:29 2018

Views: Don't unnecessarily invalidate layout when setting app menu button margin

Currently, we invalidate the app menu button's layout unconditionally when setting
its margin. Since invalidating layout walks up the view hierarchy, this essentially
keeps ToolbarView's layout dirty all the time.

This change exits early if the new margin is the same as the current margin.

Bug: 858944,  835983 
Change-Id: If94d3c7d29cb1476fdb268a8ece35187d0b43f4f
Reviewed-on: https://chromium-review.googlesource.com/1144222
Reviewed-by: Elly Fong-Jones <ellyjones@chromium.org>
Commit-Queue: Leonard Grey <lgrey@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#576873}(cherry picked from commit 02b33c1f9c7145169cfda0caf4b5eb0c50e471b5)
Reviewed-on: https://chromium-review.googlesource.com/1147181
Reviewed-by: Leonard Grey <lgrey@chromium.org>
Cr-Commit-Position: refs/branch-heads/3497@{#20}
Cr-Branched-From: 271eaf50594eb818c9295dc78d364aea18c82ea8-refs/heads/master@{#576753}
[modify] https://crrev.com/b80a747d547adbc6c364808d7596377a458a3533/chrome/browser/ui/views/toolbar/browser_app_menu_button.cc

Project Member

Comment 23 by bugdroid1@chromium.org, Jul 27

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

commit 42203ef1c102d04fc52831a9a17890973d106d8d
Author: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Fri Jul 27 16:02:14 2018

tab-switching: Always measure the tab-switch request delay.

Tab-switch requests that are made through devtools for telemetry tests
are not treated as user-gesture. So this metric can not reported in
telemetry tests. However, the cost of this function is not directly
related to the user-gesture itself. So always report this metric and
associated trace event. This allows this to be measured and monitored
in telemetry tests.

BUG=858944

Change-Id: Ib7112b4939c44af099ecfb751fe108bbe8ecec86
Reviewed-on: https://chromium-review.googlesource.com/1152888
Reviewed-by: Michael Wasserman <msw@chromium.org>
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Cr-Commit-Position: refs/heads/master@{#578659}
[modify] https://crrev.com/42203ef1c102d04fc52831a9a17890973d106d8d/chrome/browser/ui/tabs/tab_strip_model.cc

Project Member

Comment 24 by bugdroid1@chromium.org, Jul 31

The following revision refers to this bug:
  https://chromium.googlesource.com/catapult/+/600cb5aa8a50bf2f723671ee7ed62aa722250677

commit 600cb5aa8a50bf2f723671ee7ed62aa722250677
Author: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Tue Jul 31 13:35:50 2018

tabs: Report tab-switching request delay.

Report the delay before the request to make the renderer visible is
dispatched.

BUG=chromium:858944

Change-Id: I01367c82e0f1aea50cd38212d743aed53976a7ca
Reviewed-on: https://chromium-review.googlesource.com/1152483
Reviewed-by: Ben Hayden <benjhayden@chromium.org>
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>

[modify] https://crrev.com/600cb5aa8a50bf2f723671ee7ed62aa722250677/tracing/tracing/metrics/tabs_metric_test.html
[modify] https://crrev.com/600cb5aa8a50bf2f723671ee7ed62aa722250677/tracing/tracing/metrics/tabs_metric.html

Project Member

Comment 25 by bugdroid1@chromium.org, Jul 31

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

commit 2998a12c645c8217787c0b7a1963024cb10cefe3
Author: catapult-chromium-autoroll <catapult-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Date: Tue Jul 31 17:30:04 2018

Roll src/third_party/catapult cf56f6f1be08..100f0ee2ceb7 (2 commits)

https://chromium.googlesource.com/catapult.git/+log/cf56f6f1be08..100f0ee2ceb7


git log cf56f6f1be08..100f0ee2ceb7 --date=short --no-merges --format='%ad %ae %s'
2018-07-31 wangge@google.com Use `--ignore-certificate-error` if in Compatibility Mode
2018-07-31 sadrul@chromium.org tabs: Report tab-switching request delay.


Created with:
  gclient setdep -r src/third_party/catapult@100f0ee2ceb7

The AutoRoll server is located here: https://catapult-roll.skia.org

Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, please contact the current sheriff, who should
be CC'd on the roll, and stop the roller if necessary.

CQ_INCLUDE_TRYBOTS=luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;luci.chromium.try:win_optional_gpu_tests_rel

BUG=chromium:866881,chromium:858944
TBR=sullivan@chromium.org

Change-Id: Icfdb76c18f63fc0451154b71e6df45b6a19a85cb
Reviewed-on: https://chromium-review.googlesource.com/1156488
Reviewed-by: catapult-chromium-autoroll <catapult-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Commit-Queue: catapult-chromium-autoroll <catapult-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Cr-Commit-Position: refs/heads/master@{#579455}
[modify] https://crrev.com/2998a12c645c8217787c0b7a1963024cb10cefe3/DEPS

Sign in to add a comment