https://bugs.winehq.org/show_bug.cgi?id=43728
Bug ID: 43728 Summary: Magic: The Gathering Online intensive CPU usage when idle Product: Wine Version: 2.17 Hardware: x86 OS: Linux Status: UNCONFIRMED Severity: normal Priority: P2 Component: -unknown Assignee: wine-bugs@winehq.org Reporter: theli.ua@gmail.com Distribution: ---
160-200% compared to <10% on windows to reproduce launch app, login, go to account or collections tab (happens once at least 1 card has been rendered)
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #1 from Anton Romanov theli.ua@gmail.com --- Created attachment 59201 --> https://bugs.winehq.org/attachment.cgi?id=59201 sysprof
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #2 from Anton Romanov theli.ua@gmail.com --- this is coupled with high cpu usage on wineserver
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #3 from Anton Romanov theli.ua@gmail.com --- Created attachment 59202 --> https://bugs.winehq.org/attachment.cgi?id=59202 exception
not sure how related but its handling this exception over and over and over and over
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #4 from Anton Romanov theli.ua@gmail.com --- Created attachment 59203 --> https://bugs.winehq.org/attachment.cgi?id=59203 few last lines of +relay when app was consuming lots of CPU before being killed
https://bugs.winehq.org/show_bug.cgi?id=43728
Panard panard@inzenet.org changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |panard@inzenet.org
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #5 from Anton Romanov theli.ua@gmail.com --- I feel like it just gets too many messages that force it to constantly redraw when it doesn't need/have/should to. In the hottest path there are a lot of calls to dwrite/wic even if the window is static
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #6 from Anton Romanov theli.ua@gmail.com --- I'm willing to do testing/debugging if someone have any ideas as to how to approach this
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #7 from Anton Romanov theli.ua@gmail.com --- just for the record - setting STAGING_SHARED_MEMORY 1 env var doesn't help Playing in emulated desktop doesn't help either
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #8 from Anton Romanov theli.ua@gmail.com --- sysprof seems to be pointing to CoWaitForMultipleHandles and subsequently WaitForMultipleObjectsX and PeekMessageW and server calls
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #9 from Panard panard@inzenet.org --- Created attachment 60141 --> https://bugs.winehq.org/attachment.cgi?id=60141 output with WINEDEBUG=+relay with docker image on 2018-01-05
I tried to do some investigation as well, following from your logs. I'm using wine staging 2.20, within the docker image panard/mtgo:2017-11-07 on an up-to-date gentoo (intel graphics card)
First, WINEDEBUG=+relay (output attached) does not give the same output as you, notably I don't seen any recurring exceptions. However, I do see a lot of MsgWaitForMultipleObjectsEx calls. The output is after clicking on the "Collection" tab and waiting for some time.
Counting the identical calls gives the following top scorers: $ sort relay.log |uniq -c|sort -n|tail -n 20 222 0119:Ret user32.PeekMessageW() retval=00000000 ret=7e9be214 443 0119:Call ntdll.NtQueryPerformanceCounter(68eed860,68eed868) ret=7b447412 443 0119:Call ntdll.RtlAllocateHeap(00110000,00000000,00000100) ret=7ed0a37c 443 0119:Call ntdll.RtlFreeHeap(00110000,00000000,0da60be0) ret=7ed0a4ca 443 0119:Call ntdll.RtlIsCriticalSectionLockedByThread(7ee4f3e0) ret=7ed3039e 443 0119:Ret ntdll.RtlAllocateHeap() retval=0da60be0 ret=7ed0a37c 443 0119:Ret ntdll.RtlFreeHeap() retval=00000001 ret=7ed0a4ca 443 0119:Ret ntdll.RtlIsCriticalSectionLockedByThread() retval=00000000 ret=7ed3039e 444 0119:Call ntdll.NtYieldExecution() ret=7ed41e18 444 0119:Call winex11.drv.MsgWaitForMultipleObjectsEx(00000000,00000000,00000000,000004ff,00000000) ret=7ed41dce 444 0119:Ret ntdll.NtYieldExecution() retval=00000000 ret=7ed41e18 444 0119:Ret winex11.drv.MsgWaitForMultipleObjectsEx() retval=00000102 ret=7ed41dce 664 0119:Call KERNEL32.GetTickCount() ret=7ed31ae8 664 0119:Call ntdll.RtlEnterCriticalSection(7ee4f460) ret=7ed31ae0 664 0119:Ret ntdll.RtlEnterCriticalSection() retval=00000000 ret=7ed31ae0 665 0119:Call KERNEL32.TlsGetValue(00000006) ret=7e87a62d 665 0119:Call ntdll.RtlLeaveCriticalSection(7ee4f460) ret=7ed31b2f 665 0119:Ret KERNEL32.TlsGetValue() retval=0c74aac8 ret=7e87a62d 665 0119:Ret ntdll.RtlLeaveCriticalSection() retval=00000000 ret=7ed31b2f 886 0119:Ret ntdll.NtQueryPerformanceCounter() retval=00000000 ret=7b447412
The number of calls is within a very short period of time: I let the output flowed only for a couple of seconds and ended up with a 300Mb file, here the file is just 1MB.
The call winex11.drv.MsgWaitForMultipleObjectsEx(00000000,00000000,00000000,000004ff,00000000) might be a bit suspcious. http://winapi.freetechsecrets.com/win32/WIN32MsgWaitForMultipleObjectsEx_New... According to wine sources, the flag 4ff means QS_ALLINPUT.
Grep-ing in wine sources, I found the following caller candidates:
- dlls/dinput/dinput_main.c/check_dinput_events => the documentation made me raise an eyebrow: "Windows does not do that, but our current implementation of winex11 requires periodic event polling to forward events to the wineserver" ; maybe we should try by de-activating this function and see what happen? - dlls/user32/message.c/check_for_driver_events => triggered only if get_user_thread_info()->message_count > 200, which according to the docs means a lot of messages are in queue, which is a bit unlikely here (the MTGO window was not displayed) - dlls/user32/input.c/check_for_events with flags = QS_ALLINPUT => then greping for check_for_events only lead to call with QS_INPUT, therefore, this is a false positive.
I can give a try to disabling check_dinput_events, to see if it makes any difference, although I'm not sure if it is relevant at all...
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #10 from Panard panard@inzenet.org --- After a bit more source code reading, MsgWaitForMultipleObjectsEx calls are due to dlls/user32/message.c/check_for_driver_events, which are due to PeekMessageW calls (it calls it twice, which is coherent with the counts from the log file).
Maybe there is something around the count_message which is never reset, and hence calls MsgWaitForMultipleObjectsEx each time check_for_driver_evens is called, but it is quite likely to be a symptom and not the cause of the PeekMessageW calls.
But I have a hard time to find what causes these PeekMessageW calls.. probably need to learn how to use winedbg..
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #11 from Panard panard@inzenet.org --- So here is what is happening:
1. Call to CoWaitForMultipleHandles (ole32/compobj.c) 2. Enters while(TRUE) section with message_loop = TRUE 3. Call MsgWaitForMultipleObjectsEx (line 4513 of vanilla git) 4. Returns WAIT_OBJECT_0 + cHandles, enters the if section (line 4517) 5. COM_CurrentApt()->filter is false 6. Call to COM_PeekMessage 7. Call to PeekMessageW twice, both returns 0 8. Therefore the continue instruction restarts the loop, and we go back to 3.
Using WINEDEBUG=ole, we can see some CoWaitForMultipleHandles call terminate, but I suspect there could be parallel ones to an infinite one.. but what we can also see is an infinite flood of trace:ole:CoWaitForMultipleHandles waiting for rpc completion or window message
We would need an expert of the ole32 dll to help here..
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #12 from Anton Romanov theli.ua@gmail.com --- (In reply to Panard from comment #11)
So here is what is happening:
- Call to CoWaitForMultipleHandles (ole32/compobj.c)
- Enters while(TRUE) section with message_loop = TRUE
- Call MsgWaitForMultipleObjectsEx (line 4513 of vanilla git)
- Returns WAIT_OBJECT_0 + cHandles, enters the if section (line 4517)
- COM_CurrentApt()->filter is false
- Call to COM_PeekMessage
- Call to PeekMessageW twice, both returns 0
- Therefore the continue instruction restarts the loop, and we go back to 3.
Using WINEDEBUG=ole, we can see some CoWaitForMultipleHandles call terminate, but I suspect there could be parallel ones to an infinite one.. but what we can also see is an infinite flood of trace:ole:CoWaitForMultipleHandles waiting for rpc completion or window message
We would need an expert of the ole32 dll to help here..
Where is CoWaitForMultipleHandles even called from? Its not in your log extract
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #13 from Panard panard@inzenet.org --- Created attachment 60151 --> https://bugs.winehq.org/attachment.cgi?id=60151 output with WINEDEBUG=+ole
Here is the complete output with WINEDEBUG=+ole showing the CoWaitForMultipleHandles calls. However, I cannot find who is calling it, I found no matching call in the wine source code.. (parameters/logs do not match). Could it be called directly by MTGO?? But it is clearly where things go wrong - once on collection tab, we get flooded with "waiting for rpc completion or window message".
To complete the story of CoWaitForMultipleHandles, after adding additional TRACE, what seems to happen is the following: - when CoWaitForMultipleHandles calls MsgWaitForMultipleObjectsEx (dlls/ole32/compobj.c:4513), this latter returns that 1 message is waiting - but, when calling PeekMessageW, no message is found: the peek_message routine fails due to a STATUS_PENDING returned by wineserver request... (and then it tries again).
Let me know if you are interested in the patch to enable the additional TRACE and the corresponding output mixing ole and msg.
Any idea how to go further?
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #14 from Anton Romanov theli.ua@gmail.com --- (In reply to Panard from comment #13)
However, I cannot find who is calling it, I found no matching call in the wine source code.. (parameters/logs do not match). Could it be called directly by MTGO??
It is most likely called by CLR
Also see related https://blogs.msdn.microsoft.com/cbrumme/2003/04/17/managed-blocking/ https://blogs.msdn.microsoft.com/timng/2006/09/07/com-re-entrancy-and-messag...
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #15 from Anton Romanov theli.ua@gmail.com --- @Panard nice deep dive, thanks.
With that info, its obvious that it enters infinite loop because of that message that is there which does not match w/e is in that Com_PeekMessage branch and it doesn't have filter, so.
With the following change it now idles at collection window for me at less than 1% of cpu (as opposed to 300% as it was before change).
This is what it spits out: err:ole:CoWaitForMultipleHandles received message whilst waiting for RPC: 0xc065 err:ole:CoWaitForMultipleHandles received message whilst waiting for RPC: 0xc065
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #16 from Anton Romanov theli.ua@gmail.com --- Created attachment 60157 --> https://bugs.winehq.org/attachment.cgi?id=60157 naive hack patch
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #17 from Panard panard@inzenet.org --- Wow, awesome!! Same effect here, MTGO goes at 1% CPU :-)) I'll do a bit more testing (i.e., some matches) and integrate it in the main docker image.
That would be interesting to know what this message 0xc065 is, a quick grep into header files gives nothing..
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #18 from Nikolay Sivov bunglehead@gmail.com --- (In reply to Panard from comment #17)
That would be interesting to know what this message 0xc065 is, a quick grep into header files gives nothing..
That could be a result of RegisterWindowMessage() too.
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #19 from Anton Romanov theli.ua@gmail.com --- (In reply to Nikolay Sivov from comment #18)
(In reply to Panard from comment #17)
That would be interesting to know what this message 0xc065 is, a quick grep into header files gives nothing..
That could be a result of RegisterWindowMessage() too.
Yeah
err:msg:RegisterWindowMessageW L"MilChannelNotify" ret=c065
err:ole:CoWaitForMultipleHandles received message whilst waiting for RPC: 0xc065
https://bugs.winehq.org/show_bug.cgi?id=43728
Robert Walker bob.mt.wya@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |bob.mt.wya@gmail.com
https://bugs.winehq.org/show_bug.cgi?id=43728
--- Comment #20 from Anton Romanov theli.ua@gmail.com --- Created attachment 60208 --> https://bugs.winehq.org/attachment.cgi?id=60208 test patch
So I was trying to come up with the patch that would show this behaviour. As seen windows doesn't pump messages either, however it does PEEK at messages so that they will not trigger MsgWaitForMultipleObjects again, if our CoWaitForMultipleHandles would also do that then it will not be an issue as CoWaitForMultipleHandles will not look at those messages in the queue again.
This change to test makes test fail on wine but it succeeds on windows.
https://bugs.winehq.org/show_bug.cgi?id=43728
Anton Romanov theli.ua@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Attachment #60157|0 |1 is obsolete| |
--- Comment #21 from Anton Romanov theli.ua@gmail.com --- Created attachment 60209 --> https://bugs.winehq.org/attachment.cgi?id=60209 fix v2
Proposed fix
Will try to submit along with test once I clean it up in a day or two.
https://bugs.winehq.org/show_bug.cgi?id=43728
Nikolay Sivov bunglehead@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Component|-unknown |ole32
https://bugs.winehq.org/show_bug.cgi?id=43728
Anton Romanov theli.ua@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Resolution|--- |FIXED Status|UNCONFIRMED |RESOLVED
--- Comment #22 from Anton Romanov theli.ua@gmail.com --- fixed by https://source.winehq.org/git/wine.git/commit/90a094cc24a900687347af8f490c46...
https://bugs.winehq.org/show_bug.cgi?id=43728
Nikolay Sivov bunglehead@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Fixed by SHA1| |90a094cc24a900687347af8f490 | |c46617f9782df
https://bugs.winehq.org/show_bug.cgi?id=43728
Alexandre Julliard julliard@winehq.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED
--- Comment #23 from Alexandre Julliard julliard@winehq.org --- Closing bugs fixed in 3.1.
https://bugs.winehq.org/show_bug.cgi?id=43728
Michael Stefaniuc mstefani@winehq.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Target Milestone|--- |3.0.x
https://bugs.winehq.org/show_bug.cgi?id=43728
Michael Stefaniuc mstefani@winehq.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Target Milestone|3.0.x |---
--- Comment #24 from Michael Stefaniuc mstefani@winehq.org --- Removing the 3.0.x milestone from bugs included in 3.0.1.
-
wine-bugs＠winehq.org