wezterm lags with fast output in another pane/window, with format-tab-title event _and_ large keys/key_table

[crides]

What Operating System(s) are you seeing this problem on?

Linux X11, macOS

Which Wayland compositor or X11 Window manager(s) are you using?

Awesomewm

WezTerm version

20240102-011725-2f7ca41a

Did you try the latest nightly build to see if the issue is better (or worse!) than your current version?

Yes, and I updated the version box above to show the version of the nightly that I tried

Describe the bug

The reproduction below should describe what the bug is.

This quite weird as the lag only happens when the focus is on the pane without the large output. I was trying to use vtebench to see what the problem could be, and it's definitely not output ingestion rate (which is what vtebench solely tests). Focusing on another pane or not, with fast output running, doesn't really change the results vtebench gives

The lag completely goes away with either the format-tab-title callback removed (even changing it to something very simple like return '42' doesn't help), or removing the keys/key_table options. It doesn't seem like a section of the key_table introduces the issue, as commenting out parts of it improves the lag, but not completely remove it.

Removing any other config options does nothing.

To Reproduce

1. Use the config below
2. create a new tab
3. split into a new pane
4. run vtebench (or really, any program that dumps a lot of output)
5. focus on the other pane/tab/window
6. both panes will begin to lag

Configuration

config.lua

Expected Behavior

No response

Logs

No response

Anything else?

I'm currently testing out #4737, hence the version. But I've had the problem for quite a while now (starting with the 20230712-072601-f4abf8fd release, with some nightly builds in between), with the config barely changing. However, I haven't tested if removing format-tab-title or keys/key_table alleviates the problem on Mac or older versions.

I think this is a GUI rendering issue, but not because of the rendering backend. I have a 16" Macbook Pro (M2) for work, and the lag occurs on that and my linux laptop which barely has a GPU:

wezterm.gui.enumerate_gpus() on my linux laptop

[
    {
        "backend": "Vulkan",
        "device": 22806,
        "device_type": "IntegratedGpu",
        "driver": "Intel open-source Mesa driver",
        "driver_info": "Mesa 23.2.1-arch1.2",
        "name": "Intel(R) HD Graphics 620 (KBL GT2)",
        "vendor": 32902,
    },
    {
        "backend": "Gl",
        "device": 0,
        "device_type": "IntegratedGpu",
        "name": "Mesa Intel(R) HD Graphics 620 (KBL GT2)",
        "vendor": 32902,
    },
]

If there are any testing/logging options/patches, I'm happy to try/build.

[cstrahan]

FWIW, I'm also seeing performance problems with format-tab-title. Using something minimal like this causes the terminal to slow down quite a bit.

wezterm.on("format-tab-title", function(tab, tabs, panes, config, hover, max_width)
  return {
    { Text = "TEST" },
  }
end)

If I have a zsh shell open and start typing, the text renders about 2 seconds later.

This is on wezterm 20240108-182319-1c090195, on macOS 14.1, Apple M1 Pro.

[cstrahan]

Here's a minimal reproducer, pared down from my config:

local wezterm = require 'wezterm'
local config = {}
config.color_schemes = wezterm.get_builtin_color_schemes()
wezterm.on("format-tab-title", function(tab, tabs, panes, config, hover, max_width)
  return {
    { Text = "TEST" },
  }
end)
return config

The latency increases (maybe quadratic?) proportional to the number of tabs, whether those tabs are in one window or a bunch of windows containing a single tab. Each time I create a new tab, the time to display the new tab grows longer and longer.

To justify the presence of that config.color_schemes = wezterm.get_builtin_color_schemes(): In my full config, I do this:

config.color_scheme = 'Tango (terminal.sexy)'
-- make the scrollbar thumb more visible
config.color_schemes = wezterm.get_builtin_color_schemes()
local color_scheme = config.color_schemes[config.color_scheme]
color_scheme.scrollbar_thumb = "555555"

I still want all of the built-in themes available to play around with, but I also wanted to tweak the Tango (terminal.sexy) theme to make the scrollbar thumb higher contrast. I would probably want to make similar tweaks in other themes I might want to try out (more specifically, I've thought about iterating through all themes and settings the scrollbar colors to be the same, higher contrast colors).

If I keep the config.color_schemes small, any increase in latency is imperceptible:

config.color_scheme = 'Tango (terminal.sexy)'
-- make the scrollbar thumb more visible
local color_schemes = wezterm.get_builtin_color_schemes()
config.color_schemes = {
  [config.color_scheme] = color_schemes[config.color_scheme]
}
local color_scheme = color_schemes[config.color_scheme]
color_scheme.scrollbar_thumb = "555555"

It's odd that settings a callback for the format-tab-title event and increasing the number of configured color_schemes are required to cause this issue. Perhaps unlike the native tab formatting, maybe the user defined formatting code path does something inefficient with the color_schemes? Maybe crossing the Rust<->Lua boundary more often, or something accidentally quadratic, or... something else?

[cstrahan]

With format-tab-title handled and even a small color_schemes config, consisting of just one color scheme, while typing latency is alright, there are other visible symptoms of some underlying issue: if I quickly increase the window size by grabbing the window decorations, the background color takes about 1-2 seconds to paint -- until that point, the title bar immediately grows/paints as it should, but the tab bar, panes and everything are transparent, letting the desktop or other apps bleed through.

I'll see if I can get a screen recording to demo.

[cstrahan]

Here's the demo of the window resizing issues with one configured color scheme (and the format-tab-title callback registered):

And here's a demo of typing and creating new tabs with all of the default color schemes configured (and the format-tab-title callback registered):

[crides]

Here's a minimal reproducer, pared down from my config:

local wezterm = require 'wezterm'
local config = {}
config.color_schemes = wezterm.get_builtin_color_schemes()
wezterm.on("format-tab-title", function(tab, tabs, panes, config, hover, max_width)
  return {
    { Text = "TEST" },
  }                                           
end)                                          
return config                                 

Wait, so for you even format-tab-title by itself is laggy?

[cstrahan]

Wait, so for you you format-tab-title by itself is laggy?

If I also have any configured config.color_schemes, yes.

[crides]

This is not the case for me. If I remove only the key table from my config, things are fine

[crides]

I think I've found what's wrong/weird. I've added some logging around when format-tab-title is called, and ran through the reproduction steps above.

Here's the numbers for my full config:

╭────┬─────────────────────────────────────────────────────────────────────────────────────┬───────╮
│  # │                                        value                                        │ count │
├────┼─────────────────────────────────────────────────────────────────────────────────────┼───────┤
│  0 │ left status                                                                         │     1 │
│  1 │ title changed Alert { pane_id: 0, alert: WindowTitleChanged(" -") }                 │     1 │
│  2 │ title changed Alert { pane_id: 0, alert: IconTitleChanged(Some(" -")) }             │     1 │
│  3 │ activate_tab                                                                        │     1 │
│  4 │ title changed Alert { pane_id: 0, alert: CurrentWorkingDirectoryChanged }           │     1 │
│  5 │ title changed Alert { pane_id: 0, alert: WindowTitleChanged("~") }                  │     1 │
│  6 │ focus_changed                                                                       │     2 │
│  7 │ activate key table                                                                  │     2 │
│  8 │ title changed Alert { pane_id: 1, alert: CurrentWorkingDirectoryChanged }           │     2 │
│  9 │ title changed Alert { pane_id: 1, alert: WindowTitleChanged("~/gitproj/vtebench") } │     2 │
│ 10 │ title changed Alert { pane_id: 0, alert: OutputSinceFocusLost }                     │     2 │
│ 11 │ right status                                                                        │     6 │
│ 12 │ modifiers led                                                                       │     7 │
│ 13 │ mouse move ui                                                                       │     7 │
│ 14 │ mouse leave ui                                                                      │    33 │
│ 15 │ paint window                                                                        │   248 │
│ 16 │ title changed Alert { pane_id: 1, alert: OutputSinceFocusLost }                     │  3714 │
╰────┴─────────────────────────────────────────────────────────────────────────────────────┴───────╯

and here are the numbers when the keys/key_table have been removed:

╭────┬─────────────────────────────────────────────────────────────────────────────────────┬───────╮
│  # │                                        value                                        │ count │
├────┼─────────────────────────────────────────────────────────────────────────────────────┼───────┤
│  0 │ left status                                                                         │     1 │
│  1 │ title changed Alert { pane_id: 0, alert: WindowTitleChanged(" -") }                 │     1 │
│  2 │ title changed Alert { pane_id: 0, alert: IconTitleChanged(Some(" -")) }             │     1 │
│  3 │ title changed Alert { pane_id: 0, alert: CurrentWorkingDirectoryChanged }           │     1 │
│  4 │ title changed Alert { pane_id: 0, alert: WindowTitleChanged("~") }                  │     1 │
│  5 │ focus_changed                                                                       │     2 │
│  6 │ right status                                                                        │     2 │
│  7 │ title changed Alert { pane_id: 0, alert: OutputSinceFocusLost }                     │     2 │
│  8 │ title changed Alert { pane_id: 2, alert: CurrentWorkingDirectoryChanged }           │     2 │
│  9 │ title changed Alert { pane_id: 2, alert: WindowTitleChanged("~/gitproj/vtebench") } │     2 │
│ 10 │ activate_tab                                                                        │     5 │
│ 11 │ modifiers led                                                                       │    11 │
│ 12 │ mouse move ui                                                                       │    18 │
│ 13 │ mouse leave ui                                                                      │   134 │
│ 14 │ paint window                                                                        │   815 │
│ 15 │ title changed Alert { pane_id: 2, alert: OutputSinceFocusLost }                     │  2884 │
╰────┴─────────────────────────────────────────────────────────────────────────────────────┴───────╯

The 2 highest counts are paint window and title changed Alert { .. alert: OutputSinceFocusLost }. I'm quite confused as to why either of these need to trigger tab title updates.

Now, why does removing the keys/key_table options make a difference? I'm not sure yet. In the above numbers, the config with the removed options does have fewer OutputSinceFocusLost alerts, even though I havenlot actually focus on the pane with large output (other than to start and kill it), and the tests run for basically the same length of time (~62 secs).

One thing that is kinda weird, is that the time it takes to call to lua for format-tab-title is quite different for the 2 tests. The full config one is 1ms 999µs 685ns on average (stddev: 1ms 42µs 600ns) and the no keys/key_table one is 878µs 29ns on average (stddev: 674µs 246ns)

[crides]

for me, I'll remove the tab title update on those 2 instances, and test drive for probably about a week, and report back. what I can say for now is, with those removed, it's not yet possible for me to reproduce the issue

testing branch

[crides]

After a week of (heavy) use, can't feel any lag I felt before. However, tab title updating doesn't always happen when it should. For example, the tab title doesn't always update when switching panes. That's not a big issue for me, as I almost always rename the tab to something, but I'll look into it sometime

[wez]

Thanks for diving into this!

Like any good problem, it seems like there are layers that combine to make things painful.

Here's my quick take:

• Unconditionally calling wezterm.get_builtin_color_schemes() is expensive, because it is building a huge table of almost 1k color schemes and serializing it to lua. There's room to optimize this by making it return a lazily bound userdata object that will allow you to only pay the cost of accessing just the scheme you want. If you want to work around this, you might consider doing some manual caching of just the bits you need using https://wezfurlong.org/wezterm/config/lua/wezterm/GLOBAL.html which is using a similar technique already; I'm not sure if this will help because I can't remember whether this does a deep lazy bind on the values stored inside, but it's worth a try:

function get_schemes()
  local schemes = wezterm.GLOBAL.color_schemes
  if schemes then
    return schemes
  end
  wezterm.GLOBAL.color_schemes = wezterm.get_builtin_color_schemes()
  return wezterm.GLOBAL.color_schemes
end

config.color_schemes = get_schemes()

• It is surprising to see so many title changed Alert { pane_id: 1, alert: OutputSinceFocusLost } get triggered. The intent there is to support folks that want to render notifications in their status area when there is output after the focus is lost. Are you running a lot of actively updating background tabs/panes? I'm wondering why you see so many of these events. It seems like there may be something with an incorrect boundary condition somewhere that is generating too many of these, and that should definitely be looked at.
• https://github.com/osandov/wezterm/blob/2f7ca41a5e6aece60abd58c1febfe2fe405edd3d/wezterm-gui/src/termwindow/render/paint.rs#L117 is called in the render loop so that hover states can be detected and rendered correctly for tabs. In your disabled branch, are those working correctly when you hover the mouse across the tabs? It seems like the logic in mouseevent.rs may be sufficient to take care of this and that it is now fine to remove the call from the render loop
• re: tab title not updating when switching tabs, I think that is something you could fix by adding PaneFocused(_) to the set of events over here: crides@bc55667#diff-ae806be0a0b895bb2bc3b43919c4476617d0039fc475ffd1daad594c1dc821cbR1132

[wez]

re: OutputSinceFocusLost, maybe this diff will help; aside from cargo check confirming this, it is untested:

diff --git a/term/src/terminalstate/mod.rs b/term/src/terminalstate/mod.rs
index f18ad0b6b..6d3476c9b 100644
--- a/term/src/terminalstate/mod.rs
+++ b/term/src/terminalstate/mod.rs
@@ -379,6 +379,7 @@ pub struct TerminalState {
     accumulating_title: Option<String>,

     lost_focus_seqno: SequenceNo,
+    lost_focus_alerted_seqno: SequenceNo,
     focused: bool,

     /// True if lines should be marked as bidi-enabled, and thus
@@ -575,6 +576,7 @@ impl TerminalState {
             enable_conpty_quirks: false,
             accumulating_title: None,
             lost_focus_seqno: seqno,
+            lost_focus_alerted_seqno: seqno,
             focused: true,
             bidi_enabled: None,
             bidi_hint: None,
@@ -795,8 +797,11 @@ impl TerminalState {

     pub(crate) fn trigger_unseen_output_notif(&mut self) {
         if self.has_unseen_output() {
-            if let Some(handler) = self.alert_handler.as_mut() {
-                handler.alert(Alert::OutputSinceFocusLost);
+            if self.lost_focus_seqno > self.lost_focus_alerted_seqno {
+                self.lost_focus_alerted_seqno = self.seqno;
+                if let Some(handler) = self.alert_handler.as_mut() {
+                    handler.alert(Alert::OutputSinceFocusLost);
+                }
             }
         }
     }

the intent is to only send one alert after losing focus, but to allow more alerts again after regaining and subsequently losing focus.

[crides]

• Unconditionally calling wezterm.get_builtin_color_schemes() is expensive, [...]

What is this referring to? I don't think I have this in my dotfiles (can check more when I get back)

• It is surprising to see so many title changed Alert { pane_id: 1, alert: OutputSinceFocusLost } get triggered. [...] Are you running a lot of actively updating background tabs/panes?

Yeah, especially at work. Because I often need to context switch between things, some including some compilations that produces a lot of output. It might not even be background, depending on your definition, cuz it might just be a pane on the side

The intent there is to support folks that want to render notifications in their status area when there is output after the focus is lost.[...]

But that would be for the status widgets/bar right? Not tab titles?

• https://github.com/osandov/wezterm/blob/2f7ca41a5e6aece60abd58c1febfe2fe405edd3d/wezterm-gui/src/termwindow/render/paint.rs#L117 is called in the render loop so that hover states can be detected and rendered correctly for tabs. In your disabled branch, are those working correctly when you hover the mouse across the tabs?

Yes

• re: tab title not updating when switching tabs, I think that is something you could fix by adding PaneFocused(_) to the set of events over here: crides@bc55667#diff-ae806be0a0b895bb2bc3b43919c4476617d0039fc475ffd1daad594c1dc821cbR1132

Yes I'm trying something like that

[wez]

• Unconditionally calling wezterm.get_builtin_color_schemes() is expensive, [...]

What is this referring to? I don't think I have this in my dotfiles (can check more when I get back)

It's part of the discussion on this issue.

But that would be for the status widgets/bar right? Not tab titles?

It's the "same thing" from the perspective of rendering that part of the display; if either of them change, then both need to be rendered.

[wez]

I've pushed a commit that I think tackles the heart of this issue, which is cutting down the per-paint and per-output-event triggers for format-tab-title.

Please give it a try and let me know how you get on!

It typically takes about an hour before commits are available as nightly builds for all platforms. Linux builds are the fastest to build and are often available within about 20 minutes. Windows and macOS builds take a bit longer.

You can find the nightly downloads for your system in the wezterm installation docs.

If you prefer to use packages provided by your distribution or package manager of choice and don't want to replace that with a nightly download, keep in mind that you can download portable packages (eg: a .dmg file on macOS, a .zip file on Windows and an .AppImage file on Linux) that can be run without permanently installing or replacing an existing package, and can then simply be deleted once you no longer need them.

If you are eager and can build from source then you may be able to try this out more quickly.

[crides]

Thanks, I'll test drive this tomorrow and let you know how it goes

[crides]

No problems running with this patch as far as I can tell. Thanks!

[github-actions]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues. If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.