search

mzur / gnome-shell-wsmatrix

GNOME shell extension to arrange workspaces in a two-dimensional grid with workspace thumbnails
GNU General Public License v3.0
458 stars 58 forks source link

Workspace Switching Becomes Slower Over Time #209

Closed squarewav closed 2 years ago

squarewav commented 2 years ago

When first logging in, workspace switching is reasonably quick (<100ms maybe). But after about a week, workspace switching becomes noticeably slower. After two weeks it starts to become so slow (500ms+) that I have to log out and back in.

I'm trying to figure out if it's Xwayland, the gnome shell or gnome-shell-wsmatrix. How does one log gnome-shell events? Is there something to enable logging to systemd?

If I run xev, and, as quickly as I can, press Ctrl-Alt-Up, Down, Up, Down without waiting for any switching, I get the following

KeyPress event, serial 37, synthetic NO, window 0x800001,
    root 0x348, subw 0x0, time 1705541922, (145,64), root:(2113,181),
    state 0x0, keycode 64 (keysym 0xffe9, Alt_L), same_screen YES,
    XLookupString gives 0 bytes: 
    XmbLookupString gives 0 bytes:
    XFilterEvent returns: False

KeyPress event, serial 37, synthetic NO, window 0x800001,
    root 0x348, subw 0x0, time 1705541931, (145,64), root:(2113,181),
    state 0x8, keycode 37 (keysym 0xffe3, Control_L), same_screen YES,
    XLookupString gives 0 bytes:
    XmbLookupString gives 0 bytes:
    XFilterEvent returns: False

FocusOut event, serial 37, synthetic NO, window 0x800001,
    mode NotifyNormal, detail NotifyNonlinear

PropertyNotify event, serial 37, synthetic NO, window 0x800001,
    atom 0x10c (_NET_WM_STATE), time 1705543864, state PropertyNewValue

PropertyNotify event, serial 37, synthetic NO, window 0x800001,
    atom 0x13c (_GTK_EDGE_CONSTRAINTS), time 1705543864, state PropertyNewValue

FocusIn event, serial 37, synthetic NO, window 0x800001,
    mode NotifyNormal, detail NotifyNonlinear

KeymapNotify event, serial 37, synthetic NO, window 0x0,
    keys:  12  0   0   0   32  0   0   0   1   0   0   0   0   0   0   0
           0   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0

FocusOut event, serial 37, synthetic NO, window 0x800001,
    mode NotifyNormal, detail NotifyNonlinear

PropertyNotify event, serial 37, synthetic NO, window 0x800001,
    atom 0x10c (_NET_WM_STATE), time 1705544110, state PropertyNewValue

PropertyNotify event, serial 37, synthetic NO, window 0x800001,
    atom 0x13c (_GTK_EDGE_CONSTRAINTS), time 1705544110, state PropertyNewValue

FocusIn event, serial 37, synthetic NO, window 0x800001,
    mode NotifyNormal, detail NotifyNonlinear

KeymapNotify event, serial 37, synthetic NO, window 0x0,
    keys:  12  0   0   0   32  0   0   0   1   0   0   0   0   0   0   0
           0   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0

FocusOut event, serial 37, synthetic NO, window 0x800001,
    mode NotifyNormal, detail NotifyNonlinear

PropertyNotify event, serial 37, synthetic NO, window 0x800001,
    atom 0x10c (_NET_WM_STATE), time 1705565077, state PropertyNewValue

PropertyNotify event, serial 37, synthetic NO, window 0x800001,
    atom 0x13c (_GTK_EDGE_CONSTRAINTS), time 1705565077, state PropertyNewValue

Converting timestamps to S.ms I see:

541.922 Alt_L
541.931 Control_L
543.864 _NET_WM_STATE
543.864 _GTK_EDGE_CONSTRAINTS
544.110 _NET_WM_STATE
544.110 _GTK_EDGE_CONSTRAINTS

So I depress Ctrl-Alt, pause for 2 seconds and then the press up arrow triggers some events. Then xev is off screen so it doesn't capture the down arrow. But 246 ms later it does capture the second up arrow. Doing this two other times I get 235 ms and 242 ms.

Note1: I complete the up-down-up-down sequence long before the workspaces even start to switch. So I do up-down-up-down, then there's a seemingly 500ms+ delay and then the workspace switches, pauses very briefly (to display the gnome-shell-wsmatrix popup) and then switches back to the previous workspace.

Note2: Even though I did up-down twice, the workspace appears to only switch up and down once.

Gnome in general can be a little "sticky". The mouse can freeze momentarily for a few hundred ms. Scrolling with mouse wheel in FF can stick briefly. Typing sometimes freezes for a couple hundred ms. As a software developer myself who has written low-level code like drivers and such, my guess would be that there's some bloat somewhere. The hardest problems are always multiple overlapping problems. The first step to figuring this out is going to be to capture timestamps and see were the delay shows up. So how can I capture timestamps from gnome shell?

Using Fedora 41 on newish Dell Latitude laptop. Animations are off. Static Workspaces. I believe I also changed something about how long the "popup" is displayed but I don't recall what setting was used (where?).

Running very few apps. Just FF, claws mail and 6 separate gnome-terminals.

# free -h
               total        used        free      shared  buff/cache   available
Mem:           7.4Gi       3.7Gi       648Mi       656Mi       3.1Gi       2.8Gi
Swap:          7.4Gi       1.5Gi       5.9Gi

I am not experiencing the level of problems described in issue #190. However, I would like to know how that user is capturing log information.

ebeem commented 2 years ago

You can capture the log with journalctl /usr/bin/gnome-shell Probably some log will help investigate this issue more. I personally run my gnome session for a very long time without facing any issues, but let's see if you have any errors in the log and then try to figure it out.

squarewav commented 2 years ago

Letting # journalctl -f /usr/bin/gnome-shell run for a while I am getting some timing related messages. See below.

Sometimes typing freezes. But the mouse pointer freezes equally as much and for as long. Every 30 seconds or so it can be quote pronounced (maybe 100ms+ or so - long enough for me to think "that's annoying"). So it's not limited to the keyboard. I think these messages could be an artifact in something else. Some kind of lower level event processing problem.

Is there a mailing list or forum for Xwayland?

What's the next level down in the event stack?

Of course this is probably multiple overlapping problems maybe interacting with one another. Any one issue people probably don't notice or bother to complain. But when combined they are annoying and difficult to debug.

Feb 07 08:53:57 pico gnome-shell[1729]: Window manager warning: last_user_time (1790135521) is greater than comparison timestamp (1790135217).  This most likely represents a buggy client sending inaccurate timestamps in messages such as _NET_ACTIVE_WINDOW.  Trying to work around...
Feb 07 08:53:57 pico gnome-shell[1729]: Window manager warning: W0 appears to be one of the offending windows with a timestamp of 1790135521.  Working around...
Feb 07 08:58:52 pico gnome-shell[1729]: libinput error: event7  - Logitech Logitech Illuminated Keyboard: client bug: event processing lagging behind by 31ms, your system is too slow
Feb 07 08:59:30 pico gnome-shell[1729]: libinput error: event7  - Logitech Logitech Illuminated Keyboard: client bug: event processing lagging behind by 16ms, your system is too slow
Feb 07 08:59:37 pico gnome-shell[1729]: Window manager warning: last_user_time (1790475198) is greater than comparison timestamp (1790475190).  This most likely represents a buggy client sending inaccurate timestamps in messages such as _NET_ACTIVE_WINDOW.  Trying to work around...
Feb 07 08:59:37 pico gnome-shell[1729]: Window manager warning: W0 appears to be one of the offending windows with a timestamp of 1790475198.  Working around...
Feb 07 09:02:28 pico gnome-shell[1729]: Window manager warning: last_user_time (1790646320) is greater than comparison timestamp (1790646312).  This most likely represents a buggy client sending inaccurate timestamps in messages such as _NET_ACTIVE_WINDOW.  Trying to work around...
Feb 07 09:02:28 pico gnome-shell[1729]: Window manager warning: W8 appears to be one of the offending windows with a timestamp of 1790646320.  Working around...
Feb 07 09:02:50 pico gnome-shell[1729]: Window manager warning: last_user_time (1790668321) is greater than comparison timestamp (1790668225).  This most likely represents a buggy client sending inaccurate timestamps in messages such as _NET_ACTIVE_WINDOW.  Trying to work around...
Feb 07 09:02:50 pico gnome-shell[1729]: Window manager warning: W0 appears to be one of the offending windows with a timestamp of 1790668321.  Working around...
Feb 07 09:04:15 pico gnome-shell[1729]: Window manager warning: last_user_time (1790753898) is greater than comparison timestamp (1790753890).  This most likely represents a buggy client sending inaccurate timestamps in messages such as _NET_ACTIVE_WINDOW.  Trying to work around...
Feb 07 09:04:15 pico gnome-shell[1729]: Window manager warning: W12 appears to be one of the offending windows with a timestamp of 1790753898.  Working around...
Feb 07 09:04:51 pico gnome-shell[1729]: libinput error: event7  - Logitech Logitech Illuminated Keyboard: client bug: event processing lagging behind by 25ms, your system is too slow
Feb 07 09:04:51 pico gnome-shell[1729]: libinput error: event7  - Logitech Logitech Illuminated Keyboard: WARNING: log rate limit exceeded (5 msgs per 60min). Discarding future messages.
Feb 07 09:08:45 pico gnome-shell[1729]: Window manager warning: last_user_time (1791023630) is greater than comparison timestamp (1791023222).  This most likely represents a buggy client sending inaccurate timestamps in messages such as _NET_ACTIVE_WINDOW.  Trying to work around...
Feb 07 09:08:45 pico gnome-shell[1729]: Window manager warning: W12 appears to be one of the offending windows with a timestamp of 1791023630.  Working around...
ebeem commented 2 years ago

Are you sure this is related to this extension? If you disable it, do you face the same problem? It seems like a problem with the input device itself to me.

Also, you can always try out xorg to see if it's really a wayland problem.

mzur commented 2 years ago

Please reopen if you have new information regarding this issue.