Xilem's to_do_mvc enters an apparent infinite loop

[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 (e76cf31258c79d263c5669be052353c3e99c012d).

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. :confused:

@DJMcNab I'm not sure how this bug would relate to the pass order RFC. From what I remember of https://github.com/linebender/xilem/pull/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 https://github.com/linebender/xilem/issues/424#issue-2391294297.

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.

[PoignardAzur]

Does this still happen on main?

If so, does it still happen in #599?

[DJMcNab]

As described, this doesn't reproduce on main due to #604. But if I select into the box, then press a character, this does still reproduce for.

This does no longer reproduce in #599, but I disagree with the method it uses to achieve that (of just no longer enabling IME at all) - that leads to a worse UX than with this bug IMO.

[PoignardAzur]

(of just no longer enabling IME at all)

Wait, what?

[DJMcNab]

I don't know - I've not gotten around to actually looking at the code. I'm just reporting the behaviour I'm seeing, that IME is not enabled when I check out that PR.

The input events I'm getting are KeyboardKey, and the IME-style interactions (e.g. emoji input) don't work at all.

[PoignardAzur]

#599 has been merged.

Does this still occur on main?

[DJMcNab]

I believe this is now resolved, yes.