https://bugs.winehq.org/show_bug.cgi?id=49564
Bug ID: 49564 Summary: Tomb Raider I (using DosBox) hangs after starting Product: Wine Version: 5.9 Hardware: x86 URL: https://store.steampowered.com/app/224960/Tomb_Raider_ I/ OS: Linux Status: NEW Keywords: regression Severity: normal Priority: P2 Component: kernel32 Assignee: wine-bugs@winehq.org Reporter: gyebro69@gmail.com CC: julliard@winehq.org Regression SHA1: cd215bb49bc240cdce5415c80264f8daa557636a Distribution: ---
This comment in another bug report made me curious and tried the game myself (Steam version): bug 43826, comment 5
The game comes with it's own version of DosBox and configuration files. I'm starting the game like this (DRM-free, no need to launch Steam to play the game): wine dosbox.exe -conf dosboxTR.conf
The dosbox window is opened showing that 'tomb.exe' was started but it seems to be stuck and the game doesn't start. Htop shows constant 70% CPU usage with csmt=on, 25% when csmt=off. The status of the running dosbox.exe process changes continuously between 'Running' and 'Sleeping' in htop.
Plain terminal output doesn't show anything related.
According to my testing this used to work better, and regression testing resulted in https://source.winehq.org/git/wine.git/commit/cd215bb49bc240cdce5415c80264f8... as the offending commit.
I can't revert that commit but verified that the game starts with the previous commit and plays some intro videos.
Tested in wine-5.12-166-gcaa41d4917
https://bugs.winehq.org/show_bug.cgi?id=49564
--- Comment #1 from Béla Gyebrószki gyebro69@gmail.com --- Better late than never...I've just discovered that the problem goes away if I change 'Cycles' in DosBoxTR.conf from the default 'auto' to anything else, e.g. "cycles=8000". It seems the problems occurs when autodetection is enabled. This is the default DosBox setting with almost every game I encountered so far.
https://bugs.winehq.org/show_bug.cgi?id=49564
qsniyg qsniyg@mail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |qsniyg@mail.com
--- Comment #2 from qsniyg qsniyg@mail.com --- Created attachment 67705 --> https://bugs.winehq.org/attachment.cgi?id=67705 patch to remove epoll_wait timeout
This patch fixes the issue for me. Obviously this is not a correct solution, but it "fixes" the millisecond granularity issue by removing the timeout entirely.
The reason why the issue happens is because the ticks timer is updated every millisecond, but when looking at logs (I've added ERR calls to GetTickCount and Sleep), this will very often (always?) not coincide with the Sleep(1) (or SDL_Delay(1)) call dosbox calls in Normal_Loop (dosbox.cpp).
--- snip --- 835352.591:0024:err:sync:GetTickCount out=835352591 835352.591:0024:err:sync:Sleep sleeping for 1 msec --- snip--- 835352.591:0024:err:sync:Sleep slept 835352.591:0024:err:sync:GetTickCount out=835352591 835352.592:0024:err:sync:GetTickCount out=835352592 --- snip ---
After the hack however, it works properly:
--- snip --- 836157.685:0024:err:sync:GetTickCount out=836157685 836157.685:0024:err:sync:Sleep sleeping for 1 msec --- snip--- 836157.686:0024:err:sync:Sleep slept 836157.686:0024:err:sync:GetTickCount out=836157686 --- snip ---
https://bugs.winehq.org/show_bug.cgi?id=49564
Arek Hiler ahiler@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |ahiler@codeweavers.com
--- Comment #3 from Arek Hiler ahiler@codeweavers.com --- I've been debugging the same issue that happens with Doom II from Steam (also ships with dosbox.exe).
The problem got introduced with cd215bb49b ("kernel32: Use the user shared data to implement GetTickCount().") - instead of 1ms resolution we started slipping into 16-17ms. Windows apparently provides resolution of 10-16ms (according to doc), which turns out to actually be 15-16ms with occasional hiccups https://testbot.winehq.org/JobDetails.pl?Key=76665
This was easy to fix but decreasing the update time to 15 ms: -static const timeout_t kusd_timeout = 16 * -TICKS_PER_SEC / 1000; +static const timeout_t kusd_timeout = 15 * -TICKS_PER_SEC / 1000;
Doom II worked reliably.
Since then another change got introduced - 1ae1088964 ("server: Update shared user data timestamps on every request.") - apparently to address https://bugs.winehq.org/show_bug.cgi?id=49228
So I have tried: -static const int user_shared_data_timeout = 16; +static const int user_shared_data_timeout = 15;
Sadly, the game sill crashes. My current guess is that dosbox.exe doesn't like very unstable deltas between ticks, which we have now because we update timestamps at "random" intervals - on each server request. I am yet to verify that
https://bugs.winehq.org/show_bug.cgi?id=49564
--- Comment #4 from qsniyg qsniyg@mail.com --- (In reply to Arek Hiler from comment #3)
So I have tried: -static const int user_shared_data_timeout = 16; +static const int user_shared_data_timeout = 15;
Sadly, the game sill crashes. My current guess is that dosbox.exe doesn't like very unstable deltas between ticks, which we have now because we update timestamps at "random" intervals - on each server request. I am yet to verify that
The issue with dosbox is that it sleeps for one millisecond, then expects that GetTickCount will be incremented. I submitted a test for this here: https://github.com/wine-mirror/wine/commit/4617f83fcf0a34fe41b0e38dde1567195...
It's supposed to have a near-100% increment rate, but now it has a 6% increment rate instead (which makes sense, 100/16 = 6.25). So it seems like Sleep()ing somehow signals to windows that it should update the tick count, even if it's below the 15-16ms resolution?
I'm not sure about Doom II, but Tomb Raider has the source code for its patched dosbox included with the release. This is the relevant section (in dosbox.cpp):
static Bitu Normal_Loop(void) { --- snip --- Bit32u ticksNew; ticksNew=GetTicks(); ticksScheduled += ticksAdded; if (ticksNew > ticksLast) { ticksRemain = ticksNew-ticksLast; ticksLast = ticksNew; ticksDone += ticksRemain; if ( ticksRemain > 20 ) { ticksRemain = 20; } ticksAdded = ticksRemain; --- snip --- } else { ticksAdded = 0; SDL_Delay(1); // <-- ticksDone -= GetTicks() - ticksNew; // <-- if (ticksDone < 0) ticksDone = 0; }
This means ticksDone will very rarely decrement in the else block. From a quick glance at the surrounding code, I wasn't able to really figure out what the result of this meant, but it works properly when GetTicks() is incremented after sleeping for a millisecond.
https://bugs.winehq.org/show_bug.cgi?id=49564
--- Comment #5 from Henri Verbeet hverbeet@gmail.com --- (In reply to qsniyg from comment #4)
The issue with dosbox is that it sleeps for one millisecond, then expects that GetTickCount will be incremented. I submitted a test for this here: https://github.com/wine-mirror/wine/commit/ 4617f83fcf0a34fe41b0e38dde1567195395efca
It's supposed to have a near-100% increment rate, but now it has a 6% increment rate instead (which makes sense, 100/16 = 6.25). So it seems like Sleep()ing somehow signals to windows that it should update the tick count, even if it's below the 15-16ms resolution?
The issue may be with Sleep() instead of GetTickCount(). I.e., it would not surprise me if Sleep(1) is supposed to sleep until the next tick.
https://bugs.winehq.org/show_bug.cgi?id=49564
Paul Gofman pgofman@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |pgofman@codeweavers.com
--- Comment #6 from Paul Gofman pgofman@codeweavers.com --- I noticed previously that Sleep time on Windows is rounded to the next ~15 ms interval (likely 15.6ms). In Wine Sleep is 1ms precise. So if sleeping with (timeout + 14) & ~15 interval will help the issue it might be the right thing to fix.
https://bugs.winehq.org/show_bug.cgi?id=49564
--- Comment #7 from Arek Hiler ahiler@codeweavers.com --- Just to be sure I have checked how the Sleep() - GetTickCount() relationship looks like: https://testbot.winehq.org/JobDetails.pl?Key=76749&f101=exe64.report&...
.. and I have submitted the following patch that fixes Doom II (including jittery mouse movement) for me: https://www.winehq.org/pipermail/wine-devel/2020-August/171496.html
https://bugs.winehq.org/show_bug.cgi?id=49564
--- Comment #8 from Arek Hiler ahiler@codeweavers.com --- Found the actual root cause of the regression:
https://www.winehq.org/pipermail/wine-devel/2020-August/171896.html
dosbox (SDL) is calling timeBeginPeriod(1) and expects timeGetTime() to have 1ms resolution. timeGetTime() is an alias of GetTickCount().
Making Sleep() last longer by default was just hiding the problem. When I started implementing time resolution setting I have noticed that dosbox stopped working again - this lead me to the fix linked above.
There may be more bugs like this one. GetTickCount() is used widely in Wine's internals. Most of the places expect deltas of 100ms, which should be okay with the current implementation, but this needs further investigation.
https://bugs.winehq.org/show_bug.cgi?id=49564
Béla Gyebrószki gyebro69@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Fixed by SHA1| |e01ef81379f078354ac8c1e5a11 | |af0d807725e50 Resolution|--- |FIXED
--- Comment #9 from Béla Gyebrószki gyebro69@gmail.com --- Fixed with https://source.winehq.org/git/wine.git/commitdiff/e01ef81379f078354ac8c1e5a1...
https://bugs.winehq.org/show_bug.cgi?id=49564
Alexandre Julliard julliard@winehq.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED
--- Comment #10 from Alexandre Julliard julliard@winehq.org --- Closing bugs fixed in 5.16.
-
WineHQ Bugzilla