Bust-A-Move Deluxe videos not working

[unknownbrackets]

Reported in #3338.

Details from @raven02:

video is not working and suppose to playback TAITO logo

the video stop with this error

58:25:385 user_main I[ME]: HLE\sceMpeg.cpp:368 sceMpegInit()
58:25:385 user_main I[ME]: HLE\sceMpeg.cpp:379 sceMpegRingbufferQueryMemSize(4800)
58:25:385 user_main I[ME]: HLE\sceMpeg.cpp:1132 sceMpegQueryMemSize()
58:25:385 user_main I[IO]: HLE\sceIo.cpp:842 stdout: Can't allocate memory for Mpeg Ring Buffer
58:25:385 user_main I[ME]: HLE\sceMpeg.cpp:1123 sceMpegFinish(...)

Details from @sum2012:

JPCSP trace log of Bust-A-Move(psp hang) 05:54:47 user_main - sceMpegRingbufferQueryMemSize 0x12C0 = 0x9D9E00 05:54:47 user_main - sceMpegQueryMemSize = 0xB3DB

PPSSPP Log: https://gist.github.com/sum2012/c42b577c857a2f4b8283 08:36:140 user_main N[ME]: HLE\sceMpeg.cpp:377 10329600 = sceMpegRingbufferQueryMemSize(4800) 08:36:140 user_main N[ME]: HLE\sceMpeg.cpp:1130 65536 = sceMpegQueryMemSize()

Seem only sceMpegQueryMemSize result differcult

JPCSP no problem log: https://gist.github.com/sum2012/f3563ca747598605954c Hmm

06:20:26 INFO hle.sceMpeg - user_main - sceMpegInit
06:20:26 DEBUG hle.sceMpeg - user_main - finishMpeg
06:20:26 DEBUG hle.sceMpeg - user_main - finishStreams
06:20:26 DEBUG hle.sceMpeg - user_main - sceMpegRingbufferQueryMemSize packets=0x12C0
06:20:26 DEBUG hle.sceMpeg - user_main - sceMpegQueryMemSize mode=0x0
06:20:26 DEBUG hle.sceMpeg - user_main - sceMpegRingbufferConstruct ringbufferAddr=0x088CF2C8, packets=0x12C0, data=0x0913FE80, size=0x9D9E00, callbackAddr=0x0885C800, callbackArgs=0x88CF28C
06:20:26 DEBUG hle.sceMpeg - user_main - sceMpegCreate mpeg=0x088CF2FC, data=0x09B19C90, size=0x10000, ringbufferAddr=0x088CF2C8, frameWidth=0x200, mode=0x0, ddrtop=0x0
06:20:26 DEBUG hle.sceMpeg - user_main - finishStreams
06:20:26 DEBUG hle.sceMpeg - user_main - sceMpegAvcDecodeMode mpeg=0x88CF2FC, modeAddr=0x088CF29C
06:20:26 DEBUG hle.sceMpeg - user_main - sceMpegQueryStreamOffset mpeg=0x88CF2FC, bufferAddr=0x09FFEDD0, offsetAddr=0x088CF304
06:20:26 INFO hle.scePsmf - user_main - Found PSMF MPEG video stream data: streamID=0xE0, privateStreamID=0x0, unk1=0x20, unk2=0xFB, EPMapOffset=0x0, EPMapEntriesNum=0, videoWidth=480, videoHeight=272
06:20:26 INFO hle.scePsmf - user_main - Found PSMF MPEG audio stream data: streamID=0xBD, privateStreamID=0x0, unk1=0x20, unk2=0x4, audioChannelConfig=2, audioSampleFrequency=2
06:20:26 INFO hle.sceMpeg - user_main - Using MPEG file for streaming: UmdIsoVirtualFile[UmdIsoFile(name='null', length=0x137800, startSector=0x81B0), sectorBlockMode=false]

-[Unknown]

Bust A Move Deluxe - USA 1.00

[sum2012]

Update the full debug log to v1.2.2-607-g21ba67e https://drive.google.com/file/d/0B3OaSdeV0L8kN1FrNEotaFJVYlU/view?usp=sharing

[unknownbrackets]

sceKernelAllocPartitionMemory(partition = 2, UserSbrk, type= 3, size= 23068672, addr= 00001000)

Does Jpcsp also create a UserSbrk of this size? If so, it seems like the game can't allocate internally 10329600 bytes from this buffer (which is already almost all of RAM.)

Maybe this is a timing issue... maybe some internal thing hasn't freed whatever memory it's using yet?

-[Unknown]

[sum2012]

I add logging to check 21:15:29 ERROR hle.SysMemUserForUser - user_main - sceKernelAllocPartitionMemory partitionid, 2 name UserSbrk type 3 size 23068672 add 00001000) 21:15:29 ERROR hle.SysMemUserForUser - user_main - returning 18 seem allocate no problem

[sum2012]

@unknownbrackets Yes,"Simuate umd delay" fix it. full debug log: https://drive.google.com/file/d/0B3OaSdeV0L8ka2xNT1FfUUN0V1k/view?usp=sharing

[benderscruffy]

v1.5.4-933-g386c9d4fc still present the problem

[shinra358]

still an issue in 1.6

[benderscruffy]

just wondering if this can be closed and add to #7647 as this works with Simuate umd delay @unknownbrackets would a JPCSPtrace help this out ???

[unknownbrackets]

Yeah - especially if it traced sceIo functions. That said, it might alter their timing...

-[Unknown]

[benderscruffy]

here is a JpcspTrace with a few sceIO functions log.zip log1.zip

[unknownbrackets]

Ah, it's harder to tell without the log before/after each syscall. The version in my fork does that: https://github.com/unknownbrackets/JpcspTrace

-[Unknown]

[benderscruffy]

ok i used your version of JpcspTrace log.zip

[unknownbrackets]

Based on that log, average timings:

Microseconds per byte:

• Average 1.3964
• Max 14.719
• Min 0.0718

Microseconds per sector assuming a full sector read:

• Average 0.6903
• Max 3.229
• Min 0.0718

And total overall timings (there's surely some factor of overhead):

• Average 4096
• Max 21415 (21ms)
• Min 869

Currently, our timing (which is based on memory stick access) is definitely much faster:

• 0.001us per byte
• +100000us (0.1s) if more than 204800 bytes distant from last read (interestingly this is higher than ANY max in that log)
• The 304 byte read (should be 869us) would've been 3us
• The 95533 byte read (should be 21415us) would've been 955us

I think it'd be worth trying just increasing the time for ISO by 20x, which might be more realistic. If you want to give this a shot, open Core/FileSystems/ISOFileSystem.cpp and find:

https://github.com/hrydgard/ppsspp/blob/bb5b981efa82ce9ca1b2ef8a457a1a59ae9c9573/Core/FileSystems/ISOFileSystem.cpp#L476-L477

Add right below that:

	usec = size / 2 + 400;
	if (usec < 600) {
		usec = 600;
	}

That won't increase the read speeds for memory stick access, but it will increase it for all ISO/UMD access. But it might be that aligning to a sector is more realistic.

-[Unknown]

[benderscruffy]

sorry im not good at things like that if you could change it and upload the new version of ppsspp here i can test it thanks

[sum2012]

Tested @unknownbrackets changed,no change @benderscruffy the change build of win 64 bit

https://drive.google.com/file/d/1Duz2fiXM248Itc2hwqOSuMXQ0hMIYnqd/view?usp=sharing

[benderscruffy]

yep there was no change

[sum2012]

PPSSPP v1.10.3-1395-g1ba290a45 Windows 64 bit still not working. log: https://gist.github.com/sum2012/01fda17681bbc47bbcbdd5dbcf08c03d

Simuate umd delay log: https://gist.github.com/sum2012/a650c52218cfffa5b876ed95849c9d57

[unknownbrackets]

Hm, the difference in those is:

48:42:185 ThreadFunc   I[SCEKERNEL]: hle\scekernelthread.cpp:2168 sceKernelExitThread(1)
48:45:637 user_main    E[SCEKERNEL]: hle\scekernelthread.cpp:2774 sceKernelSuspendThread(321): thread not running

It seems like ThreadFunc fails (exit 1 usually means an error) and then it can't be suspended.

Just to confirm, if you comment out this line: https://github.com/hrydgard/ppsspp/blob/679a952dc11519d41b9bebebb587e5644a80c020/Core/FileSystems/ISOFileSystem.cpp#L570

It makes "Simulate UMD Delays" not work, right? How low can you make 100000 and it still works? Does 10000 work?

-[Unknown]

[sum2012]

comment that line ,"Simulate UMD Delays" not work

My lowest value that work is 88463

It get a bluescreen in 87000

[ghost]

Add this game id to [ForceUMDDelay] fixes this issue.

[benderscruffy]

Add this game id to the compat.ini [ForceUMDDelay] this will fix it

[sum2012]

I think that we might be need to check the mpeg.prx crc

[hrydgard]

True, there might be multiple versions with different behaviors...

[sum2012]

I don't know that how to do crc of disc0:/PSP_GAME/USRDIR/module/mpeg.prx old code uint32_t crcvalue = Reporting::RetrieveCRC(gamepath) cannot do it.

[sum2012]

Anyway update full debug of v1.13.1-653-g5200208a8 (bad) and good ("Simulate UMD Delays" ) ppssppBADlog.zip ppssppGOODlog.zip

[sum2012]

Update full debug log to v1.13.2-1304-g16f93a268 bad and good ("Simulate UMD Delays" ) ppsspp_bad_log.zip ppssppgoodlog.zip

[sum2012]

v1.14.4-106-g765bfac01 still same. Some info update, 18:12:998 user_main I[ME]: HLE\sceMpeg.cpp:462 sceMpegInit(), mpegLibVersion 0x104, mpegLibcrc 99de104f