The online racing simulator
Linux: Every 30 seconds glitch/lag - screen freeze for about third of a second
(21 posts, started )
Linux: Every 30 seconds glitch/lag - screen freeze for about third of a second
Hey guys,

I am experiencing a problem mentioned in the thread name. My LFS freezes for ~0.3 sec every ~30secs (almost precise 30 seconds I think).

Have you anyone had similar issue? Any ideas what could be the problem? What to focus on?

I have tried to play with graphics settings, but to no avail.

Running on
Intel(R) Core(TM) i7-3520M CPU @ 2.90GHz

with Integrated laptop graphics
VGA compatible controller
product: 3rd Gen Core processor Graphics Controller
vendor: Intel Corporation

Fedora release 21 (Twenty One) @ 3.19.5-200.fc21.x86_64

wine-1.7.41 (Staging)

$ update-alternatives --display wine
wine - status is auto.
link currently points to /usr/bin/wine32
/usr/bin/wine64 - priority 10
slave wine-preloader: /usr/bin/wine64-preloader
/usr/bin/wine32 - priority 20
slave wine-preloader: /usr/bin/wine32-preloader
Current `best' version is /usr/bin/wine32.

# Tried wine64 LFS.exe (no change)

$ glxinfo | grep -i "version"
server glx version string: 1.4
client glx version string: 1.4
GLX version: 1.4
OpenGL core profile version string: 3.3 (Core Profile) Mesa 10.4.7
OpenGL core profile shading language version string: 3.30
OpenGL version string: 3.0 Mesa 10.4.7
OpenGL shading language version string: 1.30
OpenGL ES profile version string: OpenGL ES 3.0 Mesa 10.4.7
OpenGL ES profile shading language version string: OpenGL ES GLSL ES 3.0



PS: If anyone would have also an idea, how to resolve every time recalibrating wheel after alt+f4 (and back), please, let me know as well.

Thank you Smile
Well I got lots of frame drops here and there in Blackwood. You using 32 libraries in wine or is it just 64bit?
I am using 64bit libraries..
Apart from this issue, I am really satisfied with the performance.
If it happens only online, your system clock might be running too fast. In the other case you might wish to run "strace -tt wine LFS.exe" and check the timestamps to see if there is something specific that takes too long to finish.
What I am looking for in such a log output from strace?
I have two glitches caught there, between mid 18:12 and early 18:13. (Don't know where.)
The raw strace text file has 33 MBs..

Here's the file http://uloz.to/x5oawnSq/strace-lfs

$ grep -i error /tmp/strace_lfs
18:11:55.486829 write(17, "rs\r\n3a_carerror car error\r\n3a_ra"..., 1024) = 1024
18:11:56.098494 stat64("/home/mtoth/.wine/dosdevices/c:/LFS/data/sound/Error.wav", {st_mode=S_IFREG|0664, st_size=176328, ...}) = 0
18:11:56.130831 open("/usr/lib/pulseaudio/libgpg-error.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
18:11:56.130850 open("/lib/libgpg-error.so.0", O_RDONLY|O_CLOEXEC) = 21

Also, I am missing a file
18:13:15.425401 stat64(".wine/dosdevices/c:/LFS/data/pic/Skyovercast6_E.raw", 0x32f2ac) = -1 ENOENT (No such file or directory)
Since you're already at the level of using strace to debug the issue this might be a bit too high-level, but still ...

Did you try (re)nicing the wine/LFS process to a negative value? Perhaps you've got some other stuff going on that steals cpu time.


$ man nice

Quote from felplacerad :Since you're already at the level of using strace to debug the issue this might be a bit too high-level, but still ...

Did you try (re)nicing the wine/LFS process to a negative value? Perhaps you've got some other stuff going on that steals cpu time.


$ man nice


Tried nice-ing it by to -5, -10 and -15, but still lagging.. Frown
If you're feeling adventurous perhaps try adjusting the kernel timer frequency. But LFS allegedly runs at 2000 hz so I'm not really sure if that would help? Unfortunately I highly doubt you'd be able to do that in userland. Either boot options or recompilation of the kernel.

Quote from Scawen :That is the reason for LFS's high update rate of 2000 Hz in the sub-updates, which avoids the cars jumping up and down all on their own due to jumping wheels!

Edit: or 100 hz? Confused

Quote from Scawen : The LFS physics run at 100 Hz [...]

But obviously I'm basically rambling here. Perhaps MadCatX could shed some light on this.
Probably Scawen would be the most competent here.. Big grin
Thank you for now. Looking forward to more comments Smile
Tried to race with it, but it is pretty bad for racing. (what is the core of this game..)

When it happens and I am braking, it will remember the "actual state/values". Even after de-freeze state, it continues to apply that 'previous_actual_state' and does brake, even when I do not want to brake at all.. Smile

Unplayable, if it happens on too important places. Frown
Since a lot of users are successfully running LFS with wine I guess this is not a "generic" lfs+wine error. Perhaps if you, in addition to your hardware specifications above, provide some more detailed information about your rig it'd be easier for people to assist you:


$ cat /etc/*-release
$ uname -a
$ wine --version
$ glxinfo | grep -i "version" # Might not be relevant, but still ...

( ... And update post #1 ...)

PS: the re-calibration after "onBlur" occurs in Windows as well, IIRC.
-- updated comment #1 with the relevant information --
Analysis of the second strace file reveals four syscalls that take longer than 250 msecs. All of them happen around "poll([{fd=35, events=POLLIN}], 1, 0) = 0 (Timeout)". File descriptor 35 and 36 point to your "/dev/input/js0" device so there might be something going on when WINE tries to read the status of your controller, I assume it's a wheel?

It also seems that you have selected the wrong device in LFS configuration. WINE should pick your wheel up twice, once through the legacy joydev interface ("/dev/input/js0") and once through evdev ("/dev/input/eventXX"). You can try to select the other device and check if the problem goes away. Even better test would be to disconnect your wheel completely and try it without it.
#16 - w126
Here is a 0.3 s time difference from that last log:
Quote :22:21:15.675668 sched_yield() = 0
22:21:15.675693 gettimeofday({1432498875, 675702}, NULL) = 0
22:21:15.675719 select(0, NULL, NULL, NULL, {0, 4949}) = 0 (Timeout)
22:21:15.680780 clock_gettime(CLOCK_MONOTONIC_RAW, {417569, 108602728}) = 0
22:21:15.998481 futex(0x110070, FUTEX_WAIT_PRIVATE, 0, {5, 0}) = -1 EAGAIN (Resource temporarily unavailable)
22:21:15.998991 rt_sigprocmask(SIG_BLOCK, [HUP INT USR1 USR2 ALRM CHLD IO], [], 8) = 0

But this does not necessarily mean that clock_gettime system call takes that long. Could you add -T option to strace?
Quote : -T Show the time spent in system calls. This records
the time difference between the beginning and the
end of each system call.

The last log captured with the wheel disconnected doesn't seem to show any obvious pattern. It'd probably be a good idea to run some tests with games other than LFS. At least we need to figure out whether this problem is specific to LFS. Is there anything suspicious in your "dmesg" log?
So I have tested it yesterday at work place - everything work like it should, no glitches, no problems.
Came home, tried it again, same issues, glitch showed up every 30secs..
Today I have tried it again at work. No issues. (RBR can't start because of some direct3d issue.. maybe it's connected).

I have killed all the wine related processes and tried again at home. Now it's working properly. I have really no idea what could it be.
But few observations:
1) All wine* processes got killed (just today)
2) Haven't restarted PC for a long time. (Actually I am still up, for 11,5 days on laptop)
3) Tried it yesterday w/o internet, external monitor, wheel, did not work at home. Although, always worked at my work place.

Conclusion? No idea. My wild guess would be either some stuck process, or fedora has some hidden usage of my workplace Big grin (NTP, other net-service, who knows)

Thank you very much guys, for your cooperation and suggestions.
I really appreciate it.
Mich
Ok, so I am back with this issue. Came home today, started LFS, glitch is here. Rebooted PC, still doing the same thing.

dmesg shows no error. (only problem loading modules for not mine iwlwifi drivers and bluetooth (all in 50th second of boot).

I have tried RBR with the following wine output. Same issue happens as well. What is good for LFS. Bad for me and my wine.

fixme:winediag:start_process Wine Staging is a testing version containing experimental patches.
fixme:winediag:start_process Please report bugs at http://bugs.wine-staging.com (instead of winehq.org).
fixme:module:load_dll Loader redirect from L"wined3d.dll" to L"wined3d-csmt.dll"
fixme:ole:RemUnknown_QueryInterface No interface for iid {00000019-0000-0000-c000-000000000046}
err:winediag:wined3d_dll_init The GLSL shader backend has been disabled. You get to keep all the pieces if it breaks.
fixme:winediag:wined3d_dll_init Experimental wined3d CSMT feature is currently enabled.
err:quartz:GetClassMediaFile Media class not found
err:quartz:GetClassMediaFile Media class not found
fixme:d3d:swapchain_init The application requested more than one back buffer, this is not properly supported.
Please configure the application to use double buffering (1 back buffer) if possible.
fixme:dinput:IDirectInputDevice8AImpl_GetImageInfo (0x3990b98)->(0x33f5f4): stub !
fixme:dinput:IDirectInputDevice8AImpl_GetImageInfo (0x3990b98)->(0x33f5f4): stub !
fixme:dinput:IDirectInput8AImpl_EnumDevicesBySemantics (this=0x3985f80,(null),0x8951d8,0x4cb2c0,(nil),0000): semi-stub
fixme:dinput:SysKeyboardWImpl_BuildActionMap (0x39915a4)->(0x33f4c0,(null),00000004): semi-stub !
fixme:dinput:SysMouseWImpl_BuildActionMap (0x399393c)->(0x33f4c0,(null),00000004): semi-stub !
err:d3d:wined3d_format_convert_color_to_float Unhandled conversion from WINED3DFMT_DXT1 to floating point.
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:query_init Unhandled query type 0x4.
fixme:msvcp:_Locinfo__Locinfo_ctor_cat_cstr (0x33f1d4 1 C) semi-stub
fixme:msvcp:_Locinfo__Locinfo_ctor_cat_cstr (0x33f20c 1 C) semi-stub
fixme:msvcp:_Locinfo__Locinfo_ctor_cat_cstr (0x33f278 1 C) semi-stub
fixme:msvcp:_Locinfo__Locinfo_ctor_cat_cstr (0x33f0a8 1 C) semi-stub
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
fixme:d3d:buffer_internal_preload Too many declaration changes or converting dynamic buffer, stopping converting
Init View 3D, OncePerFramePostTickerTic
TAG=49474e45
Version=101
Num diffrent rpms=6
Num diffrent load/rpm samples=2
0 0 1 100
Num diffrent load/rpm samples=2
0 0 1 100
Num diffrent load/rpm samples=2
0 0 1 100
Num diffrent load/rpm samples=2
0 0 1 100
Num diffrent load/rpm samples=2
0 0 1 100
Num diffrent load/rpm samples=2
0 0 1 100
Init View 3D, OncePerFramePostTickerTic

I am not able to provide strace, because it starts normally, when as soon as "fixme:dsound:IDirectSoundBufferImpl_Restore (0x883ebc8):stub" shows up, whole strace output is overridden by these fixme messages.

So I am back stuck and looking for a help. The issue is definitely in wine.

$ wine --version
wine-1.7.43 (Staging)

$ rpm -qa |grep wine | sort
mingw32-wine-gecko-2.36-1.fc21.noarch
mingw64-wine-gecko-2.36-1.fc21.noarch
wine-1.7.43-1.fc21.x86_64
wine-alsa-1.7.43-1.fc21.x86_64
wine-arial-fonts-1.7.43-1.fc21.noarch
wine-capi-1.7.43-1.fc21.i686
wine-capi-1.7.43-1.fc21.x86_64
wine-cms-1.7.43-1.fc21.i686
wine-cms-1.7.43-1.fc21.x86_64
wine-common-1.7.43-1.fc21.noarch
wine-core-1.7.43-1.fc21.i686
wine-core-1.7.43-1.fc21.x86_64
wine-courier-fonts-1.7.43-1.fc21.noarch
wine-desktop-1.7.43-1.fc21.noarch
wine-filesystem-1.7.43-1.fc21.noarch
wine-fixedsys-fonts-1.7.43-1.fc21.noarch
wine-fonts-1.7.43-1.fc21.noarch
wine-ldap-1.7.43-1.fc21.i686
wine-ldap-1.7.43-1.fc21.x86_64
wine-marlett-fonts-1.7.43-1.fc21.noarch
wine-mono-4.5.6-1.fc21.noarch
wine-ms-sans-serif-fonts-1.7.43-1.fc21.noarch
wine-openal-1.7.43-1.fc21.i686
wine-openal-1.7.43-1.fc21.x86_64
wine-opencl-1.7.43-1.fc21.i686
wine-opencl-1.7.43-1.fc21.x86_64
wine-pulseaudio-1.7.43-1.fc21.i686
wine-pulseaudio-1.7.43-1.fc21.x86_64
wine-small-fonts-1.7.43-1.fc21.noarch
wine-symbol-fonts-1.7.43-1.fc21.noarch
wine-systemd-1.7.43-1.fc21.noarch
wine-system-fonts-1.7.43-1.fc21.noarch
wine-tahoma-fonts-1.7.43-1.fc21.noarch
wine-twain-1.7.43-1.fc21.i686
wine-twain-1.7.43-1.fc21.x86_64
wine-wingdings-fonts-1.7.43-1.fc21.noarch

Any suggestions please?
Thank you
Intriguing problem.
If I'm reading it right, you still had the problem with the wheel disconnected, yeah?

It's great that you've ruled out LFS as the origin of the problem (by finding another app with the same problem). However, maybe I missed it, but I'm not seeing any reason why you're confident the problem is within Wine. Why could it not be at the Linux level? E.g. rogue process (either CPU activity or more likely IO).
It's been a (very!) long time since I hacked the Linux kernel, but one stupidly basic test I used to perform to debug scheduler issues was to simply hold down the space bar in a shell window, and watch the cursor, looking out for jerky movement happening from time to time.
The WINE log suggests that you have the CSMT Direct3D offloading enabled. Does the problem go away then you switch it off?

Linux: Every 30 seconds glitch/lag - screen freeze for about third of a second
(21 posts, started )
FGED GREDG RDFGDR GSFDG