Xilem's to_do_mvc enters an apparent infinite loop (depends on specifics of IME, blocked on rework of pass order)

[matta]

Xilem's to_do_mvc example (xilem/examples/to_do_mvc.rs) seems to go into a loop when I click on the text edit.

This is on Debian, running from Xilem's current head (e76cf31).

1. cd <repo root>
2. cd xilem
3. cargo run --example to_do_mvc
4. Click on the text input.

CPU usage for the app goes up to about 40%, and the log spews this seemingly forever:

17:55:17.227Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.227Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.244Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.244Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.260Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.260Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.277Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.277Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.294Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.294Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.310Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.310Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.327Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.327Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.343Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.344Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.360Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.360Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.377Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.377Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.393Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.394Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.410Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.410Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.427Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.427Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.444Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.444Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.460Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.460Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true
17:55:17.477Z DEBUG text_event: Running ON_TEXT_EVENT pass with Ime::Preedit("")
17:55:17.477Z DEBUG text_event: ON_TEXT_EVENT finished focused_widget=1 handled=true

[DJMcNab]

Thanks!
This is a known issue, and is due to an expedient hack added in #314, which was needed as we have not fully designed our passes. This should be resolved when the pass order update is designed and implemented.

As for using 40% of your CPU, that is a surprisingly large amount, as I believe we are entirely single threaded. What's the amount used if you use release mode?

[matta]

As for using 40% of your CPU, that is a surprisingly large amount, as I believe we are entirely single threaded. What's the amount used if you use release mode?

Apologies, I wasn't clear. There is nothing surprising about the CPU usage, I think. The percentage I spoke of is reported by top, which reports 100% CPU usage when a process is fully utilizing a single CPU core (and/or hyperthread if that is enabled).

The release build of the to_do_mvc example hovers around 13% of one core/hyperthread on my machine.

Glad there is an explanation. Feel free to close this issue if there is no utility in keeping it open.

[PoignardAzur]

I'm on PopOS 22.04, and I tried to run cargo run --example to_do_mvc on commit e76cf31 and I can't reproduce either the high CPU usage or the endless logs. I'm not sure why we're getting different results there. 😕

@DJMcNab I'm not sure how this bug would relate to the pass order RFC. From what I remember of #314, I'm guessing you mean the fact we're sending a signal from the paint() method which would be moved to another pass? (Eg the upcoming "compose" pass?)

[matta]

To eliminate oddities specific to my Debian installation, I checked the behavior in a freshly created Debian 12 VM. It behaves the same as I report in #424 (comment).

I did the same in a PopOS 22 VM and can confirm @PoignardAzur's results. It doesn't seem to happen in PopOS 22.

Debian 12 runs Gnome 43.9, whereas PopOS 22 runs Gnome 42.9. Maybe there is some difference. It isn't clear how mature access kit is when run against these older Gnome versions.

[PoignardAzur]

I see. Then yes, I think we'll look at it again after the "pass specification" refactor.

[DJMcNab]

It isn't clear how mature access kit is when run against these older Gnome versions.

To be clear, this behaviour is nothing to do with AccessKit, and is entirely based on what IME provider your desktop environment is using. The reason I say this has to do with pass order, is that will make it so that we know when a widget has moved, which would be used to update the IME position. It's just about not moving this code to somewhere else, if that somewhere else won't exist when we then do the pass order work.