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

86 views
Skip to first unread message

leeoneil

unread,
Jul 3, 2026, 7:02:45 PMJul 3
to MPF Users
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

unread,
Jul 4, 2026, 5:58:07 AMJul 4
to MPF Users
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.

Nixco

unread,
Jul 14, 2026, 12:47:11 PMJul 14
to MPF Users
Hi thanks for the update.

In your code,  if you earn, for example, the bigscore5 with 2'600'000, you earn all the bigscore from 1 to 4 as well.

I'm curious if you could solve the issue with this code.

"{current_player.variable_superpops_value==0}": superpops_ready
  "{current_player.score>=500000 and current_player.score<1000000}": bigscore1
  "{current_player.score>=1000000 and current_player.score<1500000}": bigscore2
  "{current_player.score>=1500000 and current_player.score<2000000}": bigscore3
  "{current_player.score>=2000000 and current_player.score<2500000}": bigscore4
  "{current_player.score>=2500000 and current_player.score<3000000}": bigscore5
  "{current_player.score>=3000000}": bigscore6



kaydeeH

unread,
Jul 14, 2026, 1:12:34 PMJul 14
to MPF Users
This is fantastic! We had the same issue on our Dukes of Hazzard and NEVER figured it out. Now I'm super excited to see if the code fix solves the issue for us. Nice work all!

On Friday, July 3, 2026 at 4:02:45 PM UTC-7 l...@rdtp.net wrote:
Reply all
Reply to author
Forward
0 new messages