I don’t see a link to logs.i3wm.org. Did you follow https://i3wm.org/docs/debugging.html? (In case you actually provided a link to a logfile, please ignore me.)

i3 listens for keyboard change events (see commit dcba0b4) and it looks like ibus sends a lot of these. Not sure if there is a certain property of these events that i3 should ignore.

I believe this problem is not limited to configurations where "shared input method" is disabled. Disabling this mode merely makes it more apparent. I can reproduce this lag with "shared input method" enabled by switching the input method and immediately trying to switch to other window: the switching will be delayed the same way.

I have traced what's happening a bit, and here are my observations:

handle_event is called with type==xkb_base && state->xkbType == XCB_XKB_NEW_KEYBOARD_NOTIFY 8 times every time input method is changed. Each call takes ~60 ms to complete, which is bad on its own, but having it eight times brings the lag to almost 0.5 s.

By looking at the profile and flame graph, the slow function with the most "self" time is _xcb_map_remove.

handle_event type=85 xkbType=0 (67 ms, 110 _xcb_map_remove calls)
handle_event type=85 xkbType=0 (57 ms, 80 _xcb_map_remove calls)
handle_event type=85 xkbType=0 (51 ms, 57 _xcb_map_remove calls)
handle_event type=85 xkbType=0 (60 ms, 62 _xcb_map_remove calls)
handle_event type=85 xkbType=0 (67 ms, 68 _xcb_map_remove calls)
handle_event type=85 xkbType=0 (67 ms, 67 _xcb_map_remove calls)
handle_event type=85 xkbType=0 (68 ms, 73 _xcb_map_remove calls)
handle_event type=85 xkbType=0 (69 ms, 75 _xcb_map_remove calls)

This problem surfaces in another way with certain applications, like Firefox and Thunderbird.

They tend to send some kind of messages to i3 (type 28, to be exact) when typing, so when i3 is blocked, you can't input text in Firefox. Basically you have to wait 0.5s or more after keyboard layout switch, which is annoying, to put it mildly.

Moreover, performance seems to degrade over time for some reason. Eventually i3 starts to block for several seconds after switching keyboard layout.

FWIW, when running fcitx (alternative to ibus), when switching layouts, i3 receives XCB_XKB_STATE_NOTIFY events, which are handled very quickly.

@bluetech It seems like libxkbcommon’s xkb_x11_keymap_new_from_device is slow, at least when called on XCB_XKB_NEW_KEYBOARD_NOTIFY, which ibus generates many events of whenever the user switches layouts apparently. Should i3 not be calling that function? Or not in response to that event? Or should there be some throttling? Caching?

Thanks for any insights!

And thanks @WGH- for profiling and clarifying :) Much appreciated!

Hmm interesting. That's over a local X server, not SSH or such?

The amount of notifications ibus sends does seem excessive, but first I'd like to understand where the 60ms figure actually comes from.

If @WGH-'s profile is accurate, and the time is indeed spent in _xcb_map_remove, then something is going wrong. While the datastructure used by xcb there is quite poor (a map implemented with a single big non-intrusive linked list!!!), and the function is O(n), the n itself (number of pending replies) should not get so big. It would make more sense if the time is actually spent in the nearby select()/poll() call.

I'll try to reproduce this when I get the chance.

This is indeed a local server.

I might have done a grave mistake of having a library missing its debug symbols, leading to incorrect profile results.

I've added the debug symbols for libxkbcommon, and captured callstack using a different method ("dwarf" in perf). Although there's still something a bit wrong (it missed the inlined static functions despite debug data being available), it looks more believable.

I think the conclusion "xkb_x11_keymap_new_from_device is slow" still stands, but the problem is not in _xcb_map_remove. It might be doing too many remote calls to the X server, which CPU consumption spikes as well, maybe even more so than i3's (but it still might be a misleading and premature conclusion as well).

I tried a few ways to reproduce this but couldn't see any serious slowness on the libxkbcommon side, although I didn't try the actual i3+ibus scenario (a bit too much for me to setup).

Your profile shows the time being spent in adopt_atoms. I somehow doubt it can really be so slow -- a keymap has at most a couple hundred atoms, but a local X server should be able to do about a million GetAtomName requests per second, and we do pipeline most of these requests as well. However optimizing this can't hurt, so I created xkbcommon/libxkbcommon#200 for this. If you can test it that would be great.

Regardless we should find what is causing ibus to issue all of the keymap update notifications. I wouldn't know where to look in the ibus code myself though.

Which keyboard layout and xmodmap are you all using? Maybe that’s related?

Could you please tell me where to look? I configured the X server once, I frankly don't remember.

I can say that in IBus I use xkb:us::eng (QWERTY), xkb:ru::rus (ЙЦУКЕН) and mozc-jp (QWERTY romaji input), if that's what you're asking.

Could you please tell me where to look?

I think the output of setxkbmap -query might be a good start :)

Depending on current ibus input method, correspondingly:

$ setxkbmap -query
rules:      evdev
model:      pc105
layout:     us
$ setxkbmap -query
rules:      evdev
model:      pc105
layout:     ru,us
variant:    ,
$ setxkbmap -query
rules:      evdev
model:      pc105
layout:     jp

@bluetech this patch certainly helps a lot. It's still somewhat slow, but not that much anymore.

When I rapidly switch between open terminal windows in i3, i3 CPU consumption stays relatively low, and there's no visible lag. However, at the same time, CPU spikes in the X server process and Firefox, and Firefox becomes unresponsive for a while (even though it was open on the different workspace).

Perhaps, Firefox doesn't use xkbcommon, and it has similar code? Needs another round of profiling, oh well.

(The trace log above had "ms" and "_xcb_map_remove" mixed up, but the magnitude was similar)

handle_event type=85 xkbType=2 (20 µs, 0 _xcb_map_remove calls)
handle_event type=10 (14 µs, 0 _xcb_map_remove calls)
handle_event type=9 (165 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=2 (12 µs, 0 _xcb_map_remove calls)
handle_event type=33 (19 µs, 0 _xcb_map_remove calls)
handle_event type=10 (9 µs, 0 _xcb_map_remove calls)
handle_event type=10 (6 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=2 (17 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=2 (18 µs, 0 _xcb_map_remove calls)
handle_event type=7 (11 µs, 0 _xcb_map_remove calls)
handle_event type=9 (17 µs, 0 _xcb_map_remove calls)
handle_event type=18 (17 µs, 0 _xcb_map_remove calls)
handle_event type=28 (224 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (7682 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (4705 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (5196 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (5219 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (5052 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (4498 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (3136 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (2830 µs, 0 _xcb_map_remove calls)
handle_event type=28 (3 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=2 (20 µs, 0 _xcb_map_remove calls)
handle_event type=10 (14 µs, 0 _xcb_map_remove calls)
handle_event type=9 (167 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=2 (11 µs, 0 _xcb_map_remove calls)
handle_event type=33 (84 µs, 0 _xcb_map_remove calls)
handle_event type=10 (5 µs, 0 _xcb_map_remove calls)
handle_event type=10 (6 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=2 (16 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=2 (9 µs, 0 _xcb_map_remove calls)
handle_event type=7 (8 µs, 0 _xcb_map_remove calls)
handle_event type=9 (16 µs, 0 _xcb_map_remove calls)
handle_event type=18 (20 µs, 0 _xcb_map_remove calls)
handle_event type=28 (3759 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (7057 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (5922 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (5023 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (5827 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (6729 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (6388 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (4393 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=0 changed=3 (3466 µs, 0 _xcb_map_remove calls)
handle_event type=28 (5 µs, 0 _xcb_map_remove calls)
handle_event type=85 xkbType=2 (55 µs, 0 _xcb_map_remove calls)

Thanks for testing @WGH-. I'll definitely merge it then and do a release some time after. I also added a benchmark to the PR which shows the keymap refresh time improving from about 4ms on my laptop to about 0.6ms (after the first one).

Perhaps, Firefox doesn't use xkbcommon, and it has similar code? Needs another round of profiling, oh well.

Firefox on X11 doesn't use xkbcommon, but every libX11 user has some similar code to refresh the local keymap in response to keymap update events. One difference is that xkbcommon's keymaps are immutable, so even if something small is changed, the entire keymap is re-fetched, while libX11 only updates the parts that changed, and so might be a bit faster. I couldn't say if the Firefox slowness comes from this code however.

_xcb_map_remove

I couldn't understand from the trace if it still showing slowness. If it does, it would not be difficult to speed it up in libxcb.

_xcb_map_remove

I couldn't understand from the trace if it still showing slowness. If it does, it would not be difficult to speed it up in libxcb.

More likely it never did, to be honest.

I'll continue debugging though, as I feel like there's something going on on the X server side.

I know this is likely not an i3 message anymore, but it seems that every time I change input methods, Firefox bombards the X server with tens of thousands ProcXkbGetMap calls, which take 5 seconds, during which Firefox doesn't accept any input. Is this normal?

#!/usr/bin/env bpftrace
uprobe:/usr/bin/X:ProcXkbGetMap {
    @a1[probe] = count();
    @total1[probe] = count();
}

uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap {
    @a2[probe, pid, comm] = count();
    @total2[probe, pid, comm] = count();
}

interval:s:1 {
    print(@a1);
    clear(@a1);
    print(@a2);
    clear(@a2);
}

Sample output (I changed the input method only once):

@total1[uprobe:/usr/bin/X:ProcXkbGetMap]: 26036
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3914837, alacritty]: 1
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3916102, alacritty]: 1
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3915717, alacritty]: 1
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3862501, alacritty]: 1
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3889826, parcellite]: 1
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3916118, alacritty]: 1
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3915869, alacritty]: 1
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3412279, ibus-x11]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3317212, Web Content]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3315983, Web Content]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3317601, Web Content]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3412275, ibus-ui-gtk3]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3318887, Web Content]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3318394, Web Content]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3317317, Privileged Cont]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3315910, WebExtensions]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3320616, Web Content]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3316691, Web Content]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3315863, Web Content]: 2
@total2[uprobe:/usr/lib/libX11.so.6.3.0:XkbGetUpdatedMap, 3315791, firefox]: 25953

FWIW I filed it to Firefox bug tracker https://bugzilla.mozilla.org/show_bug.cgi?id=1680909

After caching was added in libxkbcommon, and Firefox patched, this issue is longer that severe for me. The ibus mode with remembering layouts is still causes noticeable lag, but it is not as bad as it was (I don't really use the mode, however).

I guess in my case Firefox was the main culprit, as hammering the X server slows it down for everyone.

I'll try to collect more profile data to analyze whether things can optimized further, but I can now live with it as things are now.

Just FYI, there was a loosely related issue in AwesomeWM:
awesomeWM/awesome#1494
awesomeWM/awesome@9f3a675

Apparently, there are people who provide xmodmap which long input. For each line of input, some X11 event was generated that caused AwesomeWM to refresh the XKB state. 1000 such events were enough to cause an 11 second freeze of AwesomeWM until all the re-querying was done.

The fix in AwesomeWM was not to deal with the events immediately, but instead remember to do them later. A bit more detailed: A bool was set to true and at the end of a main loop iteration the keymap was updated (think: an ev_prepare watcher was started). If many such events are received during one main loop iteration, the keymap thus is still only updated once.

(So, after the fix, AwesomeWM gets the event and updates the keymap. While the keymap is (slowly) updating, all the other events are received and the keymap is only updated once more in the following main loop iteration.)

(Thank you @bluetech for sending me here)

Edit: Oh, hey, the same reproducer works with i3 (but only produces a three second freeze)!

$ date ; i3-msg nop ; xmodmap <(for x in $(seq 1 1000) ; do echo "keycode 107 = parenleft " ; done) ; i3-msg nop ; date
Sun Mar  7 11:01:55 CET 2021
[{"success":true}]
[{"success":true}]
Sun Mar  7 11:01:58 CET 2021