Project

General

Profile

Actions

Emulator Issues #12558

closed

MGS Twin Snakes performance regression since 5.0-14382

Added by vladkosi over 3 years ago. Updated over 3 years ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
% Done:

0%

Operating system:
N/A
Issue type:
Bug
Milestone:
Current
Regression:
Yes
Relates to usability:
No
Relates to performance:
Yes
Easy:
No
Relates to maintainability:
No
Regression start:
5.0-14382
Fixed in:
5.0-14462

Description

Game Name?

Metal Gear Solid: The Twin Snakes

Game ID? (right click the game in the game list, Properties, Info tab)

GGSEA4

MD5 Hash? (right click the game in the game list, Properties, Verify tab, Verify Integrity button)

0720e3d3fe42587b2ce22fbb8a60b847

What's the problem? Describe what went wrong.

Since 5.0-14382 there is heavy CPU usage and poor performance most noticeable in the codec conversations. One CPU core is spiking to 100%, second one around 70%. Framerate drops to 50-55 FPS with lots of audio stutters.
In 5.0-14367 the maximum CPU usage is about 60% on one core and 20% on the second one.

What steps will reproduce the problem?

  1. Start the game.
  2. Skip the intro to the first codec conversation.

Is the issue present in the latest development version? For future reference, please also write down the version number of the latest development version.

Yes. 5.0-14445

Is the issue present in the latest stable version?

No.

If the issue isn't present in the latest stable version, which is the first broken version? (You can find the first broken version by bisecting. Windows users can use the tool https://forums.dolphin-emu.org/Thread-green-notice-development-thread-unofficial-dolphin-bisection-tool-for-finding-broken-builds and anyone who is building Dolphin on their own can use git bisect.)

5.0-14382

If your issue is a graphical issue, please attach screenshots and record a three frame fifolog of the issue if possible. Screenshots showing what it is supposed to look like from either console or older builds of Dolphin will help too. For more information on how to use the fifoplayer, please check here: https://wiki.dolphin-emu.org/index.php?title=FifoPlayer

N/A

What are your PC specifications? (CPU, GPU, Operating System, more)

i5-8600K
GeForce 1060 6GB
Windows 10
16GB RAM

Is there anything else that can help developers narrow down the issue? (e.g. logs, screenshots,
configuration files, savefiles, savestates)

Reverting this change fixes the performance https://github.com/dolphin-emu/dolphin/commit/83ea16f40238fa82981221ba65061a7094b2a64b#diff-6b1d0b09968daf1d99fe6301f5ef540216e408709ee1a1fd10b2c451d25c9bbaL331


Files

dolphin-14367.log (824 Bytes) dolphin-14367.log vladkosi, 06/20/2021 09:24 PM
dolphin-14382.log (330 Bytes) dolphin-14382.log vladkosi, 06/20/2021 09:24 PM
Dolphin.zip (12.8 KB) Dolphin.zip vladkosi, 06/21/2021 10:56 AM

Related issues 1 (0 open1 closed)

Has duplicate Emulator - Emulator Issues #12553: Performance regression with Pokemon Battle Revolution after pr#9702Duplicate

Actions
Actions #1

Updated by JosJuice over 3 years ago

  • Milestone set to Current
  • Regression changed from No to Yes
  • Relates to performance changed from No to Yes
  • Regression start set to 5.0-14382
Actions #2

Updated by JosJuice over 3 years ago

  • Related to Emulator Issues #12553: Performance regression with Pokemon Battle Revolution after pr#9702 added
Actions #3

Updated by filoppi over 3 years ago

Check out what I said in this other similar bug report:
https://bugs.dolphin-emu.org/issues/12553
The code in the specific commit you mentioned doesn't really run when games are running, unless you have a faulty USB cable that constantly disconnects and reconnects devices (or a similar problem).
In that case, please check and paste here your ControllerInterface log.
And even when the code in the commit runs, it should only affect performance if you have an input configuration window open.

Actions #4

Updated by vladkosi over 3 years ago

I am just using keyboard and mouse, no controller is attached. Deleting shader cache didn't help.

I tried my own appveyor build reverting every commit in PR#9702 one by one. Reverting this one line fixes the performance for me https://github.com/dolphin-emu/dolphin/commit/83ea16f40238fa82981221ba65061a7094b2a64b#diff-6b1d0b09968daf1d99fe6301f5ef540216e408709ee1a1fd10b2c451d25c9bbaL331 I am not sure why, it was just trial and error.

Actions #5

Updated by filoppi over 3 years ago

I would kindly ask you to try testing the commits again before I investigate, because it does sound quite unlikely. And yes, check your log.

Actions #6

Updated by vladkosi over 3 years ago

Fresh Dolphin configuration (deleted "user" folder). Using the same settings in all three runs. Deleted "user/cache" before each run.

Official build 5.0-14367 - CPU usage 17% & 22%

https://i.imgur.com/SER0PB6.png

Official build 5.0-14382 - CPU usage 70% & 89%

https://i.imgur.com/mbSin80.png

AppVeyor build 5.0-14445 - CPU usage 20% & 11%

https://i.imgur.com/5igfv6m.png

Only change is "MappingWindow.cpp" from previous commit https://github.com/dolphin-emu/dolphin/commit/626c686fee8a7d116e86096a283dc0346327524e

https://ci.appveyor.com/project/vladkosi/dolphin/builds/39675975

Actions #7

Updated by filoppi over 3 years ago

Ok I will take a look. Could you post the post i mentioned though?

Actions #9

Updated by vladkosi over 3 years ago

Forgot to include the Official 5.0-14445 build

https://i.imgur.com/IRCwvMW.png

Actions #10

Updated by filoppi over 3 years ago

Can you try to disable DSU as well?

Actions #11

Updated by vladkosi over 3 years ago

It is disabled. This is the default configuration, I only changed few graphics settings.

Actions #12

Updated by filoppi over 3 years ago

So AppVeyor build 5.0-14445 (dirty) is the latest version with this line https://github.com/dolphin-emu/dolphin/commit/83ea16f40238fa82981221ba65061a7094b2a64b#diff-6b1d0b09968daf1d99fe6301f5ef540216e408709ee1a1fd10b2c451d25c9bbaL331 reverted, which effectively makes the file identical to https://github.com/dolphin-emu/dolphin/commit/626c686fee8a7d116e86096a283dc0346327524e
Is that what you meant?
If so, I'm gonna ask you to put a breakpoint in "void MappingWindow::RefreshDevices()" because that supposedly only runs when the user presses the refresh devices button, which isn't even clickable unless that widget is open, and by checking the code again, it would be very weird for the "button clicked" event to be trigged by code without a user input.

Actions #13

Updated by filoppi over 3 years ago

Also, instead of checking the CPU utilization, try setting the emulation speed to unlimited and see if there are actually any emulation speed regressions please.
Thanks.

Actions #14

Updated by vladkosi over 3 years ago

Yes, latest master, "MappingWindow.cpp" replaced with file from commit 626c686fee8a7d116e86096a283dc0346327524e.

Line #5 in the log https://ci.appveyor.com/project/vladkosi/dolphin/builds/39675975?fullLog=true

Sadly I can't install Visual Studio right now, hence the appveyor builds.

If you can provide me with test builds I am happy to try them to see what's going on.

Actions #15

Updated by filoppi over 3 years ago

Ok. See my last comment about unlocking the emulation speed.
Did you actually test everything twice or are the screenshots from the first time you tested everything?

Actions #16

Updated by vladkosi over 3 years ago

The screenshots are from 4 hours ago, I've tested it plenty times. I have every build in separate portable folder with identical configurations.

Emulation speed is definitely lower.

5.0-14367 - FPS around 90, VPS around 190

https://i.imgur.com/aVaMFgJ.png

5.0-14382 - FPS around 60, VPS around 120

https://i.imgur.com/TwbVtvE.png

Actions #17

Updated by vladkosi over 3 years ago

5.0-14445-dirty - same as 5.0-14367 FPS around 90, VPS around 190

https://i.imgur.com/WhWtxeh.png

Actions #18

Updated by filoppi over 3 years ago

I tested both build 14367 and 14382 and to me the unlimited emulation speed is exactly the same.
Plus, I experimented with the code you said that fixed the problem after reverting it, and it does not stall nor run on the emulation/CPU thread in any way, the emulation still runs at flawless ~350% if I spam click the "Refresh" devices button, so even if something was clicking that underneath (which is not because it would show in the logs), it would not affect emulation performance (which it would instead would have before my changes).
I'm gonna ask you to redownload both builds, re-delete your whole Dolphin documents folder (before each test) and try again. If you still find a speed regression with 14382, then try to revert commits individually again, because the change you mentioned can't be the reason of an emulation speed regression.
Thanks.

Actions #19

Updated by filoppi over 3 years ago

Could you try both:
5.0-14445-dirty
and
5.0-14445 (not dirty, with no changes)
from AppVeyor, and maybe upload them here, so we can prove if the change you mentioned actually impacts performance?
Please make a new build with the reversed change, as it could have been a build machine "bug".

Actions #20

Updated by vladkosi over 3 years ago

Redownloaded and retested with clean default settings. Performance regression is still present.

I am not using documents folder for settings. Each build is in separate portable folder with it's own "user" folder. Both build folders are identical, they differ only in "dolphin.exe". I've attached the settings.

https://i.imgur.com/tV4MkuI.png
https://i.imgur.com/b8EeRuQ.png

Please also try both builds with 200% emulated CPU clock override. That's how I first discovered the bug. I was using 200% in my config. At 200% it drops below 60 FPS and the sound stutters badly.

With 200% clock override:

https://i.imgur.com/e3Dzmt7.png
https://i.imgur.com/FFLUmLN.png

I have also tested on second PC (i5-3570K, integrated graphics). Same two portable folders and settings (I've deleted the "user/cache" folder).

Without clock override:

5.0-14367 is around 55 FPS, 130 VPS
5.0-14382 drops to 41 FPS, 120 VPS

I will rebuild the appveyor builds and try them on both PCs. Each takes 29 minutes to build so I will report later.

Actions #21

Updated by JMC4789 over 3 years ago

To get those FPS/VPS values, are you running dualcore completely unsynced or something?

Actions #22

Updated by vladkosi over 3 years ago

"clean default settings" so yes, dualcore is enabled. Only change from defaults is the unlimited emulation speed and emulated CPU clock override.

Actions #23

Updated by JMC4789 over 3 years ago

Based on your readings, the game is running 20/60 natively, which doesn't make sense since it's a 30/60 game.

I didn't mean is dual core enabled, I meant did you disable syncing entirely which is a hidden option. If you're default the answer is no but I still don't get how you have such a weird reading for this.

Actions #24

Updated by vladkosi over 3 years ago

The setting used are in the attached ZIP file.

Actions #25

Updated by vladkosi over 3 years ago

Unmodified appveyor build from master:

https://ci.appveyor.com/project/vladkosi/dolphin/builds/39682698?fullLog=true
You can download it from here: https://ci.appveyor.com/project/vladkosi/dolphin/builds/39682698/artifacts

With 200% clock override:
https://i.imgur.com/vMT1Qoc.png

Appveyor build from master with "MappingWindow.cpp" replaced from commit 626c686fee8a7d116e86096a283dc0346327524e

https://ci.appveyor.com/project/vladkosi/dolphin/builds/39683218?fullLog=true
Download: https://ci.appveyor.com/project/vladkosi/dolphin/builds/39683218/artifacts

Exactly the same settings with 200% clock override:
https://i.imgur.com/cQmZiNs.png

Second PC without clock override:

5.0-14447 - 40 to 45 FPS, 115 VPS
5.0-14447-dirty - 50 to 55 FPS, 145 VPS

When I was testing the appveyor builds few days ago, at first I reverted the whole commit https://github.com/dolphin-emu/dolphin/pull/9702/commits/83ea16f40238fa82981221ba65061a7094b2a64b and that fixed my performance.

Then I saw this part in the commit message: "Avoid calling ControllerInterface::RefreshDevices() from the CPU thread if the emulation is running and we manually refresh devices from Qt, as that is not necessary anymore."

So I tried reverting just the "MappingWindow.cpp" file (the only file with changes related to "RefreshDevices()") and that fixed it too. I don't know the reason why or how it works but clearly it does, on two separate machines.

Actions #26

Updated by filoppi over 3 years ago

Can you build another AppVeyor version with any random change, and test the speed then? Don't change MappingWindow.cpp, just change any other file which should be irrelevant to the emulation speed, and then report the numbers again.
I've compared the two binaries you uploaded and they are extensively different, despite the only change supposedly being one line, so that is weird.
Also I've tested their performance and it's exactly the same on my machine.

Actions #27

Updated by vladkosi over 3 years ago

You can't compare release binaries by contents like that. They are heavily optimized by the compiler. Just one line in source code can produce massively different binary.

Have you tested on 200% or even 400% clock override where the performance difference is really large?

Actions #28

Updated by filoppi over 3 years ago

From another chat:

So something interesting came up
changing the line the user has mentioned
between the old: Core::RunAsCPUThread([&] { g_controller_interface.RefreshDevices(); });
and the new: g_controller_interface.RefreshDevices();
does COMPLETELY change the binary
so the compiler puts the binary together in a very different way.
if any other line is changed, the binaries end up having very little differences
so maybe it's the dependency from "Core" in that object that gives that user that speed up?
Removing Core::RunAsCPUThread(...) does take away any dependency from "Core", in MappingWindow.cpp
Still, the Qt project has other Core::RunAsCPUThread(...) around, they are just in other files.
In any case, performance is always exactly the same on my machine.
And as expected "MappingWindow::RefreshDevices()" does not run, unless the user clicked its connected UI button.
So if this was real, it wouldn't be a problem with my changes itself, but with the compiler, I assume. I really wouldn't know how to proceed for here.

Actions #29

Updated by vladkosi over 3 years ago

We just need to find out why you can't reproduce the performance regression between official builds 5.0-14367 and 5.0-14382.
Because I definitely can, using the default settings and on two different machines.

Actions #30

Updated by filoppi over 3 years ago

I'm on AMD 5900X, so maybe it's an "Intel" problem, though I couldn't see way.
Did you put both builds in equivalent folders (like on the same hard drive) and run them at different times?
All I can do is ask others to test for performance regressions as well, but I believe a few already tried and also didn't have any.

Actions #31

Updated by vladkosi over 3 years ago

Could be an Intel thing. I can test it on third machine, my laptop, but that is also an Intel.

Yes, everything is in separate folders, on same drive, with the exact same config files, run at different times.

These are the exact steps to reproduce on my two machines:

  1. download https://dl.dolphin-emu.org/builds/b2/c9/dolphin-master-5.0-14367-x64.7z
  2. download https://dl.dolphin-emu.org/builds/a3/c2/dolphin-master-5.0-14382-x64.7z
  3. extract each build to separate directory
  4. copy the "portable.txt" file and "user" folder from the attached ZIP https://bugs.dolphin-emu.org/attachments/8450/Dolphin.zip to each directory making it portable (these are default Dolphin settings, only change is "ISOPath0 = ." and unlimited emulation speed)
  5. copy "Metal Gear Solid The Twin Snakes Disc 1.iso" (MD5 0720e3d3fe42587b2ce22fbb8a60b847) to each directory
  6. set emulated CPU clock override to 200%
  7. start new game, skip all cutscenes/codec conversations to the part on the screenshots and use the codec to start a new conversation

5.0-14367 stays at 97 FPS
5.0-14382 drops to 55-57 FPS and while Colonel is talking audio is stuttering. The FPS drops are present during the intro cutscenes at random times, but here I can reproduce it 100%.

Same with he latest master https://dl.dolphin-emu.org/builds/20/37/dolphin-master-5.0-14447-x64.7z FPS drops to 55

Actions #32

Updated by JMC4789 over 3 years ago

The performance regression only happens in dualcore, that's why I was unable to reproduce it. Single Core is actually faster in this game for me anyway.

Actions #33

Updated by vladkosi over 3 years ago

That's correct, with dualcore disabled I get lower performance (98 to 70 FPS) on both builds, but the drops to 55 FPS on 5.0-14382 are not there.

Same with the latest master.

Actions #34

Updated by ds22x over 3 years ago

Pardon my intrusion, but I've been following this discussion ever since I got notified that an issue related to my issue was opened, and I decided to redo the testing I did with Pokemon Battle Revolution, and it seems that there indeed is a regression in performance with dualcore.
I probably had dualcore enabled as an override during the initial testing, while disabling it later when I went and cleared the shader cache and running the second testing the next day.

Actions #35

Updated by JosJuice over 3 years ago

  • Related to deleted (Emulator Issues #12553: Performance regression with Pokemon Battle Revolution after pr#9702)
Actions #36

Updated by JosJuice over 3 years ago

  • Has duplicate Emulator Issues #12553: Performance regression with Pokemon Battle Revolution after pr#9702 added
Actions #37

Updated by leoetlino over 3 years ago

  • Status changed from New to Fixed
  • Fixed in set to 5.0-14462
Actions

Also available in: Atom PDF