mpf
mpf copied to clipboard
missionpinball
Scoring with score reels chime lag issue.
When using score_reels and score_reel_groups with chimes defined, the chime pulse lags behind the score reel pulse the amount of the repeat_pulse_time. So for example, score 500 points, the first reel pulse happens then after the repeat time the second reel pulse happens simultaneously with the first chime pulse, then 3rd reel with 2nd chime, etc until the end where there the last chime happens by itself. Log snippet showing this in action.
2022-02-05 09:57:13,866 : INFO : EventManager : Event: ======'player_score'====== Args={'value': 500, 'prev_value': 0, 'change': 500, 'player_num': 1} 2022-02-05 09:57:13,917 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power) 2022-02-05 09:57:13,917 : INFO : SwitchController : <<<<<<< 's_player_1_100' inactive >>>>>>> 2022-02-05 09:57:13,954 : INFO : SwitchController : <<<<<<< 's_left_flipper' inactive >>>>>>> 2022-02-05 09:57:14,090 : INFO : EventManager : Event: ======'reel_score_player_1_100_advance'====== Args={} 2022-02-05 09:57:14,090 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power) 2022-02-05 09:57:14,090 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power) 2022-02-05 09:57:14,296 : INFO : EventManager : Event: ======'reel_score_player_1_100_advance'====== Args={} 2022-02-05 09:57:14,296 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power) 2022-02-05 09:57:14,296 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power) 2022-02-05 09:57:14,502 : INFO : EventManager : Event: ======'reel_score_player_1_100_advance'====== Args={} 2022-02-05 09:57:14,503 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power) 2022-02-05 09:57:14,503 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power) 2022-02-05 09:57:14,710 : INFO : EventManager : Event: ======'reel_score_player_1_100_advance'====== Args={} 2022-02-05 09:57:14,710 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power) 2022-02-05 09:57:14,710 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power) 2022-02-05 09:57:14,914 : INFO : EventManager : Event: ======'reel_score_player_1_100_advance'====== Args={} 2022-02-05 09:57:14,914 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
The delay happens also with just a single pulse event such as scoring 100 pts. The delay is very noticeable in the gameplay, with a delay between playfield object being hit and the chime sounding
Can be seen in the Quidditch homebrew thread on pinside, this post has video https://pinside.com/pinball/forum/topic/my-homebrew-lots-of-questions/page/2#post-5458864
Attached a minimal setup with score reels to show the effect. basically around step 10-14 from tutorial with score reel stuff added.
Looking at this briefly, the reel_[x]_advance event happens after the score reel coil finishes pulsing. So you see it pulse, and then in the next time wave, it shows the advance event. That advance event instantly pulses the coil.
So to time it up, it would need to ready the pulse for the change instead of the advance event for when to pulse the coil. So those two coils pulse in parallel (drive reel and chime).
Not sure if this is due to PSU power management or some logic error. I did not check the code yet. Guess that would be the first thing to find out.
I ran this simplified config borgdog provided and was able to replicate the same delay. So I wouldn't think PSU if virtual is doing it as well. The chime is happening right after the advance event, but the advance event is 1/4 second behind the actual driving of the coil.
I played around with the hw_confirm_time and repeat_pulse_time. But some configurations broke it so it would never reset to let me start a game, and others modified the time, but it would still be wrong (but different amounts of time between repulses.
2022-04-11 15:08:37,995 : INFO : EventManager : Event: ======'player_score'====== Args={'value': 500, 'prev_value': 0, 'change': 500, 'player_num': 1, 'source': 'base'}
2022-04-11 15:08:37,998 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-11 15:08:38,226 : INFO : EventManager : Event: ======'reel_score_player_1_100_advance'====== Args={}
2022-04-11 15:08:38,226 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-11 15:08:38,227 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
It almost looks like coil.c_chime_100 is waiting for 'reel_score_player_1_100_advance' to pulse?
I'm just doing this all virtual at the moment as well, do not have this wired up yet.
Correct, in the code every chime that is configured has a handler for the associated advance event. Presumably there is a delay or a check that takes time in the code, which delays the advance event from posting until that period of time after the coil fires.
There is a ton of nuance here. I added a chime event that fires right after the coil pulses, that removes the 200ms delay that you can see in the logs above. But now the first (and only first) chime fires 40ms early, all others are within 1ms.
Additionally when you get rolling over to the next number both are firing at the same time, even though the pulse for the carry over number is delayed (albeit only ~50ms).
2022-04-11 17:08:07,222 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-11 17:08:07,222 : INFO : coil.c_chime_1000 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-11 17:08:07,222 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-11 17:08:07,270 : INFO : coil.c_player_1_1000 : Pulsing Driver for 10ms (1.0 pulse_power)
I have no intention of every using chimes in my machine, so if this is an acceptable end result, I can clean up the code and push up a PR for review and feedback. Basically it will check if you have chimes in your config and if so fire a reel_XX_chime event. This all happens before the hardwareswitch method checks, and then it would fire the advance event after it confirms.
I'm not sure I follow on the 40ms, can you post more of the event sequence?
I have chimes going into 3 machines, but only one of those will also have score reels where this issue occurs.
This all sounds like an acceptable end result to me, but I can't actually test on the hardware to see if it may cause power issues. I only know of two machines with reels and chimes, Hot Rod, and Quidditch I linked to above. I'm guessing Jeremy probably doesn't want to go through updating whatever MPF version Hod Rod is on to test this (and I think he has his own score reel code anyway), but maybe we can bring the quidditch guy to give feedback.
Oh and thanks much for looking into this.
To elaborate on the 1000 issue: if you look at the four lines above, you can see at .222ms it chimes both 100 and 1000. At the same time it pulses the 100. So the 100 reel and chime are in sync. But the 1000 chime goes off, and then .048 seconds later at .270 the 1000 coil actually rotates.
As for the first time the chime and coil fire, you can see below. I removed all the noise and paired them up. But you can see the very first chime happens immediately after a score is updated, but it takes about 40ms for the reel to trigger. I saw that very consistently. But then after the initial everything is perfectly synced up (at least close enough for human ears and eyes).
2022-04-11 17:08:05,674 : INFO : EventManager : Event: ======'player_score'====== Args={'value': 500, 'prev_value': 0, 'change': 500, 'player_num': 1, 'source': 'base'}
2022-04-11 17:08:05,681 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-11 17:08:05,720 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-11 17:08:05,728 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-11 17:08:05,729 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-11 17:08:05,767 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-11 17:08:05,767 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-11 17:08:05,787 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-11 17:08:05,793 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-11 17:08:05,829 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-11 17:08:05,830 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
As for power issues, its a hunch Jan had, and he might not be wrong. But I would imagine that these are pretty low power coils and unless your YAML has it very restricted in your PSU setup, I would think it could do both. As the above the Quidditch is doing them both at the same time, just delayed by one cycle.
40ms would be far less noticeable than the 250ms or so that it currently does, and since the chime is the one firing first it may not really be noticed at all.
You appear to have a really short repeat_pulse_time there, does everything still hold with something like a 100ms repeat_pulse_time?
If that still behaves the same with a 100ms-150ms repeat_pulse_time, then I would be good with that.
Here is the log based on your original config that was supplied with the updated code (Thanks!). You can see everything paired up that it goes off as expected. Only thing is the ** lines half way through where the 1000 chime and 1000 coil don't perfectly align. That's a bigger thing to straighten out and basically rewrite the logic. So I would say for now that is a necessary evil, but the main chime and reel line up at this point.
2022-04-12 10:15:16,240 : INFO : EventManager : Event: ======'player_score'====== Args={'value': 500, 'prev_value': 0, 'change': 500, 'player_num': 1, 'source': 'base'}
2022-04-12 10:15:16,246 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-12 10:15:16,246 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:16,464 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:16,465 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-12 10:15:16,680 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:16,681 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-12 10:15:16,895 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:16,895 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-12 10:15:17,111 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:17,111 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-12 10:15:17,600 : INFO : EventManager : Event: ======'player_score'====== Args={'value': 1000, 'prev_value': 500, 'change': 500, 'player_num': 1, 'source': 'base'}
2022-04-12 10:15:17,607 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
**2022-04-12 10:15:17,607 : INFO : coil.c_chime_1000 : Pulsing Driver for 20ms (1.0 pulse_power)**
2022-04-12 10:15:17,607 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
**2022-04-12 10:15:17,653 : INFO : coil.c_player_1_1000 : Pulsing Driver for 10ms (1.0 pulse_power)**
2022-04-12 10:15:17,824 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:17,824 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-12 10:15:18,025 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:18,025 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-12 10:15:18,229 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:18,230 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
2022-04-12 10:15:18,414 : INFO : coil.c_player_1_100 : Pulsing Driver for 10ms (1.0 pulse_power)
2022-04-12 10:15:18,421 : INFO : coil.c_chime_100 : Pulsing Driver for 20ms (1.0 pulse_power)
This looks great! Thanks so very much. Now I need to get busy building the machine. Once this gets pushed to dev I'll poke the Quidditch creator and see if they can test it out on actual hardware.
@jabdoa2 Do you have a preference on the solution? There are three options that I have:
- move the advance up before the hardware check. This keeps all code the same, but will fire the advance before it's "actually" advanced
- add a new event for chime right after the reel coil pulse, and leave advance where it is. This means there are two events posted, even if a chime isn't used.
- Get really fancy with number two to check a reel_group to see if chimes are configured and fire the chime event conditionally. Advance would still fire so it doesn't break any user events queued from that. It would be a bigger lift to bring that object over to reference the config, but is probably the cleanest implemented option.
@atummons thanks for your analysis. I would go with 2 as it sounds as clean as possible. Maybe we could add a _will_advance event? In other areas we had similar ordering issues and our usual way is to post will_xxx when we made the decision to do something. Then xxxing when we actually start the process (same as our current event here; we got this without "ing" in a few cases where we added it in retrospectively). Often event handlers can also delay this event (i.e. ball device eject). Finally, we post xxxed after something happened. I would apply the same general structure here as well.
@toomanybrians you completed this PR a while back, so this issue can be closed when you get to it.