Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

MotorStorm artic edge Playable but wo/ sound #7445

Closed
CoCoNO opened this issue Feb 7, 2015 · 40 comments · Fixed by #12121
Closed

MotorStorm artic edge Playable but wo/ sound #7445

CoCoNO opened this issue Feb 7, 2015 · 40 comments · Fixed by #12121
Milestone

Comments

@CoCoNO
Copy link

CoCoNO commented Feb 7, 2015

The game boots and gets ingame, it is even its playable at decent speed. but the moment you get ingame the sound dies and wont be on again unless you restart the game

@CoCoNO
Copy link
Author

CoCoNO commented Feb 7, 2015

using v1.0-38-g05fc4cf on win x64

@CoCoNO
Copy link
Author

CoCoNO commented Feb 7, 2015

Using the disasembly tool i can see that the Sound thread is waiting for an event flag, i guess it's relevant

@hrydgard
Copy link
Owner

Yeah, the question is which thread is supposed to trigger that event flag, and why it doesn't..

@sum2012
Copy link
Collaborator

sum2012 commented Mar 20, 2015

ppsspp-v1.0.1-195-g87f31d0 log:
https://gist.github.com/sum2012/7b09934b7b17c3cf2357
JPCSPtrace log:
https://gist.github.com/sum2012/f75bdcc55e29e2a28e96

A fast compare,sceAtracGetStreamDataInfo wrong

PPSSPP:
44:56:196 StreamThread D[ME]: HLE\sceAtrac.cpp:1279 sceAtracGetStreamDataInfo(0, 0accf7d0[0adb17c0], 0accf7c8[0001b9c0], 0accf7c4[00040000])

JPCSPTrace:
23:11:34.824090 StreamThread - -> sceAtracGetStreamDataInfo 0x0, 0x08CCB0D0(0x0), 0x08CCB0C8(0x0), 0x08CCB0C4(0x0) = 0x0

23:11:34.824171 StreamThread - <- sceAtracGetStreamDataInfo 0x0, 0x08CCB0D0(0x8DAD160), 0x08CCB0C8(0x1BC68), 0x08CCB0C4(0x40000) = 0x0

@CoCoNO
Copy link
Author

CoCoNO commented Mar 22, 2015

I guess that the game kills the sound thread while loading to speed up the process; But when the load finishes somehow doesn't fire the flag to re-start the sound thread.

@sum2012
Copy link
Collaborator

sum2012 commented Apr 6, 2015

Update the log to v1.0.1-343-gbc490e6
https://gist.github.com/sum2012/88eb2f485724863b6e1b

@CoCoNO
Copy link
Author

CoCoNO commented Oct 17, 2015

Problem persist in 1.1.1

@unknownbrackets
Copy link
Collaborator

Does this look any better in the latest git build? What does the latest log look like?

-[Unknown]

@daniel229
Copy link
Collaborator

The log
03

full log
ppsspplog.txt

@csenech
Copy link

csenech commented Jan 8, 2016

Same problem [-> 1.1.1-647 (win) ...] audio is "disabled" everytime a race is launch, Playing the first intro video (menu:garage>media) make audio "enabled" again until the player launch a race ...

29:44:812 09F7A700 E[ME]: HLE\sceMpeg.cpp:1301 UNIMPL sceMpegAvcDecodeFlush(09b3cf00)
29:49:198 user_main E[ME]: HLE\sceMpeg.cpp:1895 UNIMPL sceMpegAvcInitYCbCr(09b3cf00, 1, 480, 272, 09d6b580)
29:49:198 user_main E[ME]: HLE\sceMpeg.cpp:1895 UNIMPL sceMpegAvcInitYCbCr(09b3cf00, 1, 480, 272, 09d9b300)
29:51:198 user_main E[ME]: HLE\sceMpeg.cpp:1301 UNIMPL sceMpegAvcDecodeFlush(09b3cf00)
29:52:049 user_main E[FileSys]: FileSystems\DirectoryFileSystem.cpp:560 DirectoryFileSystem::OpenFile: FAILED, 3 - access = 1
29:52:049 user_main E[IO]: HLE\sceIo.cpp:1783 ERROR_ERRNO_FILE_NOT_FOUND=sceIoOpenAsync(ms0:\PSP\GAME\UCES01250\MSAESPED.EDAT, 40000001, 00000000) - file not found
29:53:350 user_main E[ME]: HLE\sceMpeg.cpp:1895 UNIMPL sceMpegAvcInitYCbCr(098b2e80, 1, 480, 272, 09add980)
29:53:350 user_main E[ME]: HLE\sceMpeg.cpp:1895 UNIMPL sceMpegAvcInitYCbCr(098b2e80, 1, 480, 272, 09b0d700)
30:19:243 user_main E[ME]: HLE\sceMpeg.cpp:1301 UNIMPL sceMpegAvcDecodeFlush(098b2e80)
30:54:659 user_main N[HLE]: DevScreens.cpp:204 Submitted:

@sum2012
Copy link
Collaborator

sum2012 commented Jan 17, 2016

v1.1.1-698-g98c779c still no sound
log:
https://gist.github.com/sum2012/35b17a918b26df1b9c21

@unknownbrackets
Copy link
Collaborator

This probably isn't strictly atrac related. It's decoding audio just fine afaict, it's just not sending it on to get output by the speakers. This is probably a bug in sceAudio or sceSas, but it's hard to tell.

A log with #define HLE_LOG_FORCE at the top of sceSas.cpp and sceAudio.cpp might be helpful.

-[Unknown]

@sum2012
Copy link
Collaborator

sum2012 commented Jan 17, 2016

I perfer to switch sceAudio and sceSas to "Verb." in logging channels
so that I don't need compile
log:
https://drive.google.com/file/d/0B3OaSdeV0L8kSDV2bGNyRlVjX1U/view?usp=sharing

@unknownbrackets
Copy link
Collaborator

Okay. I think Verbose is compiled off by default but that's fine.

39:39:968 SoundThread  D[SCESAS]: HLE\sceSas.cpp:317 0=__sceSasCoreWithMix(08a9d3c0, 08aaff00, 3276, 3276)
39:39:968 SoundThread  D[SCESAS]: HLE\sceSas.cpp:268 fffff401=sceSasGetEndFlag(08a9d3c0)
39:39:968 SoundThread  D[AUDIO]: HLE\sceAudio.cpp:341 sceAudioOutput2OutputBlocking(00008000, 08aaff00)

So it's sending the output of SAS to the speaker. Do sound effects work?

Atrac is decoding to 0x08df17c0, and there are no PCM voices. sceAudioOutput2OutputBlocking is single channel, so it's only sending the SAS mixer output. That means to me that 08aaff00 is meant to be pre-populated with the atrac decode result.

If you set a breakpoint at 0x08df17c0 with size=0x00002000, and uncheck "Write", does it break? If so, where? That's where we should be expecting it to read the atrac data in.

We could also try checking a "Write" breakpoint for the SAS mix input, but that seems to use a rolling buffer and SAS will be writing to it too.

-[Unknown]

@sum2012
Copy link
Collaborator

sum2012 commented Jan 17, 2016

No audio and no sound effects in in-game.
"breakpoint at 0x08df17c0 with size=0x00002000" it hit before in-game so that it has sound
1

@unknownbrackets
Copy link
Collaborator

What if you keep it disabled (you can uncheck the box next to it at the bottom) until it's in game and doesn't have sound?

This looks like it's copying the data. This looks like what we would want to be happening while it's in game.

-[Unknown]

@sum2012
Copy link
Collaborator

sum2012 commented Jan 17, 2016

3

@unknownbrackets
Copy link
Collaborator

So, it is copying then. Strange. Maybe it's a timing issue...

-[Unknown]

@CoCoNO
Copy link
Author

CoCoNO commented Jan 19, 2016

While ingame the sound thread is asleep, is there any way to manually wake it up??

@unknownbrackets
Copy link
Collaborator

Someone must be responsible for waking it. But in the debugger, you can try force waking it by right clicking on it under the Threads tab. You must pause first and then resume.

-[Unknown]

@CoCoNO
Copy link
Author

CoCoNO commented Jun 26, 2016

It doesnt work, You cant try to force the tread to wake up but it will go back to sleep immediately

@unknownbrackets
Copy link
Collaborator

Hmm. Well, in that case it's possible something else is already waking it up, but it's just not doing anything.

So it sounds like it's decoding, but for some reason not outputting. Like some flag wasn't set right. It's tricky to find these flags, I'm not sure how to explain the process...

-[Unknown]

@sum2012
Copy link
Collaborator

sum2012 commented Jun 28, 2016

@unknownbrackets jpcsp no problem so
How about this change ?
mirror/jpcsp@685caea

@hrydgard
Copy link
Owner

Huh, that's really interesting. I had no idea that was supposed to work.

@CoCoNO
Copy link
Author

CoCoNO commented Jun 29, 2016

So, is problem caused by multiple threads trying to output sound and crashing the sound thread?

The sound does work ingame in jpcsp but the game is un-playably slow and reduced to a low res window

Also in previous builds of ppsspp the game would crash the moment the emulator finished loading, unless you had a special build that had its entire sound system removed, so this makes sense
http://forums.ppsspp.org/showthread.php?tid=430&pid=87693#pid87693

@unknownbrackets unknownbrackets added the Needs hardware testing Testing on a real device needed to determine correct behavior. label Jun 29, 2016
@unknownbrackets
Copy link
Collaborator

Hmm, does that mean they're supposed to mix separately? We can verify if this is happening by checking here in __sceAudio.cpp:

if (chan.sampleQueue.size() > 0) {

    if (chan.sampleQueue.size() > 0) {

Add below:

        NOTICE_LOG(HLE, "Blocking thread for audio output");

Below that, find this part:

            // Non-blocking doesn't even enqueue, but it's not commonly used.
            return SCE_ERROR_AUDIO_CHANNEL_BUSY;
        }
    }

And change to:

            // Non-blocking doesn't even enqueue, but it's not commonly used.
            return SCE_ERROR_AUDIO_CHANNEL_BUSY;
        }
    } else {
        NOTICE_LOG(HLE, "Submitting audio");
    }

What will be interesting is if the log alternates between the two notice logs, or if they show on multiple threads.

But, I would expect this to cause choppy, not entirely missing, audio? Not sure though, would need to test.

-[Unknown]

@unknownbrackets
Copy link
Collaborator

Well, that only shows one thread... hmm.

-[Unknown]

@unknownbrackets
Copy link
Collaborator

unknownbrackets commented Jul 10, 2016

sceAudioOutput2Reserve(00000100)
sceAudioOutput2Release()
sceAudioOutput2Reserve(00000800)
sceAudioOutput2Release()
sceAudioOutput2Reserve(00000100)
sceAudioOutput2Release()
sceAudioOutput2Reserve(00000800)
sceAudioOutput2Release()
sceAudioOutput2Reserve(00000100)
sceAudioOutput2Release()

So it turns out, the problem is that the channel is not actually reserved. Seems like whatever should be reserving it, isn't, or perhaps we're not handling some error scenario where it isn't reserved incorrectly (or maybe reserve is by thread? Doubtful...)

-[Unknown]

@hrydgard
Copy link
Owner

Actually it's not so strange if reserve would be per thread.... As the API is blocking, you need a thread per channel anyway, and presumably this sceAudioOutput2 is a successor to the old sceAudioOutput APIs where you had to manually manage channels. So it actually makes quite a lot of sense if the new API is also to have a multichannel capability...

@unknownbrackets
Copy link
Collaborator

unknownbrackets commented Jul 10, 2016

Well, I mean based on the threads it's reserving and releasing from. I think the sample count would be wrong if it were per thread, since it doesn't release from the same thread as it reserves from each time, and the sample counts are different.

-[Unknown]

@hrydgard
Copy link
Owner

Well, the release calls don't specify a number of samples so you can't tell which release belongs to which reserve that way. If it works this way, in the background it'll really open one channel for each thread, jsut hiding the channel allocations from the user...

@unknownbrackets
Copy link
Collaborator

unknownbrackets commented Jul 10, 2016

You're right, if it maintains the sample count per thread or something.

Here are the thread names (sorry didn't give full picture before...):

SoundThread  N[AUDIO]: sceAudioOutput2Reserve(00000100)     
SoundThread  N[AUDIO]: sceAudioOutput2Release()             
09F67C80     N[AUDIO]: sceAudioOutput2Reserve(00000800)     <-- generally, videos
user_main    N[AUDIO]: sceAudioOutput2Release()             <-- end of video
SoundThread  N[AUDIO]: sceAudioOutput2Reserve(00000100)     
SoundThread  N[AUDIO]: sceAudioOutput2Release()             
09F67C80     N[AUDIO]: sceAudioOutput2Reserve(00000800)     <-- another on video thread
user_main    N[AUDIO]: sceAudioOutput2Release()             
SoundThread  N[AUDIO]: sceAudioOutput2Reserve(00000100)     
user_main    N[AUDIO]: sceAudioOutput2Release()             

So yes, if it's per thread maybe the second one on 09F67C80 is just an error, and the ones on user_main do nothing...

(FWIW this happens in the Arctic Edge demo.)

-[Unknown]

@unknownbrackets
Copy link
Collaborator

unknownbrackets commented Jul 13, 2016

Confirmed via a brief test that there's no per-thread reserving:

» `output2threads.cpp` (expand/collapse)
#include <common.h>
#include <pspaudio.h>
#include <pspthreadman.h>

enum MsgType {
    MSG_RESERVE,
    MSG_RELEASE,
    MSG_QUIT,
};

struct Msg {
    Msg(MsgType ty, int i1 = 0) {
        memset(&header, 0, sizeof(header));
        type = ty;
        int1 = i1;
    }

    SceKernelMsgPacket header;
    MsgType type;
    int int1;
};

struct ThreadInfo {
    int thnum;
    SceUID mbox;
};

int threadFunc(SceSize args, void *argp) {
    ThreadInfo *info = (ThreadInfo *)argp;
    Msg *msg;

    while (sceKernelReceiveMbx(info->mbox, (void **)&msg, NULL) == 0) {
        switch (msg->type) {
        case MSG_QUIT:
            info->mbox = 0;
            break;

        case MSG_RESERVE:
            checkpoint("  [%d] Reserve: %08x", info->thnum, sceAudioOutput2Reserve(msg->int1));
            break;

        case MSG_RELEASE:
            checkpoint("  [%d] Release: %08x", info->thnum, sceAudioOutput2Release());
            break;

        default:
            checkpoint("  [%d] Unknown msg type %d", info->thnum, msg->type);
            break;
        }

        delete msg;
    }

    return 0;
}

extern "C" int main(int argc, char *argv[]) {
    SceUID thread1 = sceKernelCreateThread("thread1", &threadFunc, 0x1a, 0x1000, 0, NULL);
    SceUID thread2 = sceKernelCreateThread("thread2", &threadFunc, 0x1a, 0x1000, 0, NULL);

    ThreadInfo info1 = { 1 };
    info1.mbox = sceKernelCreateMbx("mbx1", 0, NULL);
    ThreadInfo info2 = { 2 };
    info2.mbox = sceKernelCreateMbx("mbx2", 0, NULL);

    sceKernelStartThread(thread1, sizeof(ThreadInfo), &info1);
    sceKernelStartThread(thread2, sizeof(ThreadInfo), &info2);

    sceKernelSendMbx(info1.mbox, new Msg(MSG_RESERVE, 0x100));
    sceKernelSendMbx(info2.mbox, new Msg(MSG_RESERVE, 0x800));

    sceKernelSendMbx(info1.mbox, new Msg(MSG_RELEASE));
    sceKernelSendMbx(info2.mbox, new Msg(MSG_RELEASE));

    sceKernelSendMbx(info1.mbox, new Msg(MSG_RESERVE, 0x100));
    sceKernelSendMbx(info2.mbox, new Msg(MSG_RELEASE));
    sceKernelSendMbx(info2.mbox, new Msg(MSG_RESERVE, 0x800));
    sceKernelSendMbx(info1.mbox, new Msg(MSG_RELEASE));

    sceKernelSendMbx(info1.mbox, new Msg(MSG_QUIT));
    sceKernelSendMbx(info2.mbox, new Msg(MSG_QUIT));

    return 0;
}

Results:

[x]   [1] Reserve: 00000000
[x]   [2] Reserve: 80268002
[x]   [1] Release: 00000000
[x]   [2] Release: 80260008
[x]   [1] Reserve: 00000000
[x]   [2] Release: 00000000
[x]   [2] Reserve: 00000000
[x]   [1] Release: 00000000

The above shows it treat reserving as a global thing. So definitely seems like either it should be releasing that last time, or else it should be reserving again somewhere.

PS: We currently fail this test because we don't error on double-release. I don't think that's a problem here, though.

-[Unknown]

@unknownbrackets
Copy link
Collaborator

unknownbrackets commented Jul 13, 2016

The correct sequence from JpcspTrace is:

02:07:55.422545 SoundThread - <- sceAudioOutput2Reserve 0x100 = 0x0
02:08:07.076553 SoundThread - <- sceAudioOutput2Release = 0x0
02:08:08.062674 09F63280 - <- sceAudioOutput2Reserve 0x800 = 0x0
02:08:14.801130 user_main - <- sceAudioOutput2Release = 0x0
02:08:14.801246 SoundThread - <- sceAudioOutput2Reserve 0x100 = 0x0
02:08:19.109222 SoundThread - <- sceAudioOutput2Release = 0x0
02:08:21.045656 09F63280 - <- sceAudioOutput2Reserve 0x800 = 0x0
02:09:15.845421 user_main - <- sceAudioOutput2Release = 0x0
02:09:15.845539 SoundThread - <- sceAudioOutput2Reserve 0x100 = 0x0

So, the final sceAudioOutput2Release() on user_main shouldn't be happening...

Edit: Hmm, but the sceMpegFinish right before it IS supposed to happen and I don't see how it could skip the release in that case...

-[Unknown]

@ppmeis
Copy link
Contributor

ppmeis commented Oct 21, 2018

It's been a long time since latest commend but...Tested with latest build, no sound or music ingame:

image

@dEFLASH
Copy link

dEFLASH commented Mar 16, 2019

Check this folks.
Made a save file to skip loading freeze bug, cheat+config files giving 25+ FPS and good sound without lag.
PSP.zip
Screenshot_20190316-153132

If loading still stuck - change IO timing settings in "system settings"

@unknownbrackets
Copy link
Collaborator

It seems this actually had the same cause as #6842, release when busy should not actually release. My guess is, it's a bug in the game and no one noticed because it silently didn't release.

-[Unknown]

@sum2012
Copy link
Collaborator

sum2012 commented Jul 1, 2019

Thanks @unknownbrackets @hrydgard
Here is the error log of v1.8.0-371-g0abdcbb3a-windows-amd64
42:03:892 user_main E[SCEAUDIO]: hle\sceaudio.cpp:377 80268002=sceAudioOutput2Release(): output busy

@unknownbrackets
Copy link
Collaborator

Great, that's exactly what's expected. The game is calling that function in a way that should cause that error.

-[Unknown]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

8 participants