[Windows] Log console is super slow and can greatly reduce performance

[bslenul]

Description

On Windows with "Logging Verbosity" ON, for some reason the log console is super slow and with cores that spam stuff in logs (Dolphin and MAME2010 are good examples) it hurts performance a lot. This is happening with 1.9.1 stable and nightlies. It runs fine if "Logging Verbosity" is OFF or if "Log to File" is ON.

I don't know what's causing this, in 1.9.0 stable from the buildbot it's perfectly fine, despite the spam the content still runs fine, however if I build the 1.9.0 stable commit (6388872) myself with my MSYS2 setup it's super laggy too.

Here's 2 examples, 1.9.0 stable from the buildbot (left side) vs. 1.9.1:

https://user-images.githubusercontent.com/33353403/114387394-aaeb2600-9b92-11eb-875d-3f4a8b9d48fd.mp4

1. I'm comparing MAME2010 first, you can hear that audio is super distorted when inserting coins with 1.9.1, I didn't show gameplay to not make the video too long, but it's also slow.
2. I'm comparing Dolphin boot and close time, you can see that it takes forever with 1.9.1 :x

It spams the same amount of content in logs, but for some reason it's just MUCH slower with 1.9.1, like the whole Dolphin spam scrolls in a blink of an eye in 1.9.0 but takes like 6 seconds to scroll in 1.9.1...

Expected behavior

Performance shouldn't take a hit with the log console opened, or at least not this much. It should run like 1.9.0 stable.

Actual behavior

Reduces performance greatly, looks like the log console struggles to catch up or something.

Steps to reproduce the bug

1. Make sure you have "Logging Verbosity" ON, "Log to File" OFF and the levels to "1 (Info)".
2. Boot a GC game with Dolphin, or mslug.zip with MAME2010 (starwars.zip is also a great test, unplayble).
3. Compare with 1.9.0 stable from the buildbot: https://buildbot.libretro.com/stable/1.9.0/windows/x86_64/RetroArch.7z

Bisect Results

Seems to be a compilation issue, not a RetroArch bug, so I'd say since the buildbot migration probably? Or whenever a change was made with how RetroArch is compiled.

Version/Commit

• RetroArch: 1.9.1 / 7f3b9e8

Environment information

• Windows 10 / i5-4670K / GTX 970 / 16GB

[bslenul]

Here's another 1.9.0 vs. 1.9.1 with starwars.zip on MAME2010:

https://user-images.githubusercontent.com/33353403/114391281-952c2f80-9b97-11eb-94c6-210ccdaa891f.mp4

😅

[inactive123]

Ideally cores should only log when absolutely necessary, and they should definitely not casually log spam. Logging is big overhead in nearly every program, functions like fprintf, vfprintf and friends are just not very optimized and probably never will. And yes, the regular way people should play is definitely with Logging verbosity turned off, and only enabled when it's absolutely necessary and there's something they have to debug.

As for whether there has been a regression in logging performance since the migration of the buildbot, I can't really say but I'd need more substantive reports on that.

[inactive123]

In the meantime, while this does not fix any of the underlying issues obviously, I will get rid of that per-frame log message in that 2010 core.

[bslenul]

Yeah I guess not many people leave the log console, but I like to have it open to quickly spot issues and all :p Not a big deal tho, it's a weird issue but I can just create an override for these cores with core verbosity set to "warning" to work around it.

Also it seems to happen only with the Windows command prompt, for example if I launch RetroArch from the MSYS2 shell/terminal, the spam is still there, but the games are not lagging.

[inactive123]

I'm very thankful for these logging performance reports so definitely keep those coming. They can be especially helpful for certain cores so that we know if there is a particular bottleneck somewhere that we need to plug.