MotorStorm artic edge Playable but wo/ sound

[CoCoNO]

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]

using v1.0-38-g05fc4cf on win x64

[CoCoNO]

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

[hrydgard]

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

[sum2012]

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]

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]

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

[CoCoNO]

Problem persist in 1.1.1

[unknownbrackets]

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

-[Unknown]

[daniel229]

The log

full log ppsspplog.txt

[csenech]

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]

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

[unknownbrackets]

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]

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]

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]

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

[unknownbrackets]

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]

[unknownbrackets]

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

-[Unknown]

[CoCoNO]

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

[unknownbrackets]

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]

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

[unknownbrackets]

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]

@unknownbrackets jpcsp no problem so How about this change ? https://github.com/mirror/jpcsp/commit/685caeac817f44bc1125a89d1c6319b8b5d3d4b2

[hrydgard]

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

[CoCoNO]

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]

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

https://github.com/hrydgard/ppsspp/blob/fa6fe85dc3f15977345acd6678b7fad15e8abd05/Core/HLE/__sceAudio.cpp#L194

    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]

[sum2012]

@unknownbrackets log: https://gist.githubusercontent.com/sum2012/46ce3b7ca4acc9bef0eac47a1955b881/raw/acba8762f96d05088aa19082549b77e9347e1d35/gistfile1.txt

[unknownbrackets]

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

-[Unknown]

[unknownbrackets]

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]

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]

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]

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]

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]

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

» `output2threads.cpp` (expand/collapse)

``` c++ #include #include #include 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]

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]

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

[dEFLASH]

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

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

[unknownbrackets]

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]

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]

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

-[Unknown]