https://bugs.winehq.org/show_bug.cgi?id=45815
Bug ID: 45815 Summary: FamiTracker etc. use much more CPU in Wine than Windows Product: Wine Version: 3.15 Hardware: x86-64 OS: Linux Status: UNCONFIRMED Severity: normal Priority: P2 Component: -unknown Assignee: wine-bugs@winehq.org Reporter: jimbo1qaz@gmail.com Distribution: ---
Famitracker 0.4.6, 0CC-Famitracker 0.3.14.5, and j0CC 0.6.0a (forks of the same MFC-based codebase) use around 60% of a single CPU core (with WINEDEBUG=-all) when idling, and causes my laptop fan to spin up. It uses significantly less than that when idling on Windows (16-32% of a core, corresponding to 4-8% of four cores in taskmgr).
Famitracker: http://famitracker.com/files/FamiTracker-v0.4.6.zip
Tested on 3.14 and 3.15 and 3.15-staging, and in a clean WINEARCH-win32 wineprefix.
https://bugs.winehq.org/show_bug.cgi?id=45815
--- Comment #1 from jimbo1qaz jimbo1qaz@gmail.com --- I tried using `perf -g` to record performance logs.
Seems a lot of CPU time is spent in functions that end up calling __vdso_gettimeofday . (Debian 9 x64 VM)
https://bugs.winehq.org/show_bug.cgi?id=45815
--- Comment #2 from jimbo1qaz jimbo1qaz@gmail.com --- Wine: 3.16 Github: https://github.com/jimbo1qaz/j0CC-FamiTracker/releases/tag/j0.6.1 Exact binary used: https://github.com/jimbo1qaz/j0CC-FamiTracker/releases/download/j0.6.1/j0CC-... Symbols: https://github.com/jimbo1qaz/j0CC-FamiTracker/releases/download/j0.6.1/j0CC-...
I ran `perf report` on native non-VM Kubuntu 18.04: - 69.22% 0x6619ba + 33.94% 0x502dc4 + 33.63% 0x503467
It seems 502dc4 and 503467 are eating CPU.
## 502dc4
`winedbg attach` immediately breaks in a subcall of 502dc4. I run bt, then compare binary addresses with x32dbg running under Wine.
- Open .exe in x32dbg - ctrl+G, paste, enter - it loads .pdb and tells me which file/line# the code corresponds to
famitrackerview.cpp:839 10 0x0000000000443e3a in j0cc-famitracker-j0.6.1 (+0x43e39) (0x000000000033fac4) void CFamiTrackerView::OnTimer(UINT_PTR nIDEvent) CView::OnTimer(nIDEvent)...
wincore.cpp 11 0x00000000004f7752 in j0cc-famitracker-j0.6.1 (+0xf7751) (0x000000000033fb90) call esi
It seems that void CFamiTrackerView::OnTimer(UINT_PTR nIDEvent) is using too much CPU time. Most of the CPU load occurs in CView::OnTimer(nIDEvent) and subfunctions (which draw the main screen).
----------
## 503467
famitracker.cpp:757 BOOL CFamiTrackerApp::OnIdle(LONG lCount) // // // if (CWinApp::OnIdle(lCount)) 7 0x00000000004196de in j0cc-famitracker-j0.6.1 (+0x196dd) (0x000000000033fe3c)
thrdcore.cpp 8 0x0000000000503467 in j0cc-famitracker-j0.6.1 (+0x103466) (0x000000000033fe5c)
It seems that BOOL CFamiTrackerApp::OnIdle(LONG lCount) is using too much CPU time. Most of the CPU load occurs in (CWinApp::OnIdle(lCount)). According to `perf report`, CWinApp::OnIdle calls GetTopWindow, GetWindow, and a deep stack leading to CallWindowProcA.
full stacktraces with partial .pdb labeling at https://gist.github.com/jimbo1qaz/58a8462e9607375b0b9948299fd266a2
Should I share the perf.data file?
------------
I suspect CFamiTrackerView::OnTimer (overrides CView::OnTimer), and CFamiTrackerApp::OnIdle (overrides CWinApp::OnIdle) are being called too often. I may have to recompile on Windows, add a print statement in both functions, and compare the rate of output in Windows vs Linux VM.
Turns out winedbg was unnecessary, the `perf report` addresses are fully valid in x32dbg. (I swear the addresses were complete gibberish last time I tried viewing in x32dbg. Maybe I viewed &stack instead of &EIP?)
------------
sidenote: running `winedbg j0CC-Famitracker-j0.6.1.exe` would crash:
WineDbg starting on pid 00c1 00c2:err:module:DelayLoadFailureHook failed to delay load uxtheme.dll.IsThemeActive wine: Call from 0x7b43d41c to unimplemented function uxtheme.dll.IsThemeActive, aborting 00c2:err:module:attach_dlls "comctl32.dll" failed to initialize, aborting 00c2:err:module:attach_dlls Initializing dlls for L"H:\apps\j0cc-famitracker\j0CC-Famitracker-j0.6.1.exe" failed, status 80000100 Process of pid=00c1 has terminated
https://bugs.winehq.org/show_bug.cgi?id=45815
--- Comment #3 from jimbo1qaz jimbo1qaz@gmail.com --- j0CC has an undocumented console output mode. `j0CC_FamiTracker.exe -console`
## OnTimer and OnIdle
CFamiTrackerView::OnTimer - Intended: 1 call per 20ms = 50 call/s + OnTimer(0) is called in the background. OnTimer(1) only when scrolling (in practice, only via mouse clicks, other forms of scroll don't call it). - Windows: 20-40 call/s - Debian VM Wine: ~50 call/s + Wine is actually more correct and consistent. - Ubuntu Wine:
CFamiTrackerApp::OnIdle - Intended: whenever idle - Windows: OnIdle(0 and 1) are called equally. + OnIdle(0) OnIdle(1) each called 40 times per second normally. + nearly 200 times/second if I'm waving mouse rapidly over the window. - Debian VM Wine: + OnIdle(0) called 50/second. + OnIdle(1) called ~10/second. + Waving mouse around does not affect call rate.
In my Debian Stretch VM (wine 3.16), 0x502dc4 uses negligible cpu, while only 0x503467 (CFamiTrackerApp::OnIdle) does.
(x32dbg's memory mappings are only correct when executing the debugger under Wine. The addresses are not valid under Windows.)
https://stackoverflow.com/questions/8349677/how-cwinthreadonidle-is-used "MFC uses its default OnIdle processing to enable and disable menu items and toolbar buttons, as you can see in the documentation for CWinApp::OnIdle"...
https://msdn.microsoft.com/library/e426a3cd-0d15-40d6-bd55-beaa5feb2343.aspx...
OnIdle(0) is handled by MFC itself (CWinApp::OnIdle(lCount) returns TRUE and the function returns.) OnIdle(1) is handled by 0CC. Unfortunately CWinApp::OnIdle this takes much longer on Wine than Windows, so OnIdle(1) barely gets a chance to run.
https://bugs.winehq.org/show_bug.cgi?id=45815
--- Comment #4 from jimbo1qaz jimbo1qaz@gmail.com --- The symbols perfectly match source files located at C:\Program Files (x86)\Microsoft Visual Studio\2017\Community\VC\Tools\MSVC\14.15.26726\atlmfc\src\mfc*.cpp . (Note that VC++ bundles precompiled MFC libraries from the same source, and does not compile these source files. I have tried and failed to find a way to compile them in my own Visual Studio project, let alone GCC.)
- 63.48% 0x503467 - 0x4196de - 63.44% 0x50ad24 CFamiTrackerApp::OnIdle - 63.36% 0x503202 CWinApp::OnIdle - 56.73% 0x4f8556 CWinThread::OnIdle - 44.25% 0x4f8556 CWnd::SendMessageToDescendants - 14.21% 0x4f855f + 13.62% 0x7eb06646 user32 (#define GetNextWindow GetWindow)
- 13.49% 0x4f853d + 13.29% 0x7eb0838b user32 (GetTopWindow) + 12.91% 0x7eb06646 user32 (GetWindow)
- 10.55% 0x4f851e returns to wincore.cpp:3025 SendMessageToDescendants - 10.36% 0x4f3cfa AfxCallWndProc - 10.16% 0x4f8b7a CWnd::WindowProc - 10.06% 0x4f548d CWnd::DefWindowProc calls CallWindowProcA at 7EB15C80 - 9.95% 0x7eb16e6d user32 (CallWindowProcA?)
Normal, probably also found on Windows: - 2.40% 0x4f8556 ::GetNextWindow - 1.16% 0x4f8556 ::GetNextWindow - 0.58% 0x4f851e returns to wincore.cpp:3025 SendMessageToDescendants - 0.56% 0x4f3cfa AfxCallWndProc - 0.56% 0x518676 Render toolbars. - 0x4f8b59 - 0.55% 0x4f7a28 0.52% 0x517acd - truncated
+ 9.58% 0x4f851e + 1.07% 0x4f855f + 1.05% 0x4f853d - 0.54% 0x4f84fa - 0.53% 0x7eb0838b 0.52% 0x7eb06646 + 3.84% 0x4f851e + 1.09% 0x4f853d + 1.08% 0x4f855f
CWinApp::OnIdle has no loop, calls:
CWinThread::OnIdle has no loop, calls:
CWnd::SendMessageToDescendants loops through: for (HWND hWndChild = ::GetTopWindow(hWnd); hWndChild != NULL; hWndChild = ::GetNextWindow(hWndChild, GW_HWNDNEXT))
Using never-breakpoints in x32dbg, I ran j0CC for over a minute: - CWnd::SendMessageToDescendants gets called 5082 times - The for loop gets executed 42964 times (which seems fairly normal).
I think user32 is too slow. Specifically: GetTopWindow, GetWindow, CallWindowProcA
https://bugs.winehq.org/show_bug.cgi?id=45815
--- Comment #5 from jimbo1qaz jimbo1qaz@gmail.com --- would be nice if I could use `gdb --args wine exe` and have it pick up symbols...
apt install wine-devel-dbg:i386 (note, amd64 didn't supply 32-bit symbols, and conflicts with i386 due to widl) gdb --args wine j0CC-Famitracker-j0.6.1.exe
Reading symbols from wine...Reading symbols from /usr/lib/debug//opt/wine-devel/bin/wine...done.
(gdb) b GetWindow Function "GetWindow" not defined. Make breakpoint pending on future shared library load? (y or [n]) y Breakpoint 1 (GetWindow) pending. (gdb) b GetTopWindow Function "GetTopWindow" not defined. Make breakpoint pending on future shared library load? (y or [n]) y Breakpoint 2 (GetTopWindow) pending. (gdb) b CallWindowProcA Function "CallWindowProcA" not defined. Make breakpoint pending on future shared library load? (y or [n]) y Breakpoint 3 (CallWindowProcA) pending. (gdb) r Starting program: /usr/bin/wine j0CC-Famitracker-j0.6.1.exe
you have to continue past SIGUSR1 twice (0xf7ffcc89), but none of the breakpoints trigger.
-
wine-bugs＠winehq.org