Wezterm pauses task/command execution when hidden into scratchpad (minimized?)

[Crandel]

Describe the bug

When I hide scratchpad with wezterm it pause task execution.
For example.

$ while true; do
date; sleep 1
done
2021-06-18T13:46:37 CEST
2021-06-18T13:46:38 CEST
2021-06-18T13:46:39 CEST
2021-06-18T13:46:40 CEST
2021-06-18T13:46:41 CEST
2021-06-18T13:46:42 CEST
2021-06-18T13:46:43 CEST
2021-06-18T13:46:44 CEST
2021-06-18T14:17:27 CEST
2021-06-18T14:17:28 CEST
2021-06-18T14:17:29 CEST
2021-06-18T14:17:30 CEST
2021-06-18T14:17:31 CEST

So wezterm paused command execution on 2021-06-18T13:46:44 CEST and continue on 2021-06-18T14:17:27 CEST

Environment (please complete the following information):

• OS: Arch Linux - Swaywm(Wayland)
• shell: zsh
• Version: wezterm 20210502-154244-3f7122cb
• The active keyboard layout name: ENG

To Reproduce

I emulate quake like behavior with sway build-in scratchpad. One keybinding toggle show/hide scratchpad, so terminal shows only if it's necessary. I test alacritty and tilix on the same scratchpad and they both works as expected, so issue is not on sway side.

Configuration

Config file could be found here

Expected behavior

Command/task execution never paused, until I do it manually.

[wez]

I can't reproduce this; can you try the nightly build?

[Crandel]

Hi @wez . I removed stable version and installed nightly version(20210619-130117-d317f0f3). Result the same. After ~10 minutes in scratchpad it paused and resume again after showing scratchpad.

[wez]

Does it have to be in the scratchpad for 10 minutes before the pause occurs?

[Crandel]

Yes, all this time it was hidden in scratchpad

[wez]

I managed to reproduce this: wezterm is waiting for the wayland server to respond, but the wayland EGL implementation has decided to block forever while waiting for that response:

Thread 1 (Thread 0x7f3f9951eac0 (LWP 933359) "wezterm-gui"):
#0  0x00007f3f99e88a5f in poll () from /lib64/libc.so.6
#1  0x00007f3f999fb92c in poll (__timeout=-1, __nfds=1, __fds=0x7ffead0f96e0) at /usr/include/bits/poll2.h:46
#2  wl_display_poll (display=0x5653894eadc0, display=0x5653894eadc0, events=1) at src/wayland-client.c:1728
#3  wl_display_dispatch_queue (queue=<optimized out>, display=<optimized out>) at src/wayland-client.c:1801
#4  wl_display_dispatch_queue (display=0x5653894eadc0, queue=0x5653897001d0) at src/wayland-client.c:1774
#5  0x00007f3f7b01cc54 in dri2_wl_swrast_commit_backbuffer (dri2_surf=0x565389703a90) at ../src/egl/drivers/dri2/platform_wayland.c:1804
#6  dri2_wl_swrast_put_image2 (draw=0x5653896ed780, op=<optimized out>, x=<optimized out>, y=y@entry=0, w=<optimized out>, h=0, stride=4096, data=0x56538aaa5300 "", loaderPrivate=0x565389703a90) at ../src/egl/drivers/dri2/platform_wayland.c:1934
#7  0x00007f3f7b01cf0c in dri2_wl_swrast_put_image (draw=<optimized out>, op=<optimized out>, x=<optimized out>, y=0, w=<optimized out>, h=<optimized out>, data=0x56538aaa5300 "", loaderPrivate=0x565389703a90) at ../src/egl/drivers/dri2/platform_wayland.c:1946
#8  0x00007f3f798fdc1a in drisw_put_image () from /usr/lib64/dri/swrast_dri.so
#9  0x00007f3f798fdda7 in drisw_swap_buffers () from /usr/lib64/dri/swrast_dri.so
#10 0x00007f3f7b01a66d in dri2_wl_swrast_swap_buffers (disp=<optimized out>, draw=<optimized out>) at ../src/egl/drivers/dri2/platform_wayland.c:1956
#11 0x00007f3f7b0127a2 in dri2_swap_buffers (disp=0x56538960fd20, surf=0x565389703a90) at ../src/egl/drivers/dri2/egl_dri2.c:1998
#12 0x00007f3f7b006071 in eglSwapBuffers (dpy=0x56538960fd20, surface=<optimized out>) at ../src/egl/main/eglapi.c:1341
#13 0x00005653851298f4 in window::egl::ffi::generated::Egl::SwapBuffers (self=0x565389617cc8, dpy=0x56538960fd20, surface=0x565389703a90) at /home/wez/wez-personal/wezterm/target/debug/build/window-49fd002d28264350/out/egl_bindings.rs:531
#14 0x0000565384f75fd4 in window::egl::{{impl}}::swap_buffers (self=0x56538998bbd0) at /home/wez/wez-personal/wezterm/window/src/egl.rs:604
#15 0x0000565384ff0daf in glium::backend::{{impl}}::swap_buffers<window::egl::GlState> (self=0x565389ab4cc0) at /home/wez/.cargo/registry/src/github.com-1ecc6299db9ec823/glium-0.28.0/src/backend/mod.rs:57
#16 0x0000565386602dcb in glium::context::Context::swap_buffers (self=0x565389ac1bf0) at /home/wez/.cargo/registry/src/github.com-1ecc6299db9ec823/glium-0.28.0/src/context/mod.rs:319
#17 0x000056538512520d in glium::Frame::set_finish (self=0x7ffead0f9c00) at /home/wez/.cargo/registry/src/github.com-1ecc6299db9ec823/glium-0.28.0/src/lib.rs:1148
#18 0x000056538512522e in glium::Frame::finish (self=...) at /home/wez/.cargo/registry/src/github.com-1ecc6299db9ec823/glium-0.28.0/src/lib.rs:1134
#19 0x0000565385079c05 in window::os::wayland::window::{{impl}}::finish_frame (self=0x5653895fbc60, frame=<error reading variable: Cannot access memory at address 0x1>) at /home/wez/wez-personal/wezterm/window/src/os/wayland/window.rs:633
#20 0x0000565384f6b87b in window::os::x_and_wayland::{{impl}}::finish_frame (self=0x5653895fbc58, frame=...) at /home/wez/wez-personal/wezterm/window/src/os/x_and_wayland.rs:126
#21 0x0000565383a72f2e in wezterm_gui::termwindow::TermWindow::do_paint (self=0x5653895fbc68, gl=0x5653895fd688, window=0x5653895fbc58) at /home/wez/wez-personal/wezterm/wezterm-gui/src/termwindow/mod.rs:687
#22 0x0000565383b55d74 in wezterm_gui::termwindow::{{impl}}::dispatch_window_event::{{closure}} () at /home/wez/wez-personal/wezterm/wezterm-gui/src/termwindow/mod.rs:659
#23 0x0000565383cc818f in core::future::from_generator::{{impl}}::poll<generator-0> (self=..., cx=0x7ffead0fbfa8) at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/core/src/future/mod.rs:80
#24 0x0000565383b517bc in wezterm_gui::termwindow::{{impl}}::new_window::{{closure}}::{{closure}} () at /home/wez/wez-personal/wezterm/wezterm-gui/src/termwindow/mod.rs:557
#25 0x0000565383cc958b in core::future::from_generator::{{impl}}::poll<generator-2> (self=..., cx=0x7ffead0fbfa8) at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/core/src/future/mod.rs:80
#26 0x0000565383d51951 in async_task::runnable::spawn_local::{{impl}}::poll<core::future::from_generator::GenFuture<generator-2>> (self=..., cx=0x7ffead0fbfa8) at /home/wez/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.0.3/src/runnable.rs:132
#27 0x0000565383ceacf2 in core::future::future::{{impl}}::poll<alloc::boxed::Box<async_task::runnable::spawn_local::Checked<core::future::from_generator::GenFuture<generator-2>>, alloc::alloc::Global>> (self=..., cx=0x7ffead0fbfa8) at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/core/src/future/future.rs:119
#28 0x0000565383bbb06b in async_task::raw::RawTask<core::pin::Pin<alloc::boxed::Box<async_task::runnable::spawn_local::Checked<core::future::from_generator::GenFuture<generator-2>>, alloc::alloc::Global>>, core::result::Result<(), anyhow::Error>, closure-0>::run<core::pin::Pin<alloc::boxed::Box<async_task::runnable::spawn_local::Checked<core::future::from_generator::GenFuture<generator-2>>, alloc::alloc::Global>>,core::result::Result<(), anyhow::Error>,closure-0> (ptr=0x565389553ff0) at /home/wez/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.0.3/src/raw.rs:489
#29 0x000056538687d42a in async_task::runnable::Runnable::run (self=...) at /home/wez/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.0.3/src/runnable.rs:309
#30 0x0000565384fe01fb in window::spawn::schedule_with_pri::{{closure}} () at /home/wez/wez-personal/wezterm/window/src/spawn.rs:42
#31 0x0000565384fbde11 in core::ops::function::FnOnce::call_once<closure-0,()> () at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/core/src/ops/function.rs:227
#32 0x0000565386781ae8 in alloc::boxed::{{impl}}::call_once<(),FnOnce<()>,alloc::alloc::Global> (self=..., args=()) at /rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/alloc/src/boxed.rs:1521
#33 0x0000565384f6e58f in window::spawn::SpawnQueue::run_impl (self=0x5653894dae70) at /home/wez/wez-personal/wezterm/window/src/spawn.rs:171
#34 0x0000565384f6d1ee in window::spawn::SpawnQueue::run (self=0x5653894dae70) at /home/wez/wez-personal/wezterm/window/src/spawn.rs:65
#35 0x0000565384f7085d in window::os::wayland::connection::{{impl}}::run_message_loop (self=0x5653895f1050) at /home/wez/wez-personal/wezterm/window/src/os/wayland/connection.rs:225
#36 0x0000565384f6b6f3 in window::os::x_and_wayland::{{impl}}::run_message_loop (self=0x5653895ae490) at /home/wez/wez-personal/wezterm/window/src/os/x_and_wayland.rs:85
#37 0x0000565383beb9ef in wezterm_gui::frontend::GuiFrontEnd::run_forever (self=0x5653895ae4f0) at /home/wez/wez-personal/wezterm/wezterm-gui/src/frontend.rs:93
#38 0x0000565383abc18e in wezterm_gui::run_terminal_gui::{{closure}} () at /home/wez/wez-personal/wezterm/wezterm-gui/src/main.rs:359
#39 0x0000565383a886d8 in wezterm_gui::run_terminal_gui (opts=...) at /home/wez/wez-personal/wezterm/wezterm-gui/src/main.rs:362
#40 0x0000565383a8c7a0 in wezterm_gui::run () at /home/wez/wez-personal/wezterm/wezterm-gui/src/main.rs:590
#41 0x0000565383a88ba1 in wezterm_gui::main () at /home/wez/wez-personal/wezterm/wezterm-gui/src/main.rs:401

This thread is also responsible to acting on the data that is read from the shell output. As there is back-pressure between these two threads, the shell eventually fills up the kernel buffer and the date command blocks.

AFAICT, the root cause is the wayland server not responding. This is compounded by the EGL implementation deciding to block forever inside the buffer swap routine.

These two things aren't directly under the control of wezterm, so I'm not sure that there is a lot that I can do to mitigate this.

[Crandel]

Thank you @wez for investigation. Would it help if I open an issue in sway about this behavior?

[wez]

Yeah, I think it would be good to get some feedback on what's going on and how applications are supposed to respond in this situation!

[Crandel]

According to @emersion

Yes, this is expected. The client needs to listen to wl_surface.frame callbacks. See https://emersion.fr/blog/2018/wayland-rendering-loop/.

[emersion]

Let me know if you have questions.

If you can't listen to these events to know when to render, some workarounds are being discussed in this Mesa issue: https://gitlab.freedesktop.org/mesa/mesa/-/issues/4932

[Crandel]

Hi @wez any news about this issue?

[wez]

No news; I understand broadly what needs to happen, but since I don't often use wayland and I don't use sway this hasn't been top of my mind. If you, or someone else, is motivated to try a PR for this, the gist of it is that:

• The code under window/src/os/wayland needs to set up an event callback for the frame callback on the appropriate surface(s)
• That callback would need to track whether a frame could be drawn and stash it in, perhaps, a boolean in the window state
• We'd want to avoid dispatching WindowEvent::NeedRepaint if that boolean indicates that we can't draw
• There may need to be some other adjustments around how we invalidate the window (eg: force the need for a repaint) as well

An alternative approach that might be easier to wrangle: one of the existing callbacks receives the set of window states (eg: maximization, minimization) in SCTKWindowEvent::Configure handling. If we're minimized, we could pretty simply skip dispatching WindowEvent::NeedRepaint. Assuming that the scratch pad state is reflected in a similar way, then that might help to resolve this. That change might "just" be a matter of allowing the do_paint function in window/src/os/wayland/window.rs to reason about those states.

You could try starting wezterm using WEZTERM_LOG=window=debug,trace wezterm and putting it in the scratch pad. It should log the configure events and the states (grep for Config: in its stderr) and that might suggest whether we could use the simpler state based version.

[Crandel]

You could try starting wezterm using WEZTERM_LOG=window=debug,trace wezterm and putting it in the scratch pad. It should log the configure events and the states (grep for Config: in its stderr) and that might suggest whether we could use the simpler state based version.

So I run latest wezterm-nightly using your command for ~15 minutes and got this result

    807: 2021-08-03T16:19:51.983Z DEBUG window::os::wayland::window > Config: self.full_screen=None, states:false []
    908: 2021-08-03T16:19:52.032Z DEBUG window::os::wayland::window > Config: self.full_screen=None, states:false [Activated]
   7527: 2021-08-03T16:20:07.573Z DEBUG window::os::wayland::window > Config: self.full_screen=None, states:false []
   7821: 2021-08-03T16:33:28.081Z DEBUG window::os::wayland::window > Config: self.full_screen=None, states:false [Activated]
  73901: 2021-08-03T16:33:37.318Z DEBUG window::os::wayland::window > Config: self.full_screen=None, states:false []

[wez]

AFAICT, this is now resolved in main and should show up in the nightly downloads in ~10 minutes from now

[Crandel]

I can confirm - nightly works fine. Thank you very much!

[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.