Found a bug 0.57.3 - performance issues solved - wait between 2 balls

[leeoneil]

Hello everyone,
if you remember me, i'm behind the cthulhu pinball.
I came here several times for a big performance issue with my homebrew : very very long wait beetween 2 balls, when playing big score ang long plays.

Last month I was exhausted, impossible to find my bug (working on it since 2 years !!!).
So I tried Claude AI. Yeah I know... I'll burn in hell.
But the result is astonishing so I want to share it here, maybe it's a problem with MPF, and can help the development team.

I had this code on my base mode :

  "{current_player.variable_superpops_value==0}": superpops_ready

  "{current_player.score>=500000}": bigscore1

  "{current_player.score>=1000000}": bigscore2

  "{current_player.score>=1500000}": bigscore3

  "{current_player.score>=2000000}": bigscore4

  "{current_player.score>=2500000}": bigscore5

  "{current_player.score>=3000000}": bigscore6

I just changed it for this, and everything i now fine :

  player_variable_superpops_value{value==0 and change!=0}: superpops_ready

  player_score{value>=50000 and current_player.bigscore1_done==0}: bigscore1

  player_score{value>=100000 and current_player.bigscore2_done==0}: bigscore2

  player_score{value>=150000 and current_player.bigscore3_done==0}: bigscore3

  player_score{value>=200000 and current_player.bigscore4_done==0}: bigscore4

  player_score{value>=250000 and current_player.bigscore5_done==0}: bigscore5

  player_score{value>=300000 and current_player.bigscore6_done==0}: bigscore6

You can't imagine how pleased I am !

Here is a sunthetis enterely written by the AI, I hope you won't blame me for this.
It helped understand what was happening :

# Multi-second freeze between balls: subscription futures leak event handlers on `player_turn_ended`/`player_turn_started`

## Summary

Condition-only config player entries (e.g. `event_player: "{current_player.score>=50000}": some_event`) leak event handlers on every re-evaluation. The leaked handlers accumulate on `player_turn_ended` and `player_turn_started` for the whole duration of a ball, and are all executed/removed at the next player turn transition, with quadratic cost. On long, high-scoring balls this produces a silent multi-second freeze between two balls (we measured 4.5 s after a ~6.5 minute ball; nothing is written to the log during the freeze).

The bug is in MPF 0.57.3/0.57.4 and the relevant code is unchanged on the current `dev` branch.

## Symptoms

- Long pause between the end of one ball and the start of the next (game appears frozen after the bonus display, before the next ball is served).

- Pause duration grows superlinearly with the amount of scoring during the preceding ball.

- Never happens before an extra ball (extra balls skip the `player_turn_*` events).

- The MPF log is completely silent during the pause: the gap sits exactly between `player_turn_ended` and `player_turn_will_start`.

Measured on our machine (Windows, MPF 0.57.4, single player):

| Ball | `player_score` events during ball | `player_turn_ended` → `player_turn_will_start` |

|---|---|---|

| short ball (~2 min) | 102 | 0.18 s |

| long ball + extra ball (~7 min) | 618 | **4.55 s** |

The ratio of durations (~25×) matches the quadratic prediction ((618/102)² ≈ 37).

## Root cause

Config players treat a key that is *only* a condition as a subscription

(`ConfigPlayer.register_player_events` → `_create_subscription` → `_update_subscription`, `mpf/core/config_player.py`).

Each (re-)evaluation goes through `PlaceholderManager.evaluate_and_subscribe_template` (`mpf/core/placeholder_manager.py`), which collects one future per placeholder node:

- every `current_player` **name node** subscribes via `PlayerPlaceholder.subscribe()` → `wait_for_any_event(["player_turn_ended", "player_turn_started"])` → registers **2 event handlers**;

- every **attribute node** (e.g. `.score`) subscribes via `subscribe_attribute` → `wait_for_event("player_<attr>")` → registers 1 event handler;

- plus `asyncio.shield(machine.stop_future)` appended to the list.

These futures are then combined with:

```python

future = Util.any(subscriptions)   # = Util.first(futures, timeout, False)

```

`Util.first` with `cancel_others=False` (`mpf/core/utility_functions.py`) does **not** cancel the losing futures when the first one completes. Even if it did, cancelling a `wait_for_event` future would not deregister its handlers: `EventManager._wait_handler` (`mpf/core/events.py`) only removes its keys when the awaited event actually fires.

Consequence, for a template like `current_player.score>=50000 and current_player.bigscore1_done==0`:

1. Any `player_score` event completes the `.score` future → the template re-evaluates → a **fresh** set of futures/handlers is registered.

2. The previous evaluation's `player_turn_ended`/`player_turn_started` handlers (4 of them here: 2 per `current_player` occurrence) and the `player_bigscore1_done` handler are orphaned and stay registered.

3. Orphaned handlers are only purged when *their* event fires. `player_turn_*` fires only at a real player turn transition — never during the ball, never on extra balls — so they pile up for the entire ball.

4. At `player_turn_ended`, thousands of stale `_wait_handler`s run; each performs an O(n) `remove_handler_by_key` on the (huge) handler list → overall O(n²). With ~7,600 accumulated handlers this takes seconds, with no logging.

The same leak exists for `variable_player`, `show_player` and `light_player` subscriptions, and for device/timer placeholders (those orphans land on more frequently firing events, so they self-purge faster and mostly go unnoticed).

## Reproduction

Minimal config idea (any game config):

```yaml

event_player:

  "{current_player.score>=999999999}": never_happens

```

Play (or simulate) a ball with a few hundred scoring events, then drain. The `player_turn_ended` → `player_turn_will_start` gap grows with the number of score events; with several such templates (we had 6) the pause reaches multiple seconds. Instrumenting `len(machine.events.registered_handlers['player_turn_ended'])` during a ball shows monotonic growth.

## Workaround (config level)

Replace condition-only keys with event-triggered conditional keys, which are evaluated lazily and create no subscriptions:

```yaml

# before (leaks):

"{current_player.score>=50000 and current_player.bigscore1_done==0}": bigscore1

# after (no leak):

player_score{value>=50000 and current_player.bigscore1_done==0}: bigscore1

```

After converting our 6 score-based templates, the same segment went from 4.55 s down to **1–2 ms**, verified on a session with ~2,200 score events and a 7+ minute ball.

## Suggested fix directions

- In `evaluate_and_subscribe_template` (or `Util.first`), cancel the losing futures once one completes, **and** make cancellation of a `wait_for_event`/`wait_for_any_event` future actually deregister its handlers (e.g. via `Future.add_done_callback` removing the keys on cancellation, since `_wait_handler` currently only removes keys when the event fires).

- Alternatively, have subscriptions reuse persistent per-(template, event) handlers instead of re-registering on every evaluation.

Happy to provide the full before/after logs if useful.

**Environment:** MPF 0.57.4 (also 0.57.3), MPF-MC, Python on Windows 10, custom homebrew machine. Code references checked against the 0.57.4 sdist and the current `dev` branch.

[Alex L]

Good stuff! I put up a proposed fix at https://github.com/missionpinball/mpf/pull/2056 . It would be great if you could try it with the conditional-only event style syntax. Though I guess it's 0.81-only when it's on dev. You could cherry-pick the commits, if you're on git and using 0.57.3~4.