Gameplay suddenly jumps back/seeks for a frame

[flustix]

Type

Game behaviour

Bug description

While playing, the gameplay jumped back about 12 seconds for a singular frame and then goes back, causing HitObjects to flicker and be missed. This also triggered the "Playback discrepancy" (Line 369 of 1706694260.runtime.log)

Screenshots or videos

flicker.mp4

Version

2024.130.2

Logs

compressed-logs.zip

[bdach]

I'm bumping to p0 due to count of duplicates reported, but am also at a loss where to even begin with investigating this.

Maybe we can start by collecting info about the audio devices involved...

@flustix @UneCloud @Vince7778 @DutchEllie @Packsolite @jaydenamour19 @DoubleJ-G please post information about your hardware, especially audio card. if on windows, the easiest way is via a dxdiag report:

1. Press Windows+R, type dxdiag in the appearing window and press Enter.
2. You could be prompted if you'd want Windows to check if the device drivers are signed - there should be no harm in agreeing to that.
3. In the DirectX Diagnostic Tool window that will appear, click Save All Information... and choose a file to save to.
4. Attach the saved file to this issue.

also general information about your setup would be appreciated (frame limiter settings, threading mode, anything else you may consider relevant).

[DutchEllie]

I am using Arch Linux. My kernel version is 6.7.4-arch1-1, but it probably was not at the time when I last found this issue. The game version at the time was 2024.131.0. I am using Pipewire for audio driver.
My audio is going through my GPU (AMD RX 7900 XTX). The rest of my system is a Threadripper 3960X with 128GB of RAM.

If you need any more information, just ask me. My logs are still in my old issue #27004.

[UneCloud]

Sure thing. Here you go!
DxDiag.txt

Frame limiter: 8x
Threading mode: multi-threading
The audio is passed through the front port of the case, leading to the motherboard's built-in audio Realtek ALC897

[peppy]

I see there being two possibilities for how this could manifest, either:

• Something very broken in a framework-level clock causing the frame discrepancy (reasoning: this would just be consumed by the clock hierarchy osu!-side as-is)
• Something outside of the player (GameplayClock) system is performing a seek, ie. another component elsewhere in the game. (reasoning: we would see a seek in logs if it was performed by gameplay)

[DoubleJ-G]

Posting information after being directed here from #27343. I managed to get a screen capture of this happening in osu! standard. Note I have seen this happen multiple times just very infrequently, this is the second time it happened in one play session which is why I was recording hoping to catch it again. You can see the flash of change around 8 seconds.

OSU.Frame.Bug.mov

You can see it is actually going back a few hit circles to the blue 1 -2 slider for a frame and counting those as misses.
osu-bug-compressed-logs.zip

I am on an M1 Mac Ventura 13.4 using "Basically Unlimited" and Multithreaded for settings. I believe my audio drivers would just be whatever the default macos is

[frenzibyte]

@DoubleJ-G Do you have an audio offset applied on the beatmap or the entire game itself via settings?

[frenzibyte]

I would consider investigating the possibility of this being related to #26605 (or potentially #26600), since those were shipped in 2024.130.2, which is precisely when the issue started popping up frequently.

Another thing that keeps popping up is that the difference in the jump is almost always 12 seconds behind (except for #26843, 19 seconds)

[jaydenamour19]

I'm playing on a stock 14 inch MacBook Pro 2023 (M2 Pro) running Sonoma 14.3.1. I play with 0ms audio offset on all maps. Sometimes the bug will instantly fail me, but the other day it happened and it just caused all objects on the screen to count as misses even though I FC'd. Very weird.

[DoubleJ-G]

@frenzibyte My offset is 0ms. Also you can see the difference in my jump is only ~2 seconds

[frenzibyte]

@frenzibyte My offset is 0ms. Also you can see the difference in my jump is only ~2 seconds

That's likely due to the frame-stability clock. The new time is set 12 seconds behind for only one frame, so the frame-stability clock tried to catch up by going 2 seconds behind on the first frame, then time got fixed and frame-stability came back forward on the second frame.

[Toasterly]

compressed-logs.zip
Just happened to me on 2024.221.0

Osu Standard

Windows 11
OpenGL Renderer

[Ladwick]

compressed-logs.zip
I experienced this same thing for the first time right now on 2024.221.0
Windows 10
Direct3D 11
x4 Refresh Rate
Multithreaded

[peppy]

Thanks for all the reports, but we don't need any more "me-too" reports 👍.

[peppy]

I would consider investigating the possibility of this being related to #26605

Doesn't do anything suspicious that would cause this.

(or potentially #26600)

Can't be unless it was happening in previous releases but to a lesser extent (would have been jumping back 50 frames * 16 ms so 800ms. I can't find any reports of this.

---

I was hopeful I'd find an answer somewhere amongst the seek changes (ie. the replay-specfiic buttons we added that can seek backwards 10sec etc.) but haven't been able to yet.

[bdach]

would have been jumping back 50 frames * 16 ms so 800ms

Would have been 5 frames I think? 80ms would be probably noticeable but not as egregious.

I'd say that the fact that everything moves instantly is most indicative of frame stability letting a rogue seek through more than it would have before but the underlying failure is likely in another castle. With a lack of reproduction I'm not sure how we're going to catch that as clocks are famously easily debuggable...

Maybe we should jury-rig a change that prevents frame stability from seeking backwards at all during active gameplay (I can't recall a valid reason for real gameplay to seek backwards of all things, aside from initial seek), and/or when such a situation is detected like dump full clock state to sentry or something. As much as one would consider expedient. Because I don't know how we ever get this solved otherwise.

(except for #26843, 19 seconds)

That was on a DT score, by the way, so that lines up (19 / 1.5 = about 12).

The 12-second clue is probably the weirdest thing in this entire fiasco and also the most interesting thread, but I have no idea what it means or find anything related to that in source. It does appear that the skip freakishly lines up to be about ~11850ms long in pretty much all cases. No idea why.

[peppy]

Would have been 5 frames I think?

Yeah this was a misread of a test scene instead of the actual number: https://github.com/ppy/osu/pull/26600/files#diff-e15efd8ec019a73775f6374670c2735e43c39f9b8c964d5c2848b7338084e0f4L132

[ppy-sentryintegration]

Sentry issue: OSU-11TP

[bdach]

So in preliminary review, sentry collected.... a lot of noise.

For reducing it, I recommend putting the "Denying backwards seek during gameplay" screen:SoloPlayer filter in discover tab, which mostly scopes down to the creepy 12 seconds cases. And the log output therein appears to point the finger pretty heavily at DecouplingFramedClock:

Denying backwards seek during gameplay (reference: 157 863,53 stable: 169 667,36)
originalSource: current: 169 678,87 running: True rate: 1
userGlobalOffsetClock: current: 157 863,53 running: True rate: 1 elapsed: -11 820,50
platformOffsetClock: current: 157 863,53 running: True rate: 1 elapsed: -11 820,50
userBeatmapOffsetClock: current: 157 863,53 running: True rate: 1 elapsed: -11 820,50
interpolatedTrack: current: 157 848,53 running: True rate: 1 elapsed: -11 820,50
decoupledTrack: current: 157 848,53 running: True rate: 1 elapsed: -11 820,27
finalClockSource: current: 157 863,53 running: True rate: 1 elapsed: -11 820,50

Denying backwards seek during gameplay (reference: 74,050.08 stable: 84,876.33)
originalSource: current: 84,873.27 running: True rate: 1
userGlobalOffsetClock: current: 74,050.08 running: True rate: 1 elapsed: -10,842.91
platformOffsetClock: current: 74,041.08 running: True rate: 1 elapsed: -10,842.91
userBeatmapOffsetClock: current: 74,050.08 running: True rate: 1 elapsed: -10,842.91
interpolatedTrack: current: 74,026.08 running: True rate: 1 elapsed: -10,842.91
decoupledTrack: current: 74,026.08 running: True rate: 1 elapsed: -10,843.27
finalClockSource: current: 74,050.08 running: True rate: 1 elapsed: -10,842.91

Denying backwards seek during gameplay (reference: 60.015,79 stable: 71.806,82)
originalSource: current: 71.812,52 running: True rate: 1
userGlobalOffsetClock: current: 60.015,79 running: True rate: 1 elapsed: -11.807,70
platformOffsetClock: current: 60.015,79 running: True rate: 1 elapsed: -11.807,70
userBeatmapOffsetClock: current: 60.015,79 running: True rate: 1 elapsed: -11.807,70
interpolatedTrack: current: 60.000,79 running: True rate: 1 elapsed: -11.807,70
decoupledTrack: current: 60.000,79 running: True rate: 1 elapsed: -11.807,94
finalClockSource: current: 60.015,79 running: True rate: 1 elapsed: -11.807,70

In all these examples, the original source clock is the furthest forward (even ahead of proposedTime), and the decoupledTrack is where the stupid shenanigans start. That said I don't get why this is happenng. The source is running, so the decoupled clock should be just using whatever the source is. But it's... not?

[peppy]

Some more pulled logs for good measure:

Denying backwards seek during gameplay (reference: 11'841.38 stable: 23'651.20)
originalSource: current: 23'672.43 running: True rate: 1
userGlobalOffsetClock: current: 11'841.38 running: True rate: 1 elapsed: -11'826.48
platformOffsetClock: current: 11'841.38 running: True rate: 1 elapsed: -11'826.48
userBeatmapOffsetClock: current: 11'841.38 running: True rate: 1 elapsed: -11'826.48
interpolatedTrack: current: 11'841.38 running: True rate: 1 elapsed: -11'826.48
decoupledTrack: current: 11'841.38 running: True rate: 1 elapsed: -11'826.35
finalClockSource: current: 11'841.38 running: True rate: 1 elapsed: -11'826.48

Denying backwards seek during gameplay (reference: 34 587,15 stable: 46 376,15)
originalSource: current: 46 386,67 running: True rate: 1
userGlobalOffsetClock: current: 34 587,15 running: True rate: 1 elapsed: -11 805,66
platformOffsetClock: current: 34 587,15 running: True rate: 1 elapsed: -11 805,66
userBeatmapOffsetClock: current: 34 587,15 running: True rate: 1 elapsed: -11 805,66
interpolatedTrack: current: 34 572,15 running: True rate: 1 elapsed: -11 805,66
decoupledTrack: current: 34 572,15 running: True rate: 1 elapsed: -11 805,56
finalClockSource: current: 34 587,15 running: True rate: 1 elapsed: -11 805,66

Denying backwards seek during gameplay (reference: 184,000.42 stable: 195,786.95)
originalSource: current: 183,994.42 running: True rate: 1
userGlobalOffsetClock: current: 184,000.42 running: True rate: 1 elapsed: -11,803.19
platformOffsetClock: current: 184,009.42 running: True rate: 1 elapsed: -11,803.19
userBeatmapOffsetClock: current: 184,000.42 running: True rate: 1 elapsed: -11,803.19
interpolatedTrack: current: 183,994.42 running: True rate: 1 elapsed: -11,803.19
decoupledTrack: current: 183,994.42 running: True rate: 1 elapsed: -11,803.20
finalClockSource: current: 184,000.42 running: True rate: 1 elapsed: -11,803.19

Denying backwards seek during gameplay (reference: 82,361.94 stable: 94,144.21)
originalSource: current: 94,140.07 running: True rate: 1
userGlobalOffsetClock: current: 82,361.94 running: True rate: 1 elapsed: -11,798.94
platformOffsetClock: current: 82,352.94 running: True rate: 1 elapsed: -11,798.94
userBeatmapOffsetClock: current: 82,361.94 running: True rate: 1 elapsed: -11,798.94
interpolatedTrack: current: 82,337.94 running: True rate: 1 elapsed: -11,798.94
decoupledTrack: current: 82,337.94 running: True rate: 1 elapsed: -11,799.05
finalClockSource: current: 82,361.94 running: True rate: 1 elapsed: -11,798.94

Denying backwards seek during gameplay (reference: 13,766.91 stable: 25,529.05)
originalSource: current: 25,530.84 running: True rate: 1.5
userGlobalOffsetClock: current: 13,766.91 running: True rate: 1.5 elapsed: -11,778.81
platformOffsetClock: current: 13,769.91 running: True rate: 1.5 elapsed: -11,778.81
userBeatmapOffsetClock: current: 13,766.91 running: True rate: 1.5 elapsed: -11,778.81
interpolatedTrack: current: 13,747.41 running: True rate: 1.5 elapsed: -11,778.81
decoupledTrack: current: 13,747.41 running: True rate: 1.5 elapsed: -11,778.98
finalClockSource: current: 13,766.91 running: True rate: 1.5 elapsed: -11,778.81

Denying backwards seek during gameplay (reference: 18.732,03 stable: 30.524,56)
originalSource: current: 30.535,83 running: True rate: 1
userGlobalOffsetClock: current: 18.732,03 running: True rate: 1 elapsed: -11.809,20
platformOffsetClock: current: 18.732,03 running: True rate: 1 elapsed: -11.809,20
userBeatmapOffsetClock: current: 18.732,03 running: True rate: 1 elapsed: -11.809,20
interpolatedTrack: current: 18.717,03 running: True rate: 1 elapsed: -11.809,20
decoupledTrack: current: 18.717,03 running: True rate: 1 elapsed: -11.809,05
finalClockSource: current: 18.732,03 running: True rate: 1 elapsed: -11.809,20

Denying backwards seek during gameplay (reference: 133 095,99 stable: 144 899,17)
originalSource: current: 144 921,22 running: True rate: 1
userGlobalOffsetClock: current: 133 095,99 running: True rate: 1 elapsed: -11 819,85
platformOffsetClock: current: 133 095,99 running: True rate: 1 elapsed: -11 819,85
userBeatmapOffsetClock: current: 133 095,99 running: True rate: 1 elapsed: -11 819,85
interpolatedTrack: current: 133 095,99 running: True rate: 1 elapsed: -11 819,85
decoupledTrack: current: 133 095,99 running: True rate: 1 elapsed: -11 819,34
finalClockSource: current: 133 095,99 running: True rate: 1 elapsed: -11 819,85

[peppy]

I've spent more time investigating this than I should have.

Remarks:

• In line with @bdach's summary in Gameplay suddenly jumps back/seeks for a frame #26879 (comment), the issue looks to be occurring at either the source, or decoupling clock
• The new sentry reporting is far too noisy as it can fire from cases where player is not even the active screen, will fix this.
• A lot of the reports on sentry have weird localisations (probably not important but the percentage with them is higher than expected)

Conclusion:

I don't believe decoupling clock is the point of failure. As already pointed out, the logic there is quite simple. Even in the case the track wasn't running, there's no feasible way I can see for a backwards seek to happen (unless decoupling clock is doing a seek and TrackBass is handling that seek incorrectly – not out of the question).

I believe something is seeking the source – aka the TrackBass – and the decoupling clock is reacting to that. To which you will likely ask "then why isn't this shown in originalSource?", and the answer is that TrackBass' state and current time are updated from the audio thread, so the chance it's reporting an incorrect timestamp for a single audio update loop (1ms) and recovering before the log is high.

I'm still working through potential cases where this could be happening, but more probable outcome being a second round of logging changes for the next release which give us visibility of all track seeks, or weird changes in TrackBass timings.

[peppy]

See #27849 (comment) for another similar case.

[UneCloud]

Hello once again! I am the guy from #26843 .
Just encountered the same bug, but this time it looked like the one from #27849

I know it's been requested not to send any more me-toos, but this one seems to be a variation of this bug that is still murky waters.

Timestamp: (01:50:55 - 15:32:27 UTC)
VOD: https://www.twitch.tv/videos/2124833058?t=01h50m55s
YT version of the VOD in case Twitch VOD expires/gets deleted: https://youtu.be/p6Pm_sfx0Go?si=vCFd5BntD0fhj5O-&t=6655

Exact moment of the bug happening (logs): 15:32:32

26843_20042024.zip

[peppy]

Another case reported #29061 (extra logs may help figure something)

[frenzibyte]

I have came across this multiple times recently. I've attached a logger on TrackBass and took the client for a spin, and ended up with this:

2024-08-08 16:34:47 [error]: Denying backwards seek during gameplay (reference: 88,916.60 stable: 99,761.08)
2024-08-08 16:34:47 [error]: originalSource: current: 99,783.83 running: True rate: 1
2024-08-08 16:34:47 [error]: userGlobalOffsetClock: current: 88,916.60 running: True rate: 1 elapsed: -10,861.14
2024-08-08 16:34:47 [error]: platformOffsetClock: current: 88,916.60 running: True rate: 1 elapsed: -10,861.14
2024-08-08 16:34:47 [error]: userBeatmapOffsetClock: current: 88,916.60 running: True rate: 1 elapsed: -10,861.14
2024-08-08 16:34:47 [error]: interpolatedTrack: current: 88,916.60 running: True rate: 1 elapsed: -10,861.14
2024-08-08 16:34:47 [error]: decoupledTrack: current: 88,916.60 running: True rate: 1 elapsed: -10,860.92
2024-08-08 16:34:47 [error]: finalClockSource: current: 88,916.60 running: True rate: 1 elapsed: -10,861.14

It appears that BASS is actually reporting wrong time for a single frame, thus causing all of this fiasco. I guess the next step would be to make an isolated repro and pass it over to un4seen.

[peppy]

@frenzibyte I don't believe you need an isolated repro to report to bass. Knowing whether it only happens with mixers or not should be enough context to report it.

For someone who lives and breathes a library, they should be able to know what is the probably cause in seconds to minutes even without a repro scenario.

[frenzibyte]

Reported to un4seen: https://www.un4seen.com/forum/?topic=20482.0 (or search for "BASS_Mixer_ChannelGetPosition reporting incorrect time at a single moment")

[frenzibyte]

Latest update by Ian (BASS dev):

TL;DR: Test using latest beta libraries, and test without the BASS FX layers in the track/stream.

Cannot test this myself any time soon due to lack of a setup and/or time. Therefore I'm putting this up front for anyone that can reproduce this and want to beat me to it.

[peppy]

No one on the dev side has repro'd apart from you. Also please attach the text, not a screenshot of text.

[frenzibyte]

Yes, you can get the latest macOS builds at those URLs. BASSmix wasn't available but I have added that now too. There's also a BASS_FX update that you can try:

www.un4seen.com/stuff/bass_fx-osx.zip

Please see if the problem still happens when using them. If it does, to narrow it down, can you try disabling the BASS_FX stuff (ie. skip BASS_FX_TempoCreate and BASS_FX_ReverseCreate) to see if it still happens then?

[peppy]

I'd propose we just push the beta versions out in the imminent release if you don't have time to test.

[frenzibyte]

Sounds fine by me, feel free to open a PR for that. You may not be able to cover up all platforms though, but I guess it doesn't matter since Windows is the ruler anyway.