Hokuto no Ken Portable -ULJM05020 cannot in-game

[sum2012]

It never in-game in older ppsspp version .
JPCSP have this hint of game
21:17:53 INFO runtime - NowLoading - Pausing emulator - jump to self (death loop) at 0x088A5300
(Maybe ppsspp need add this in the log)
jpcsp only can use compiler debug log or open debugger to in-game

jpcsp compiler log
https://drive.google.com/file/d/0B3OaSdeV0L8kYmJ4LUpqb2ViMm8/view?usp=sharing

in the ppsspp log,I try to log all asslbly by logBlocks = 1;
https://gist.githubusercontent.com/sum2012/80ebf47a976616bfbca5c2146709a2dc/raw/c6451d4c4824e465ae7ac4d26386bcd631c6bf70/gistfile1.txt

v1.2.2-634-g606856c full debug log(238mb):
https://drive.google.com/file/d/0B3OaSdeV0L8kSHQ3TzJDdkFoQnc/view?usp=sharing

assumbly of 088a560c
edit:better:
http://s33.postimg.org/t8rwprfu7/image.png

Hokuto no Ken Portable - JP 1.03

[daniel229]

Lower cpu clock helps it.

[sum2012]

Thanks @daniel229
I set cpu 100 work
info log:
https://gist.github.com/sum2012/19263a70cdfe396fa6118f475a6b0ca6

[sum2012]

add the good assumbly log to compare bad one
https://drive.google.com/file/d/0B3OaSdeV0L8kcTBNck1XTlM4ZzQ/view?usp=sharing

[unknownbrackets]

=============== mips 088a5308 ===============
M: 088a5308   addiu sp, sp, -0x20             ; a0 often zero, not always for sure?
M: 088a530c   sw s5, 0x14(sp)
M: 088a5310   lui v0, 0x8B4
M: 088a5314   addiu v0, v0, 0x4BFC
M: 088a5318   sw s4, 0x10(sp)
M: 088a531c   move s5, a3
M: 088a5320   move s4, a2
M: 088a5324   sw s3, 0xC(sp)
M: 088a5328   li s3, 0
M: 088a532c   sw s2, 0x8(sp)
M: 088a5330   move s2, a0
M: 088a5334   sw s1, 0x4(sp)
M: 088a5338   sll s1, a0, 0x2                 <-- s1 = a0 * 4
M: 088a533c   addu v0, s1, v0
M: 088a5340   sw s0, 0x0(sp)
M: 088a5344   move s0, a1
M: 088a5348   sw ra, 0x18(sp)
M: 088a534c   lw v1, 0x0(v0)
M: 088a5350   beq v1, zero, ->$088a54f0
M: 088a5354   li v0, 0
=============== mips 088a5358 ===============
M: 088a5358   jal ->$088a6398
M: 088a535c   nop
=============== mips 088a5360 ===============
M: 088a5360   lui t2, 0x8B4
M: 088a5364   addiu v0, t2, 0x4C14            <-- v0 = 0x08b43c14
M: 088a5368   addu v0, s1, v0                 <-- v0 = 0x08b43c14 + s1
M: 088a536c   lw a3, 0x0(v0)                  <-- a3 = *v0
M: 088a5370   addiu v1, s0, 0x3F
M: 088a5374   srl v1, v1, 0x6
M: 088a5378   beq a3, zero, ->$088a5600
M: 088a537c   sll s0, v1, 0x6
=============== mips 088a5380 ===============
M: 088a5380   lh v0, 0x8(a3)                  <-- a3 must be an address
M: 088a5384   bltzl v0, ->$088a561c
M: 088a5388   lw a2, 0x0(a3)

=============== mips 088a561c ===============
M: 088a561c   sltu v0, a2, s0
M: 088a5620   bne v0, zero, ->$088a5390
M: 088a5624   lui t1, 0x8B4

=============== mips 088a5390 ===============
M: 088a5390   addiu v0, t1, 0x4C08            <-- t1 = 0x08b44c08
M: 088a5394   addu v0, s1, v0
M: 088a5398   lw v1, 0x0(v0)                  <-- v1 = *0x08b44c08
M: 088a539c   beq a3, v1, ->$088a5604         <-- BAD takes this branch (a3 == v1)
M: 088a53a0   lui a1, 0x8A6
=============== mips 088a53a4 ===============
M: 088a53a4   lw v0, 0x0(a3)
M: 088a53a8   addu a0, a3, v0
M: 088a53ac   addiu a3, a0, 0x40
M: 088a53b0   lh v0, 0x8(a3)
M: 088a53b4   bgez v0, ->$088a539c
M: 088a53b8   nop

=============== mips 088a5604 ===============
M: 088a5604   move a0, s2
M: 088a5608   addiu a1, a1, -0x1DF4
M: 088a560c   jal ->$088a5300                 <-- abort() or etc.
M: 088a5610   move a2, s0
=============== mips 088a5300 ===============
M: 088a5300   j ->$088a5300
M: 088a5304   nop

So it seems like it hangs when the value at 0x08b44c08 == the value at 0x08b43c14 (possibly, latter address may be off.) Sounds like a scheduling or timing issue for sure...

Something is probably writing to one of those two addresses when cpu = 100mhz, but not when it's the default mhz. If we knew what, it might help.

-[Unknown]

[sum2012]

0x08b43c14 don't hit "write address"
As hit address logged,so I can easier to compare:

log of hit 0x08b44c08 hit "write address"
default mhz (not work):
https://gist.github.com/sum2012/0e102c8b1fb5c1109726a65eed8d2129

100mhz (work):
https://gist.github.com/sum2012/edc7e1f09ca14db7d95ea93c0d5cff69

@unknownbrackets Unfortunately your thought
"Something is probably writing to one of those two addresses when cpu = 100mhz, but not when it's the default mhz" is wrong

[unknownbrackets]

NowLoading   D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
NowLoading   D[IO]:     278528 = sceIoLseek(4, 44000, 0)
main app     D[KERNEL]: Context switch: NowLoading -> main app (314->280, pc: 088a29e4->0889bec0, io seek) +57us
main app     D[KERNEL]: 0=sceKernelWaitSema(285, 1, 0)
main app     D[KERNEL]: sceKernelSignalSema(285, 1) (count: 0 -> 1)
main app     D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
main app     D[IO]:     95012864 = sceIoLseek(4, 5a9c800, 0)
idle0        D[KERNEL]: Context switch: main app -> idle0 (280->272, pc: 088a29e4->08000000, io seek) +54us
NowLoading   D[KERNEL]: Context switch: idle0 -> NowLoading (272->314, pc: 08000000->088a29e4, woke from hle delay) +45us
NowLoading   D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
NowLoading   D[IO]:     sceIoRead(4, 09fb8500, 5674): deferring result
idle0        D[KERNEL]: Context switch: NowLoading -> idle0 (314->272, pc: 088a2ad4->08000000, io read) +5us
main app     D[KERNEL]: Context switch: idle0 -> main app (272->280, pc: 08000000->088a29e4, woke from hle delay) +48us
main app     D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
main app     D[IO]:     7450=sceIoRead(4, 08d5db40, 7450)
idle0        D[KERNEL]: Context switch: main app -> idle0 (280->272, pc: 088a2ad4->08000000, io read) +5us
NowLoading   D[KERNEL]: Context switch: idle0 -> NowLoading (272->314, pc: 08000000->088a2ad4, idle) +166us

Woah, woah woah. They're both interacting with the same file handle at the same time. That doesn't look good. A more summarized play-by-play:

NowLoading: Seek file 4 to 0x00044000.
main app: Seek file 4 to 0x05a9c800.
NowLoading: Read 5674 bytes from file 4 [presumably from 0x00044000]. Actually reads from 0x05a9c800.
main app: Read 7450 bytes from file 4 [presumably from 0x05a9c800]. Actually reads from 0x05a9de2a.

So, that's probably what's really wrong (although I think it's resulting in those values becoming equal as per my notes above.)

Can you log just sceIo with 100 Mhz? I want to see how this sequencing works in that case.

A JpcspTrace of those functions would also help as well, to see correct sequencing.

sceIoRead 0x6A638D83 dxd
sceIoLseek 0x27EB27B8 dxxxd
sceKernelCreateThread 0x446D8DE6 sxxdxx
sceUmdWaitDriveStat 0x8EF08FCE x

If it doesn't work, try doing only the sceIo ones.

-[Unknown]

[sum2012]

I think that F8 may be missing to log of hit 0x08b44c08 hit "write address""
Can you help me to do in directly coding in ppsspp 's source to log it ?

Anyway ,
ppsspp sceio log with 100mhz: https://gist.github.com/sum2012/1dbfc572c13627efdbf272ec358971bd
JpcspTrace log: https://gist.github.com/sum2012/2a597b32d6c347d22b795e4daff3c439

[unknownbrackets]

In the working one, they aren't broken up:

main app     D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
main app     D[IO]:     149946368 = sceIoLseek(4, 8f00000, 0)
main app     D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
main app     D[IO]:     sceIoRead(4, 09abd700, 5bfd0): deferring result
main app     I[KERNEL]: 314=sceKernelCreateThread(NowLoading, 0889bd1c, 00000020, 4096, 00000000, 00000000)
main app     I[KERNEL]: 0=sceKernelStartThread(314, 0, 00000000)
NowLoading   D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
NowLoading   D[IO]:     278528 = sceIoLseek(4, 44000, 0)
NowLoading   D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
NowLoading   D[IO]:     sceIoRead(4, 09fb8500, 5674): deferring result
main app     D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
main app     D[IO]:     95012864 = sceIoLseek(4, 5a9c800, 0)
main app     D[IO]:     0=sceUmdWaitDriveStat(stat = 00000020)
main app     D[IO]:     sceIoRead(4, 08d5db40, 7450): deferring result

The PSP is using different timing (it's also file handle 3, but that's not the issue here):

05:22:54.652973 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:54.669583 main app - sceIoLseek 3, 0xFFFFFFFF, 0x8F00000, 0x0, 0 = 0x8F00000
05:22:54.686189 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:54.728496 main app - sceIoRead 3, 0x9A9D500, 376784 = 0x5BFD0
05:22:54.748218 main app - sceKernelCreateThread 0x08A5DFA0('NowLoading'), 0x889BD1C, 32, 0x1000, 0x0, 0x0 = 0x40CD11D
05:22:54.765816 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:54.766258 main app - sceIoLseek 3, 0xFFFFFFFF, 0x5A9C800, 0x0, 0 = 0x5A9C800
05:22:54.766472 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:54.777089 main app - sceIoRead 3, 0x8D3D940, 29776 = 0x7450
05:22:54.777337 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:54.777426 main app - sceIoLseek 3, 0xFFFFFFFF, 0x5AA4000, 0x0, 0 = 0x5AA4000
05:22:54.777485 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:54.764408 NowLoading - sceUmdWaitDriveStat 0x20 = 0x0
05:22:54.910565 main app - sceIoRead 3, 0x9739880, 1918304 = 0x1D4560
05:22:54.917872 NowLoading - sceIoLseek 3, 0xFFFFFFFF, 0x44000, 0x0, 0 = 0x44000
05:22:54.934811 NowLoading - sceUmdWaitDriveStat 0x20 = 0x0
05:22:54.959029 NowLoading - sceIoRead 3, 0x9F98300, 22132 = 0x5674
05:22:55.001523 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.020691 main app - sceIoLseek 3, 0xFFFFFFFF, 0x5C78800, 0x0, 0 = 0x5C78800
05:22:55.037408 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.059825 main app - sceIoRead 3, 0x8E156C0, 19936 = 0x4DE0
05:22:55.076182 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.092190 main app - sceIoLseek 3, 0xFFFFFFFF, 0x5C7D800, 0x0, 0 = 0x5C7D800
05:22:55.108704 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.356830 main app - sceIoRead 3, 0x8E1A500, 3547892 = 0x3622F4
05:22:55.373749 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.392419 main app - sceIoLseek 3, 0xFFFFFFFF, 0x5FE0000, 0x0, 0 = 0x5FE0000
05:22:55.409184 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.429080 main app - sceIoRead 3, 0x917C840, 18256 = 0x4750
05:22:55.446568 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.463768 main app - sceIoLseek 3, 0xFFFFFFFF, 0x5FE4800, 0x0, 0 = 0x5FE4800
05:22:55.480811 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.509964 main app - sceIoRead 3, 0x9181000, 136196 = 0x21404
05:22:55.526708 main app - sceUmdWaitDriveStat 0x20 = 0x0
05:22:55.545302 main app - sceIoLseek 3, 0xFFFFFFFF, 0x6006000, 0x0, 0 = 0x6006000
05:22:55.562431 main app - sceUmdWaitDriveStat 0x20 = 0x0

I can't see entry/exit in this version of JpcspTrace, so I'm not exactly sure how it was scheduled. Maybe sceIo internally mutexes on file handles? Hmm, I can't remember now if I tested threading behavior on files...

-[Unknown]

[sum2012]

I have added "!" parameter so that it logged before and after the syscall (i.e. twice)
https://gist.github.com/sum2012/287eeb8fd42d5fb27e59f044eec16456

[unknownbrackets]

Interesting, it seems like sceUmdWaitDriveStat blocked for a long time, even while it didn't block for the other thread. Maybe sceUmd mutexes?

-[Unknown]

[sum2012]

Just a note,based my jpcsptrace log,jpcsp fix this game jpcsp/jpcsp@074ae19

[sum2012]

@unknownbrackets As I see you fix io pull request.
Can you make a batch that based jpcsp fix (also io) ? Thanks.
jpcsp/jpcsp@074ae19

[unknownbrackets]

Hmm, well, reading I definitely remember testing more throughly before but it was also not consistent - an important thing to note is the umd cache makes testing that a bit tricky. But I can retest more.

-[Unknown]

[sum2012]

Thanks again @daniel229
When #8934 merged,this game would be fixed