[Bug 43728] New: Magic: The Gathering Online intensive CPU usage when idle
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(a)winehq.org Reporter: theli.ua(a)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) -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #1 from Anton Romanov <theli.ua(a)gmail.com> --- Created attachment 59201 --> https://bugs.winehq.org/attachment.cgi?id=59201 sysprof -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #2 from Anton Romanov <theli.ua(a)gmail.com> --- this is coupled with high cpu usage on wineserver -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #3 from Anton Romanov <theli.ua(a)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 -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #4 from Anton Romanov <theli.ua(a)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 -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Panard <panard(a)inzenet.org> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |panard(a)inzenet.org -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #5 from Anton Romanov <theli.ua(a)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 -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #6 from Anton Romanov <theli.ua(a)gmail.com> --- I'm willing to do testing/debugging if someone have any ideas as to how to approach this -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #7 from Anton Romanov <theli.ua(a)gmail.com> --- just for the record - setting STAGING_SHARED_MEMORY 1 env var doesn't help Playing in emulated desktop doesn't help either -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #8 from Anton Romanov <theli.ua(a)gmail.com> --- sysprof seems to be pointing to CoWaitForMultipleHandles and subsequently WaitForMultipleObjectsX and PeekMessageW and server calls -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #9 from Panard <panard(a)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... -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #10 from Panard <panard(a)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.. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #11 from Panard <panard(a)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.. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #12 from Anton Romanov <theli.ua(a)gmail.com> --- (In reply to Panard from comment #11)
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..
Where is CoWaitForMultipleHandles even called from? Its not in your log extract -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #13 from Panard <panard(a)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? -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #14 from Anton Romanov <theli.ua(a)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... -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #15 from Anton Romanov <theli.ua(a)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 -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #16 from Anton Romanov <theli.ua(a)gmail.com> --- Created attachment 60157 --> https://bugs.winehq.org/attachment.cgi?id=60157 naive hack patch -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #17 from Panard <panard(a)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.. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #18 from Nikolay Sivov <bunglehead(a)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. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #19 from Anton Romanov <theli.ua(a)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 -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Robert Walker <bob.mt.wya(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |bob.mt.wya(a)gmail.com -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 --- Comment #20 from Anton Romanov <theli.ua(a)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. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Anton Romanov <theli.ua(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #60157|0 |1 is obsolete| | --- Comment #21 from Anton Romanov <theli.ua(a)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. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Nikolay Sivov <bunglehead(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Component|-unknown |ole32 -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Anton Romanov <theli.ua(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Resolution|--- |FIXED Status|UNCONFIRMED |RESOLVED --- Comment #22 from Anton Romanov <theli.ua(a)gmail.com> --- fixed by https://source.winehq.org/git/wine.git/commit/90a094cc24a900687347af8f490c46... -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Nikolay Sivov <bunglehead(a)gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Fixed by SHA1| |90a094cc24a900687347af8f490 | |c46617f9782df -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Alexandre Julliard <julliard(a)winehq.org> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED --- Comment #23 from Alexandre Julliard <julliard(a)winehq.org> --- Closing bugs fixed in 3.1. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Michael Stefaniuc <mstefani(a)winehq.org> changed: What |Removed |Added ---------------------------------------------------------------------------- Target Milestone|--- |3.0.x -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=43728 Michael Stefaniuc <mstefani(a)winehq.org> changed: What |Removed |Added ---------------------------------------------------------------------------- Target Milestone|3.0.x |--- --- Comment #24 from Michael Stefaniuc <mstefani(a)winehq.org> --- Removing the 3.0.x milestone from bugs included in 3.0.1. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
participants (1)
-
wine-bugs＠winehq.org