Sound torn when the Memory Stick is checked.

[vnctdj]

The title say everything.

Look at the video I made for better understanding >> https://www.youtube.com/watch?v=9hdLVNz62yI

I don't know if this happen only in this game (Monster Hunter Freedom Unite) or in another ?

[hrydgard]

Probably something to do with I/O timing? Hm..

[thedax]

That, or maybe it's from audio being on the same thread as everything else? I get this too in other games from time to time, even with my beefy PC, since the emulator has to stop everything it's doing to load a new room/etc, so it's likely that some audio is dropped or stretched out.

[vnctdj]

Maybe I can help you by testing something ? I know how to compile my own builds and how to use JpcspTrace if you want ;)

[unknownbrackets]

And this happens with IO on a separate thread enabled? Although that doesn't currently affect savedata.

-[Unknown]

[thedax]

Yes, it does. Neither threading option, both on or off, affects it.

[vnctdj]

@thedax : I confirm that too...

[vnctdj]

Unfortunately Maxim's work doesn't fix this issue :-/

[thedax]

Why would it? It was never related to the plugin.

[vnctdj]

It's a sound problem, so... I don't know ?

[unknownbrackets]

If you turn on "Show Debug Statistics", what does it show as the top syscall during this time?

If you're having trouble catching it, change this in sceDisplay.cpp:

    gpuStats.ResetFrame();
    kernelStats.ResetFrame();

Add above that:

    NOTICE_LOG(HLE, "Slowest syscall: %s  - %0.2f ms / total %0.2f ms", kernelStats.summedSlowestSyscallName ? kernelStats.summedSlowestSyscallName : "(none)", kernelStats.summedSlowestSyscallTime * 1000.0f, kernelStats.msInSyscalls * 1000.0f);
    for (auto it = kernelStats.summedMsInSyscalls.begin(), end = kernelStats.summedMsInSyscalls.end(); it != end; ++it) {
        const double t = it->second * 1000.0f;
        if (t > 0.001f) {
            const char *name = GetFuncName(it->first.first, it->first.second);
            NOTICE_LOG(HLE, "  Syscall: %s  - %0.2f ms", name, t);
        }
    }

Also, try changing this line:

DoFrameTiming(throttle, skipFrame, (float)numVBlanksSinceFlip * (1.001f / 60.0f));

To:

DoFrameTiming(throttle, skipFrame, 1.001f / 60.0f);

That fixes the same tearing in Mana Khemia, which is because it's skipping frames.

-[Unknown]

[vnctdj]

What do you mean by the "top syscall" ? You mean the "Most active syscall" ?

I have added the "NOTICE_LOG" part of code in my sceDisplay.cpp.
The problem is that there is a huge amount of syscalls all the time (I mean that the log console is scrolling extremely fast), so this makes the research very difficult.
However, I tried to stop emulation at the moment the sound tearing is beginning.
I have done my best given that this is very tricky, so I hope it will be OK :)
Here is the screenshot :

Also, when I tried to change the "DoFrameTiming" line as you said, the game is running at 200% speed when the FPS are 30 (so it's 60/30) and when the FPS are 60 (during the introduction video) the game is running at 100% speed (so FPS are 60/60).
In other words, I get 60 FPS all the time, so I don't think it's what you expected, right ?

[unknownbrackets]

60 fps all the time is exactly what I expected. You can change it to 30.0f if you want 30. But I'm just wondering if this makes the sound effect smooth or not. I know that the change itself is wrong.

Well, you can comment out the second NOTICE_LOG from the code I pasted. The goal is to look for a "Slowest syscall:" line that has a high number at the end (>= 5 ms) 0.31 should not cause any sound distortion.

-[Unknown]

[vnctdj]

Given that with 60.0f the speed is 200%, the sound is too fast to hear if it's teared or not.
So I tried 30.0f and now I can say that it doesn't change anything, I mean that the sound is teared like before...

Anyway, I commented out the second NOTICE_LOG as you said, and yes, this is a lot more simple to see something ! :)
So I think I found the culprit : as you can see on the screenshot below, sceUtilitySavedataUpdate is 32.47 ms / total 33.48 ms...

[unknownbrackets]

Okay, try this then in Core/HLE/sceUtility.cpp, first add this at the top of the file (near the algorithm stuff):

#include "GPU/GPUState.h"

int sceUtilitySavedataUpdate(int animSpeed)
{
    if (currentDialogType != UTILITY_DIALOG_SAVEDATA)
    {
        WARN_LOG(SCEUTILITY, "sceUtilitySavedataUpdate(): wrong dialog type");
        return SCE_ERROR_UTILITY_WRONG_TYPE;
    }

Add after:

    static int lastVBlank = 0;
    static int numVblankCalls = 0;
    static int lastFlip = 0;
    static int numFlipCalls = 0;

    if (lastVBlank != gpuStats.numVBlanks) {
        if (numVblankCalls > 0)
            NOTICE_LOG(HLE, "sceUtilitySavedataUpdate: called %d times since vblank #%d", numVblankCalls, lastVBlank);
        lastVBlank = gpuStats.numVBlanks;
    }
    if (lastFlip != gpuStats.numFlips) {
        if (numFlipCalls > 0)
            NOTICE_LOG(HLE, "sceUtilitySavedataUpdate: called %d times since flip #%d", numFlipCalls, lastFlip);
        lastFlip = gpuStats.numFlips;
    }
    ++numVblankCalls;
    ++numFlipCalls;

This should show me if it's being called a lot, or if it's just a single call that is taking that long.

-[Unknown]

[vnctdj]

Apparently it's a single call, I have done the test several times one after the other and I found that the "counter" is incrementing, maybe this precision is useless though... I just say that to explain to you why it's mentioned multiple times on the screenshot :

[unknownbrackets]

Oops, I forgot to reset it. Yes, it's just one each time.

So I guess it's because it's a larger save maybe. Potentially we could distribute it in chunks throughout Update() calls as probably the PSP does...

-[Unknown]

[vnctdj]

So you are thinking it's because the size of the save is too big ?
Would it be interesting to know how the PSP does ? I mean with JpcspTrace ?

[unknownbrackets]

Yeah, it would be interesting to know how many times it calls sceUtilitySavedataUpdate:

sceUtilitySavedataUpdate 0xd4b95ffb 1 d

-[Unknown]

[vnctdj]

Here is the log : http://pastebin.com/ge4WiEbE :)

[vnctdj]

Unfortunately the following commit doesn't change anything : 1045465 :-/

[vnctdj]

My log from JpcspTrace isn't helpful ? :-/

[hrydgard]

Looks like it calls it for quite a few frames, which might mean that the save/load action is spread out over multiple frames instead of just happening instantaneously which would freeze the display and cause the audio to chop unless using asynchronous i/o.

[unknownbrackets]

Async io currently doesn't apply/work for savedata.

-[Unknown]

[unknownbrackets]

Savedata still doesn't use a thread, but has this improved with the recent fps timing changes? I think it would've detected the drop in fps potentially and caused that drop to hurt audio.

-[Unknown]

[solarmystic]

@unknownbrackets Most definitely. It's still not perfect but it's much improved as compared to how it used to sound. Would be nice for @vnctdj to come in and verify my findings though.

[vnctdj]

I totally agree with @solarmystic, it's improved but not perfect yet :)

[hrydgard]

That is reported to fix it, closing.

[vnctdj]

@hrydgard
Not really fixed, please see the following comment I made : #6468 (comment)

[unknownbrackets]

I don't think there's anything else we can practically do here with the io operations running on a separate thread. If it doesn't work for some computers with slower io or something, then it's just a problem of not being fast enough...

We could make the io operations delay longer. For example change this:

            switch (ioThreadStatus) {
            case SAVEIO_NONE:
                StartIOThread();
                break;
            case SAVEIO_PENDING:
            case SAVEIO_DONE:
                // To make sure there aren't any timing variations, we sync the next frame.
                JoinIOThread();
                ChangeStatus(SCE_UTILITY_STATUS_FINISHED, 0);
                break;
            }

To:

            switch (ioThreadStatus) {
            case SAVEIO_NONE:
                StartIOThread();
                break;
            case SAVEIO_PENDING:
                break;
            case SAVEIO_DONE:
                // To make sure there aren't any timing variations, we sync the next frame.
                JoinIOThread();
                ChangeStatus(SCE_UTILITY_STATUS_FINISHED, 0);
                break;
            }

Although this will make emulation depend on external state other than user input related which is bad.

-[Unknown]