https://bugs.winehq.org/show_bug.cgi?id=45121
Bug ID: 45121 Summary: Steam uses high CPU while idle Product: Wine Version: 3.6 Hardware: x86 OS: Linux Status: UNCONFIRMED Severity: normal Priority: P2 Component: -unknown Assignee: wine-bugs@winehq.org Reporter: myjunkmail311006@gmail.com Distribution: ---
Reported to Steam Support:
Recent Steam versions are using high CPU. This is with CPU frequencies at minimum, which is necessary to prevent my computer from overheating. At maximum frequency, Steam CPU usage is around 15% (and wineserver 11%).
No games are open, and the main Window has been closed. No network activity, and no activity on the console with Steam invoked on the command line (bash).
Idle activity for Steam used to be around 5% for me. [...]
A support person replied with this:
As for the CPU performance issues, I've tested it on a few Windows devices and one Linux computer running Ubuntu (note I didn't test on WINE) and have been unable to reproduce the error you're seeing (all CPU usage for Steam was <1% when idle). I can only guess that this CPU performance issue is either related to WINE or a program which may be interfering with Steam.
I hope to get confirmation from other people whether this is, in fact, a bug with Wine or just a problem with my particular setup. I'm using Ubuntu 18.04, and this occurs with Wine 3.6 and 3.0 with the newest Steam.exe client, with both an old 32-bit prefix and a new 64-bit prefix.
https://bugs.winehq.org/show_bug.cgi?id=45121
Misaki myjunkmail311006@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Distribution|--- |Ubuntu Hardware|x86 |x86-64
https://bugs.winehq.org/show_bug.cgi?id=45121
tokktokk fdsfgs@krutt.org changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |fdsfgs@krutt.org
https://bugs.winehq.org/show_bug.cgi?id=45121
Vincent Povirk madewokherd@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |madewokherd@gmail.com
https://bugs.winehq.org/show_bug.cgi?id=45121
alasky@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |alasky@codeweavers.com
https://bugs.winehq.org/show_bug.cgi?id=45121
Michael McGuire spoon0042@hotmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |spoon0042@hotmail.com
--- Comment #1 from Michael McGuire spoon0042@hotmail.com --- Yeah. I've been getting this for at least a month now. steam + wineserver doing (apparently) nothing are using about half a core. Out of two. Yay.
I've been putting off doing anything about it though, mostly because my initial searching didn't turn up anything useful other than "steam does that sometimes". I *think* this is new/different, but who knows. Maybe in another month I'll get to asking on the forums about attempting to debug this.
So another data point anyway. Using a new 64-bit wineprefix on 3.7 staging just now for this report. Debian 9.
https://bugs.winehq.org/show_bug.cgi?id=45121
Pavel Ondračka pavel.ondracka@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |pavel.ondracka@gmail.com
https://bugs.winehq.org/show_bug.cgi?id=45121
sworddragon2@aol.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |sworddragon2@aol.com
--- Comment #2 from sworddragon2@aol.com --- I'm seeing this too with Wine 3.11. Steam uses around 25%-30%/600% of CPU time and the wineserver64 uses around 15%-20%/600% of CPU time even when Steam is only active in the tray. A search on the web pointed me out to Steam issues in the past that 25%-30% CPU usage of Steam sometimes randomly just happens and might just be an (eventually still) unresolved bug of Steam. Reinstalling Steam and even creating a new Steam profile did not solve this issue and with seeing other Wine users having this recently as well I guess this specific case is probably a Wine issue.
https://bugs.winehq.org/show_bug.cgi?id=45121
Filip Volejnik f.volejnik@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |f.volejnik@gmail.com
--- Comment #3 from Filip Volejnik f.volejnik@gmail.com --- I have been getting this bug for about a year or even longer. My preferred solution was to kill the client and try again, but recently I have had very little luck restarting Steam without it taking about 1.5 cores, again (2x70% by two processes).
What seems to work well is putting steam into offline mode - suggesting this is network usage related issue. Sometimes clearing download cache also helps.
My CPU is Ryzen 2700x, but it also happened with i5 2500k. Both of the times I used virtual desktop (I don't know if this changes anything). My distro is Arch.
This bug has been happening since wine 2.x at least, maybe even before.
https://bugs.winehq.org/show_bug.cgi?id=45121
--- Comment #4 from Filip Volejnik f.volejnik@gmail.com --- Created attachment 61834 --> https://bugs.winehq.org/attachment.cgi?id=61834 Patch for ptid mapping (by zfigura)
Coming from esync/dxvk discord, steam seems to search for it's other process (with open_process calls) with ptid decreasing by 4, in a loop, in some cases. This causes the high idle CPU usage. Zfigura authored this as a test to see if it helps - and it does, for us who tested it there. I'm not sure if this is upstreamable, but it's worth as a source of info, at least.
Sample of the problematic behavior (taken with WINEDBG=+server): 0034: open_process( pid=0033, access=00000400, attributes=00000000 ) 0034: open_process() = 0 { handle=0128 } 0034: open_process( pid=0033, access=00000040, attributes=00000002 ) 0034: open_process() = 0 { handle=01b0 } 003e: open_process( pid=0033, access=00000040, attributes=00000002 ) 003e: open_process() = 0 { handle=01b0 } 0034: open_process( pid=0033, access=00000400, attributes=00000000 ) 0034: open_process() = 0 { handle=01a8 } 0040: open_process( pid=0033, access=00000400, attributes=00000000 ) 0040: open_process() = 0 { handle=0248 } 0040: open_process( pid=000e, access=00000410, attributes=00000000 ) 0040: open_process() = 0 { handle=034c } 0040: open_process( pid=0010, access=00000410, attributes=00000000 ) 0040: open_process() = 0 { handle=034c } 0040: open_process( pid=0013, access=00000410, attributes=00000000 ) 0040: open_process() = 0 { handle=034c } 0040: open_process( pid=001e, access=00000410, attributes=00000000 ) 0040: open_process() = 0 { handle=034c } 0040: open_process( pid=0023, access=00000410, attributes=00000000 ) 0040: open_process() = 0 { handle=034c } 0040: open_process( pid=0033, access=00000410, attributes=00000000 ) 0040: open_process() = 0 { handle=034c } 0040: open_process( pid=0033, access=00000040, attributes=00000002 ) 0040: open_process() = 0 { handle=039c } 003e: open_process( pid=0033, access=00000040, attributes=00000002 ) 003e: open_process() = 0 { handle=039c } 005c: open_process( pid=0033, access=00001000, attributes=00000000 ) 005c: open_process() = 0 { handle=0388 } ....
This goes on forever
https://bugs.winehq.org/show_bug.cgi?id=45121
--- Comment #5 from Filip Volejnik f.volejnik@gmail.com --- I've pasted a piece of the log that does not show the decreasing behavior, fixing:
005c: open_process( pid=002f, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=002b, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=0027, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=0023, access=00001000, attributes=00000000 ) 005c: open_process() = 0 { handle=0388 } 005c: open_process( pid=001f, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=001b, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=0017, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=0013, access=00001000, attributes=00000000 ) 005c: open_process() = 0 { handle=0388 } 005c: open_process( pid=000f, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=000b, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=0007, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=0003, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=ffffffff, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=fffffffb, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=fffffff7, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=fffffff3, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 } 005c: open_process( pid=ffffffef, access=00001000, attributes=00000000 ) 005c: open_process() = INVALID_PARAMETER { handle=0000 }
https://bugs.winehq.org/show_bug.cgi?id=45121
Zebediah Figura z.figura12@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |z.figura12@gmail.com Keywords| |patch
--- Comment #6 from Zebediah Figura z.figura12@gmail.com --- Ah, I hadn't noticed this bug, thanks.
What bothers me is that not everyone can reproduce this. I'd expect perhaps this bug to be variable based on how process IDs get assigned, but if I take a +server log and examine it on my machine, I don't see any open_process calls at all.
In any event however this would probably be better reported to Steam itself. That PIDs are a multiple of four is an implementation detail, not guaranteed by the Windows API.
https://bugs.winehq.org/show_bug.cgi?id=45121
David Girón duhowpi@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |duhowpi@gmail.com
--- Comment #7 from David Girón duhowpi@gmail.com --- It also happens to me, when running Warframe from Steam library (Lutris) and closing the game.
https://bugs.winehq.org/show_bug.cgi?id=45121
TheLinuxGamer eimantopastas@hotmail.lt changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |eimantopastas@hotmail.lt
--- Comment #8 from TheLinuxGamer eimantopastas@hotmail.lt --- I can confirm also having this issue of high CPU usage for almost a year. for me it is usual for Steam + wineserver to use 60% CPU while idle. it seems like setting Steam to offline mode sometimes fixes it,however multiplayer games tend to not work in offline mode.
I personally can recommend to try freezing Steam with lxtask after launching games to avoid significant fps drop ,however freezing Steam sometimes as well freezes games.
https://bugs.winehq.org/show_bug.cgi?id=45121
andy andy86@fastwebnet.it changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |andy86@fastwebnet.it
--- Comment #9 from andy andy86@fastwebnet.it --- Hi. The bug is also present for me in wine 5.19, with and without dxvk enabled.
Only workaround working for me is disable "it's other process" through winecfg, basically in library override insert "steamwebhelper.exe" and set to disable, so Steam can't launch them and them can't overload cpu.
I don't know if this means losing network functionality, but the single player experience has definitely improved.
https://bugs.winehq.org/show_bug.cgi?id=45121
winetest@luukku.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |winetest@luukku.com
--- Comment #10 from winetest@luukku.com --- maybe duplicate of bug 41304.
https://bugs.winehq.org/show_bug.cgi?id=45121
--- Comment #11 from andy andy86@fastwebnet.it --- I think it's not a duplicate.
In bug 41304 was the process of the game to be using 100% of the cpu, in this bug is steamwebserver.exe and wineserver.exe to be using about 50%-60% of the cpu both summed.
https://bugs.winehq.org/show_bug.cgi?id=45121
Etienne Dechamps etienne@edechamps.fr changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |etienne@edechamps.fr
--- Comment #12 from Etienne Dechamps etienne@edechamps.fr --- Created attachment 68634 --> https://bugs.winehq.org/attachment.cgi?id=68634 Etienne Dechamps WINEDEBUG=+server log with wine cf49617c1a3
I am facing a similar problem with wine 5.0 as well as latest wine master (cf49617c1a3). The symptoms are similar (about 15% CPU usage from steam.exe and 10% from wineserver while Steam is idle - steamwebhelper.exe is fine, however). My WINEDEBUG=+server log looks very different from what Filip Volejnik previously reported. (Full log is attached.)
Basically, while the problem is occurring, my wineserver debug log shows the following pattern repeating ad infinitum:
0024: get_thread_input( tid=0000 ) 0024: get_thread_input() = 0 { focus=00010162, capture=00000000, active=00010162, foreground=00010162, menu_owner=00000000, move_size=00000000, caret=00000000, cursor=00000000, show_count=0, rect={0,0;0,0} } 0024: get_window_parents( handle=00010162 ) 0024: get_window_parents() = 0 { count=3, parents={0001016e,000300ba,00010020} } 0024: get_window_info( handle=000300ba ) 0024: get_window_info() = 0 { full_handle=000300ba, last_active=000300ba, pid=0068, tid=006c, atom=c068, is_unicode=1, dpi=96, awareness=2 } 0024: get_message( flags=04ff0001, get_win=00000000, get_first=00000000, get_last=ffffffff, hw_id=00000000, wake_mask=00000040, changed_mask=000004ff ) 0024: get_message() = PENDING { win=00000000, msg=00000000, wparam=00000000, lparam=00000000, type=0, x=0, y=0, time=00000000, active_hooks=80000000, total=0, data={} } 0024: select( flags=2, cookie=0031d76c, timeout=infinite, size=8, prev_apc=0000, result={}, data={WAIT,handles={0074}}, context={} ) 0024: select() = PENDING { call={APC_NONE}, apc_handle=0000, context={} } 0024: *wakeup* signaled=0 0024: get_message( flags=04ff0001, get_win=00000000, get_first=00000000, get_last=ffffffff, hw_id=00000000, wake_mask=00000040, changed_mask=000004ff ) 0024: get_message() = 0 { win=000100f8, msg=00000113, wparam=49554759, lparam=00000000, type=6, x=0, y=0, time=493ba0b4, active_hooks=80000000, total=0, data={} } 0024: get_message( flags=00000000, get_win=00000000, get_first=00000000, get_last=ffffffff, hw_id=00000000, wake_mask=00000000, changed_mask=00000000 ) 0024: get_message() = PENDING { win=00000000, msg=00000000, wparam=00000000, lparam=00000000, type=0, x=0, y=0, time=00000000, active_hooks=80000000, total=0, data={} } 0024: get_thread_input( tid=0000 ) 0024: get_thread_input() = 0 { focus=00010162, capture=00000000, active=00010162, foreground=00010162, menu_owner=00000000, move_size=00000000, caret=00000000, cursor=00000000, show_count=0, rect={0,0;0,0} } 0024: get_window_parents( handle=00010162 ) 0024: get_window_parents() = 0 { count=3, parents={0001016e,000300ba,00010020} } 0024: get_window_info( handle=000300ba ) 0024: get_window_info() = 0 { full_handle=000300ba, last_active=000300ba, pid=0068, tid=006c, atom=c068, is_unicode=1, dpi=96, awareness=2 } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1218890), total=0, namelen=10, name=L"", class=L"" } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1219090), total=0, namelen=10, name=L"", class=L"" } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1219220), total=0, namelen=10, name=L"", class=L"" } 0024: select( flags=3, cookie=0031dbec, timeout=0, size=0, prev_apc=0000, result={}, data={}, context={} ) 0024: select() = TIMEOUT { call={APC_NONE}, apc_handle=0000, context={} } 0024: select( flags=2, cookie=0031d05c, timeout=0, size=8, prev_apc=0000, result={}, data={WAIT,handles={009c}}, context={} ) 0024: select() = TIMEOUT { call={APC_NONE}, apc_handle=0000, context={} } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1220900), total=0, namelen=10, name=L"", class=L"" } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1221100), total=0, namelen=10, name=L"", class=L"" } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1221260), total=0, namelen=10, name=L"", class=L"" } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1221410), total=0, namelen=10, name=L"", class=L"" } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1221520), total=0, namelen=10, name=L"", class=L"" } 0024: enum_key( hkey=007c, index=-1, info_class=2 ) 0024: enum_key() = 0 { subkeys=0, max_subkey=0, max_class=0, values=1, max_value=28, max_data=202, modif=1d6bb6b490958ba (-79.1221640), total=0, namelen=10, name=L"", class=L"" }
This pattern repeats about ~1100 times per second(!). Looks like something is caught in some kind of busy loop.
I was curious what is being read in the registry. I traced hkey=007c back to:
0024: open_key( parent=0018, access=02000000, attributes=00000000, name=L"HARDWARE\DEVICEMAP\VIDEO" ) 0024: open_key() = 0 { hkey=007c }
Mmm. Maybe Steam doesn't like what Wine presents in HKEY_LOCAL_MACHINE\Hardware\DEVICEMAP\VIDEO or something.
https://bugs.winehq.org/show_bug.cgi?id=45121
--- Comment #13 from Etienne Dechamps etienne@edechamps.fr --- Created attachment 68635 --> https://bugs.winehq.org/attachment.cgi?id=68635 Single log period with WINEDEBUG=+x11drv,+server,+relay (wine cf49617c1a3)
Attached another log that focuses on the repeating period, with +relay this time. One can observe calls to user32.MonitorFromPoint(), user32.GetMonitorInfoW(), user32.GetForegroundWindow(), user32.ShowWindow(). This looks like Steam is busy-looping in a code path related to window management and monitors.
https://bugs.winehq.org/show_bug.cgi?id=45121
--- Comment #14 from Etienne Dechamps etienne@edechamps.fr --- Out of curiosity I ran Steam under an API tracer on a Windows 10 machine and, to my surprise, I saw the exact same thing as I saw in the wine relay logs. It's doing the same busy loop even under native Windows. So the busy loop itself is *not* the consequence of a Wine bug.
This is starting to look like poor design on Steam's side. That being said, on native Windows the CPU usage from that thread is much lower. What I suspect is happening is: the calls in question might be cheaper on Windows than on Wine; and/or Windows might make the thread sleep for longer during the Sleep(0) calls that Steam makes on each iteration.
I used the Windows Performance Toolkit on the Windows machine to investigate further. On native Windows, the thread in question iterates at roughly the same rate (~1000 times per second) than on my Wine setup, but each iteration is very quick - about 42 µs on average. This leads to about 4% utilization of a single CPU. The Windows Task Manager will show an even smaller number because, contrary to "top", it divides CPU usage by the number of CPUs, which might contribute to the perception that the CPU usage is lower than on Wine.
I haven't checked how long the iteration takes on my Wine setup, but judging from the CPU usage numbers I'd estimate it's at least 4 times slower. The Win32 functions being called have likely been optimized to death on native Windows, but on Wine they have to go through several round trips to the wineserver, which involves context switches etc.
As for fixing this problem, I can see a few possible avenues at this point: - Ask Valve to fix their poorly designed busy loop. (Good luck.) - Optimize the Wine implementation of the offending Win32 calls. (I don't know, caching maybe?) - Implement some kind of clever Steam-specific workaround where Wine detects that it's being called from that loop and deliberately throttles it (e.g. by changing the Sleep(0) call to Sleep(10ms), which would reduce CPU usage by a factor of ~10).
https://bugs.winehq.org/show_bug.cgi?id=45121
winetaste@gmx.net changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |winetaste@gmx.net
https://bugs.winehq.org/show_bug.cgi?id=45121
Fabian Maurer dark.shadow4@web.de changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |dark.shadow4@web.de
--- Comment #15 from Fabian Maurer dark.shadow4@web.de --- Is this still an issue? For me steam is at <1% usage and wineserver at 0%.
https://bugs.winehq.org/show_bug.cgi?id=45121
--- Comment #16 from Zebediah Figura z.figura12@gmail.com --- The relevant bug would have been fixed by https://source.winehq.org/git/wine.git/commitdiff/daa120309e1f674a251497ff6a014168d339c90c.
https://bugs.winehq.org/show_bug.cgi?id=45121
--- Comment #17 from Fabian Maurer dark.shadow4@web.de --- So, can we close this?
https://bugs.winehq.org/show_bug.cgi?id=45121
Zebediah Figura z.figura12@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|UNCONFIRMED |RESOLVED Fixed by SHA1| |daa120309e1f674a251497ff6a0 | |14168d339c90c Resolution|--- |FIXED
--- Comment #18 from Zebediah Figura z.figura12@gmail.com --- (In reply to Fabian Maurer from comment #17)
So, can we close this?
It would be nice if someone who can reproduce the bug can confirm it's gone, but it's probably not worth waiting around for that.
https://bugs.winehq.org/show_bug.cgi?id=45121
Alexandre Julliard julliard@winehq.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED
--- Comment #19 from Alexandre Julliard julliard@winehq.org --- Closing bugs fixed in 7.0-rc6.