Skip to content

Code Lyoko audio softlock (now: bad playback) #19994

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

Closed
5 tasks done
Tracked by #20125
Xibancry opened this issue Feb 17, 2025 · 32 comments
Closed
5 tasks done
Tracked by #20125

Code Lyoko audio softlock (now: bad playback) #19994

Xibancry opened this issue Feb 17, 2025 · 32 comments
Labels
Atrac3+ Issue involves sceAtrac features.
Milestone

Comments

@Xibancry
Copy link

Game or games this happens in

ULES-01095 - Code Lyoko: Quest for Infinity

What area of the game / PPSSPP

Many areas affected. Only when some voice audio tracks play. The text box showing dialogue appears but it fails to play the voice audio preventing it from closing and effectively softlocking the game everytime it happens (this is apparently consistent with some dialogues). Only solution around it is to reset the game.

Adding a savefile previous to softlock. Softlock occurs on the third dialogue just after defeating the first enemy in the level.

ULES01095DATA00.zip

What should happen

The game should play the dialogue normally without preventing the dialogue box from closing and not softlocking the game.

Logs

ppsspplog.txt

Platform

Windows

Mobile device model or graphics card (GPU)

RTX 2080 Super

PPSSPP version affected

v1.18.1 - 0f50225

Last working version

v1.16.6

Graphics backend (3D API)

Direct3D 11

Checklist

  • Test in the latest git build in case it's already fixed.
  • Search for other reports of the same issue.
  • Try resetting settings or older versions and include if the issue is related.
  • Try without any cheats and without loading any save states.
  • Include logs or screenshots of issue.
@sum2012
Copy link
Collaborator

sum2012 commented Feb 17, 2025

@Xibancry
"Sector 5" or "Deseat sector" lock up ?
edit: should be "Sector 5"

@Xibancry
Copy link
Author

Yes, it's on sector 5 for the savefile I sent. It's not the only place it happens

@sum2012
Copy link
Collaborator

sum2012 commented Feb 17, 2025

Media log easier to check
https://gist.githubusercontent.com/sum2012/de3af54e161e8eacb48086b34315397f/raw/17207eac434bdb4fee0ab0cfb2b688f2543a19fb/gistfile1.txt

18:26:659 ATRAC3 Load D[ME]: HLE\AtracCtx.cpp:235 ATRAC analyzed: AT3Plus channels: 2 filesize: 70164 bitrate: 94 kbps jointStereo: 0
18:26:659 ATRAC3 Load D[ME]: HLE\AtracCtx.cpp:236 dataoff: 164 firstSampleOffset: 4011 endSample: 251620
18:26:659 ATRAC3 Load D[ME]: HLE\AtracCtx.cpp:237 loopStartSample: 4379 loopEndSample: 255999
18:26:659 ATRAC3 Load I[ME]: HLE\AtracCtx.cpp:699 0=sceAtracSetDataAndGetID(08a5c340, 00000800): atrac3+ stereo audio
18:26:659 ATRAC3 Load D[ME]: HLE\sceAtrac.cpp:702 00000000=sceAtracSetLoopNum(0, -1)
18:26:659 ATRAC3 Load D[ME]: HLE\sceAtrac.cpp:463 00000000=sceAtracGetRemainFrame(0, 08a5c1dc[00000002])
18:26:677 ATRAC3 play D[ME]: HLE\sceAtrac.cpp:281 00000000=sceAtracDecodeData(0, 08a7c380, 09fb7aa8[000006e5], 09fb7aac[00000000], 09fb7abc[1])
18:26:693 ATRAC3 play D[ME]: HLE\sceAtrac.cpp:532 00000000=sceAtracGetStreamDataInfo(0, 09fb7ab8[08a5c40c], 09fb7ab4[00000438], 09fb7ab0[00000800])
18:26:693 ATRAC3 play E[ME]: at3_standalone\compat.cpp:19 Atrac3/3+: Frame data doesn't match channel configuration!
18:26:693 ATRAC3 play D[ME]: HLE\sceAtrac.cpp:281 80630024=sceAtracDecodeData(0, 08a7df14, 09fb7aa8[00000000], 09fb7aac[00000001], 09fb7abc[0])
18:26:693 ATRAC3 play E[ME]: HLE\sceAtrac.cpp:382 UNIMPL sceAtracGetInternalErrorInfo(0, 09fb7aa4)
18:26:694 ATRAC3 play D[ME]: HLE\sceAtrac.cpp:253 00000000=sceAtracAddStreamData(0, 00000438)
18:26:694 ATRAC3 play D[ME]: HLE\sceAtrac.cpp:463 00000000=sceAtracGetRemainFrame(0, 09fb7abc[00000003])

ATRAC3 related

@sum2012 sum2012 added the Atrac3+ Issue involves sceAtrac features. label Feb 17, 2025
@sum2012
Copy link
Collaborator

sum2012 commented Feb 18, 2025

Even v1.16.6 don't softlock, the voice has some problem

@sum2012
Copy link
Collaborator

sum2012 commented Feb 18, 2025

v1.17.1-264 good
v1.17.1-268 bad
It mean #19053

@sum2012
Copy link
Collaborator

sum2012 commented Feb 18, 2025

git bisect result: a1ac79c

@hrydgard
Copy link
Owner

Thank you for the bisect, not surprising, it's when we switched the decoder to not use ffmpeg.

I think this is another case of not detecting mono properly, so the decoder tries to parse it as stereo and fails. Will need to figure out how it worked before..

@sum2012
Copy link
Collaborator

sum2012 commented Feb 18, 2025

@hrydgard Before it cannot decode mono correctly , but it do not have error .

@sum2012
Copy link
Collaborator

sum2012 commented Feb 18, 2025

@hrydgard I have a idea. For streamed ATRAC3+ , I think that we do not change track_.channels , so it assume stereo.
edit: No, 8:26:659 ATRAC3 Load I[ME]: HLE\AtracCtx.cpp:699 0=sceAtracSetDataAndGetID(08a5c340, 00000800): atrac3+ stereo audio So it detect wrong the atrac as stereo not mono early ?

@sum2012
Copy link
Collaborator

sum2012 commented Feb 18, 2025

Force to change to mono still fail.

		if (!decoder_->Decode(indata, track_.bytesPerFrame, &bytesConsumed, outputChannels_, (int16_t*)outbuf, &outSamples)) {
			track_.channels = 1;
			if (!decoder_->Decode(indata, track_.bytesPerFrame, &bytesConsumed, outputChannels_, (int16_t*)outbuf, &outSamples)) {			
			// Decode failed.
			*SamplesNum = 0;
			*finish = 1;
			return ATRAC_ERROR_ALL_DATA_DECODED;
			}
		}

@sum2012
Copy link
Collaborator

sum2012 commented Feb 19, 2025

Ignore decode error can work around....Before v1.19 release make the hack ?

@hrydgard
Copy link
Owner

If we can't fix it, yeah.

@hrydgard hrydgard added this to the v1.19.0 milestone Feb 19, 2025
hrydgard added a commit that referenced this issue Feb 19, 2025
Now we don't generate an error code when the channel configuration doesn't match the packets.

See the code comment for what I've been able to figure out so far.

See issue #19994
@hrydgard
Copy link
Owner

#20005 will probably work as a workaround, but I don't think it'll fix broken audio.. Something is really going wrong in decoding here.

@sum2012
Copy link
Collaborator

sum2012 commented Feb 19, 2025

#20005 work as a workaround
Jpcsp emulator play the voice correctly
PPSSPP never play the voice correctly

@sum2012
Copy link
Collaborator

sum2012 commented Feb 19, 2025

Jpcsp emulator log
https://gist.githubusercontent.com/sum2012/77328a1337e7dd96b2252bba4e7c4dd2/raw/52b997c6216503e05bbb0dbb31bb5d469a90d80d/gistfile1.txt

edit:
#20005 Warn log this two times , then it can play the bad voice
53:30:276 ATRAC3 play W[ME]: at3_standalone\compat.cpp:23 Atrac3/3+: Frame data doesn't match channel configuration! ch_block 1 >= num_channel_blocks 1,

From JPCSP emulator log, channels=2 all the times

@hrydgard
Copy link
Owner

Hm. Might have to dig into how JPCSP handles this then... Thanks for letting me know.

@sum2012
Copy link
Collaborator

sum2012 commented Feb 19, 2025

Can you code (logging) the data of the "data chunk" in PPSPPP so that I can compare it in JPCSP emulator ?

5:05:40 DEBUG hle.sceAtrac3plus - ATRAC3 Load thread - sceAtracSetDataAndGetID buffer=0x08A5C340, bufferSize=0x800
05:05:40 DEBUG hle.sceAtrac3plus - ATRAC3 Load thread - FileSize 0xA5BE4
05:05:40 DEBUG hle.sceAtrac3plus - ATRAC3 Load thread - WAVE format: magic=0x20746D66('fmt '), chunkSize=52, compressionCode=0xFFFE, channels=2, sampleRate=44100, bitrate=12058, bytesPerFrame=0x230, hiBytesPerSample=0, codingMode=0
05:05:40 DEBUG hle.sceAtrac3plus - ATRAC3 Load thread - Additional chunk data: 22 00 00 08 03 00 00 00 BF AA 23 E9 58 CB 71 44 A1 19 FF FA 01 E4 CE 62 01 00 28 45 00 00 00 00 00 00 00 00
05:05:40 DEBUG hle.sceAtrac3plus - ATRAC3 Load thread - FACT Chunk: chunkSize=8, endSample=0x25D391, sampleOffset=0xAFE
05:05:40 DEBUG hle.sceAtrac3plus - ATRAC3 Load thread - Loop #0: LoopInfo[cuePointID 0, type 0, startSample 0x0, endSample 0x25D391, fraction 0, playCount 0]
05:05:40 DEBUG hle.sceAtrac3plus - ATRAC3 Load thread - DATA Chunk: data offset=0xA4, data size=0xA5B40
05:05:40 DEBUG hle.sceAtrac3plus - ATRAC3 Load thread - hleSetHalfwayBufferAndGetID returning atID=0x0

@anr2me
Copy link
Collaborator

anr2me commented Feb 20, 2025

I don't know this code https://github.com/hrydgard/ppsspp/blob/master/Core/HLE/AtracCtx.cpp#L361 Why break after "}" ? Same with https://github.com/hrydgard/ppsspp/blob/master/Core/HLE/AtracCtx.cpp#L373 https://github.com/hrydgard/ppsspp/blob/master/Core/HLE/AtracCtx.cpp#L404

Probably because you can get compilation error when declaring and initializing a variable inside case without {}

@hrydgard
Copy link
Owner

It's nicer to have the break inside the {} of the case, but it doesn't really matter.

I'll look into this more in a little while.

@hrydgard
Copy link
Owner

Hm, jpcsp seems to handle the channel blocks exactly the same:

https://github.com/jpcsp/jpcsp/blob/cd20cf312b358b4260f26f6754f9c62926c70ba6/src/jpcsp/media/codec/atrac3plus/Atrac3plusDecoder.java#L96

Wonder what is different..

@sum2012
Copy link
Collaborator

sum2012 commented Feb 21, 2025

edit last: I know what is the problem

sum2012 added a commit to sum2012/ppsspp that referenced this issue Feb 21, 2025
Easy to compare JPCSP emulator log. Debugging in hrydgard#19994
@hrydgard
Copy link
Owner

So what is it? :)

I merged your logging change.

@sum2012
Copy link
Collaborator

sum2012 commented Feb 21, 2025

Updated PPSSPP log:
https://gist.github.com/sum2012/355e85c0347ccdacadf8a249018796e0
Our code of "Additional chunk data" is match JPCSP emulator.

@sum2012
Copy link
Collaborator

sum2012 commented Feb 22, 2025

After update source, debug build (VS2022):
34:41:289 ATRAC3 play E[HLE]: HLE\HLE.cpp:992 HLE function stack mismatch (D:\project\9\ppsspp\Core\HLE\sceAtrac.cpp:253)! stackSize = 0

@hrydgard hrydgard modified the milestones: v1.19.0, v1.20 Feb 25, 2025
@hrydgard hrydgard changed the title Code Lyoko audio softlock Code Lyoko audio softlock (now: bad playback) Feb 25, 2025
@sum2012
Copy link
Collaborator

sum2012 commented Feb 26, 2025

edit : What is actual decode data address and size in Atrac::DecodeData() ?
edit2: Is the actual decode data address is indata and the size is track_.bytesPerFrame ?
edit3: JPCSP trace log level already done for default.We only do it in PPSSPP Side
edit4: JPCSP load problem in this game in master....need apply my speed patch

@sum2012
Copy link
Collaborator

sum2012 commented Mar 1, 2025

So the error maybe in sceAtracGetStreamDataInfo()
edit:Try debug output in sceAtracGetStreamDataInfo() in beginning , same result , So we need remove dataBuf_ array, use the PSP RAM instread

@aktau
Copy link

aktau commented Mar 15, 2025

I don't know if I'm having the same problem. But I'll describe it shortly here:

(I'm running a freshly compiled ecbbadd (HEAD from two days ago) via a freshly compiled RetroArch. I'm using the Vulkan backend for video, PipeWire for audio on Linux, debian testing.)

With a lot of games, the PPSSPP core appears to lock up (makes no progress). It burns ~100% CPU. I took a perf profile:

Image

So it appears to be stuck decoding some audio. If it's not the same problem, I can try to supply more information. (There are no logs in retroarch/logs, so I assume I need a switch somewhere that passes to the PPSSPP core to be more verbose.

Differently to OP, for me the sotflock happens on a lot of different ROMs I tried (not all, OutRun 2006 Coast to Coast appears to work well most of the time.)

@hrydgard
Copy link
Owner

A hang inside decodeframe is very unexpected. But stay tuned, there will soon be a big update to atrac handling in general (#20098 ).

@aktau
Copy link

aktau commented Mar 18, 2025

OK, I guess I'll check it out once new code lands. Compiling HEAD from yesterday in debug mode, I can tell the softlock comes from a combination of:

  • A segfault.
  • sigsegv_handler not knowing what to do with it.

The segfault happens here (according to gdb):

Thread 1 "Main" received signal SIGSEGV, Segmentation fault.
0x00007eff164908d2 in ff_atrac3p_ipqf (dct_ctx=dct_ctx@entry=0x55e8f80b1e60, hist=hist@entry=0x55e8f80b62b0, in=in@entry=0x55e8f80a9d60, out=out@entry=0x55e8f80add60) at /home/aktau/github/libretro-super/libretro-ppsspp/ext/at3_standalone/atrac3plusdsp.cpp:649
649                 hist->buf2[hist_pos][i] = idct_out[7 - i];
(gdb) info args
dct_ctx = 0x55e8f80b1e60
hist = 0x55e8f80b62b0
in = 0x55e8f80a9d60
out = 0x55e8f80add60
(gdb) p hist
$1 = (Atrac3pIPQFChannelCtx *) 0x55e8f80b62b0
(gdb) p hist_pos
$2 = 0
(gdb) p i
$3 = <optimized out>

I decide to move to the next instruction, which is the sigsegv_handler:

(gdb) si
sigsegv_handler (sig=11, info=0x55e8f2e627b0, raw_context=0x55e8f2e62680) at /home/aktau/github/libretro-super/libretro-ppsspp/Common/ExceptionHandlerSetup.cpp:223

Then see where it goes in the handler:

(gdb) si
(gdb) ...
(gdb) p sicode
$4 = 128
(gdb) p SEGV_MAPERR+0
$6 = 1
(gdb) p SEGV_ACCERR+0
$7 = 2

We're now here:

│      228         int sicode = info->si_code;                                                                                                                                                                                                                                                                                 
│  >   229         if (sicode != SEGV_MAPERR && sicode != SEGV_ACCERR) {                                                                                                                                                                                                                                                       
│      230                 // Huh? Return.                                                                                                                                                                                                                                                                                     
│      231                 return;                                                                                                                                                                                                                                                                                             
│      232         }                                                                                                                                                                                                                                                                                                           

Since 128 is neither 1 nor 2, we return and the process begins a new, spinning at 100% CPU. The C code surrounding the crash is:

Update: si_code = 128 seems strange as I can't find it in the header file next to SEGV_MAPERR et al. Turns out it's SI_KERNEL (meaning: sent by the kernel). The stack overflow answer notes:

  1. Processor-specific traps
  2. kernel segment memory violation (except for semaphore access)
  3. ELF file format violations, and
  4. stack violations.

I suspect stack violation is what's going on here (see below).

642643         /* append the result to the history */644         const int hist_pos = hist->pos;                                                                                                                                                                                                                                                                             
│      645         for (i = 0; i < 8; i++) {                                                                                                                                                                                                                                                                                   
│      646             hist->buf1[hist_pos][i] = idct_out[i + 8];                                                                                                                                                                                                                                                              
│      647         }                                                                                                                                                                                                                                                                                                           
│      648         for (i = 0; i < 8; i++) {                                                                                                                                                                                                                                                                                   
│  >   649             hist->buf2[hist_pos][i] = idct_out[7 - i];                                                                                                                                                                                                                                                              
│      650         }                                                                                                                                                                                                                                                                                                           

The p i above shows <optimized out>, but perhaps the assembly is instructive:

0x7eff164908c8 <_Z15ff_atrac3p_ipqfP10FFTContextP21Atrac3pIPQFChannelCtxPKfPf+232>      vpermd 0x40(%rsp),%ymm4,%ymm0                                                                                                                                                                                                      
0x7eff164908cf <_Z15ff_atrac3p_ipqfP10FFTContextP21Atrac3pIPQFChannelCtxPKfPf+239>      mov    (%rbx,%rax,4),%edi                                                                                                                                                                                                          
│  >0x7eff164908d2 <_Z15ff_atrac3p_ipqfP10FFTContextP21Atrac3pIPQFChannelCtxPKfPf+242>      vmovaps %ymm0,0x300(%r15,%rsi,1)                                                                                                                                                                                                   
0x7eff164908dc <_Z15ff_atrac3p_ipqfP10FFTContextP21Atrac3pIPQFChannelCtxPKfPf+252>      lea    0x726d1d(%rip),%rsi        # 0x7eff16bb7600 <_ZL12ipqf_coeffs2>                                                                                                                                                             
0x7eff164908e3 <_Z15ff_atrac3p_ipqfP10FFTContextP21Atrac3pIPQFChannelCtxPKfPf+259>      vmovups (%r14),%xmm3                                                                                                                                                                                                               
0x7eff164908e8 <_Z15ff_atrac3p_ipqfP10FFTContextP21Atrac3pIPQFChannelCtxPKfPf+264>      vmovups 0x10(%r14),%xmm2

It looks like the compiler (gcc in my case) vectorized the snot out of his. It's hard to read. I can't even tell without squinting whether it's readin gfrom idct_out or writing to hist->buf2 that's doing it in. Though I suspect it's the latter since an earlier adjacent read from idct_out (646) worked.

(gdb) p &idct_out
$13 = (float (*)[16]) 0x7ffedf1faa20
(gdb) p idct_out
$12 = {1.12761927e-06, -2.9897044e-06, -8.07812012e-06, -2.06962591e-06, 4.44830812e-06, 3.54107806e-06, 2.21183518e-06, 1.62371941e-06, 9.54989446e-07, 1.73229841e-06, -2.40925374e-07, -3.72137038e-06, -1.49619018e-06, 3.10071709e-06, 3.9028123e-06, 2.96439862e-06}

(gdb) p &hist->buf2
$16 = (float (*)[24][8]) 0x55e8f80b65b0
(gdb) p hist->buf2
$17 = {{0, 0, 0, 0, 0, 0, 0, 0} <repeats 24 times>}

It's a little bit odd that one side is float[16] and the other is float[8]. Are we in addition on a page boundary? Back to the signal handler:

(gdb) si
(gdb) si
sigsegv_handler (sig=11, info=0x55e8f2e627b0, raw_context=0x55e8f2e62680) at /home/aktau/github/libretro-super/libretro-ppsspp/Common/ExceptionHandlerSetup.cpp:223
(gdb) p *info
$23 = {si_signo = 11, si_errno = 0, si_code = 128, __pad0 = 0, _sifields = {_pad = {0 <repeats 28 times>}, _kill = {si_pid = 0, si_uid = 0}, _timer = {si_tid = 0, si_overrun = 0,
      si_sigval = {sival_int = 0, sival_ptr = 0x0}}, _rt = {si_pid = 0, si_uid = 0, si_sigval = {sival_int = 0, sival_ptr = 0x0}}, _sigchld = {si_pid = 0, si_uid = 0,
      si_status = 0, si_utime = 0, si_stime = 0}, _sigfault = {si_addr = 0x0, si_addr_lsb = 0, _bounds = {_addr_bnd = {_lower = 0x0, _upper = 0x0}, _pkey = 0}}, _sigpoll = {
      si_band = 0, si_fd = 0}, _sigsys = {_call_addr = 0x0, _syscall = 0, _arch = 0}}}

I did not expect a null dereference, and I'm wondering if there isn't some shenanigangs going on due to -O3. As a last resort, I check /proc/$(pidof retroarch)/maps for 0x7ffedf1faa20. The closest match is:

  7eff193b3000-7eff193b4000 rw-p 00000000 00:00 0
> 7ffedf1db000-7ffedf1fd000 rw-p 00000000 00:00 0                          [stack]

Our address is somewhat close to the end of the mapping. The stack is apparently 0x22000 bytes, and we're 9696 bytes from the end:

$ le '0x7ffedf1fd000-0x7ffedf1faa20'
9696
$ le 'tohex(0x7ffedf1fd000 - 0x7ffedf1db000)'
0x22000

Remembering the vmovaps %ymm0,0x300(%r15,%rsi,1) from before, and finding the formula D ( Rb, Ri, S ) => (Reg[Rb]+S*Reg[Ri]+ D) for address offset calculation. I fill in:

0x300(%r15,%rsi,1) = %r15+1*%rsi+0x300
(gdb) p $r15
$33 = 94459082269360
(gdb) p $rsi
$34 = 0

The $rsi is large, I'm not sure how to interpret this. Either this is a program bug, or miscompilation, or there's some funky signed wrapping going on. Getting the opcode:

(gdb) disas /r
=> 0x00007eff164908d2 <+242>:   c4 c1 7c 29 84 37 00 03 00 00   vmovaps %ymm0,0x300(%r15,%rsi,1)

At this point I ran out of time, maybe later in the week.

@hrydgard
Copy link
Owner

Fixed since #20138 (though really fixed by #20098).

@hrydgard hrydgard modified the milestones: v1.20, v1.19.0 Mar 22, 2025
@aktau
Copy link

aktau commented Mar 24, 2025

I can confirm that the infinite loop through segfault is gone.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Atrac3+ Issue involves sceAtrac features.
Projects
None yet
Development

No branches or pull requests

5 participants