Metal Gear Peace Walker (Android #12447) broken by async I/O change (was Burnout Dominator)

[JBDaz]

It WAS fixed up to v1.9.3-164-g0a5ec4838; BO Dominator works.
Recent async i/o changes (as of v1.9.3-170-g6a196c04a) broke it again - Burnout Dominator crashes again like seen in old issue.

(not sure if comments to closed issue count ? That's why I opened this as a "new" issue ...

[unknownbrackets]

Comments are comments, whether they issue is marked as fixed or not. They always count. Me and Henrik (and a few hundred other people) get an email for every issue or comment you create.

A log would help, since I don't have this game.

-[Unknown]

[Saramagrean]

MGS:PW too game freeze after logo Konami.

Last work 1.9.3 build 167.
First break 1.9.3 build 170.

[Panderner]

Hmm I don't see any crashes but it's seems the game is playable

[hrydgard]

@Panderner Are you really testing the latest build from https://buildbot.orphis.net/ppsspp/ ? It broke recently, it seems.

[Panderner]

@Panderner Are you really testing the latest build from https://buildbot.orphis.net/ppsspp/ ? It broke recently, it seems.

Yes. It's v1.9.3-189-g6d8ddb7a7

[Panderner]

@JBDaz what android phone are you using?

[JBDaz]

• v1.9.3-170-g6a196c04a (Update async priority more correctly) broke BO:Domin. on Win and Android.
• v1.9.3-181-g78e36ece5 (or a few builds before) made it work on Win again (prolly on Android too ? - didn't test yet)

My current phone is an OP7TPro ...

[Panderner]

@JBDaz have you tried to update the latest build?

[unknownbrackets]

Most likely this was fixed by v1.9.3-171-g347433910. It would not be platform specific.

-[Unknown]

[Saramagrean]

MGS:PW with v1.9.3 build 189 still freeze after logo Konami. [Android/Windows] 😂

[bababoombatman]

I can confirm that metal gear peace walker keeps crashing on the latest versions on my honor 9 lite. The last working one was v1.9.3-167-gb2dd3c7e1 as stated above. Right now I'm very busy, but next week I think I'll be able to drop a log here if needed 😃

[hrydgard]

Metal Gear PW seems to be the game with the problem now indeed, so renaming the issue.

[hrydgard]

Bisected, and the breaking commit is 593e48b . Strange.

[unknownbrackets]

Hm, a log might help. I'm most interested in:

What SDK ver does the game use?
What default priorities does it set?
Does it ever override the priority?
Which is the last sceIo call that presumably doesn't work out?

-[Unknown]

[hrydgard]

Log up until the crash:
metal_pw_log.txt

It doesn't call sceIoChangeAsyncPriority. Lots of module loading and linking though.

I can do more checks tomorrow.

[unknownbrackets]

Module SDK: 05050010

50:48:059 kfs io0      D[SCEIO]: HLE\sceIo.cpp:2141 0=sceIoWaitAsync(4, 08df4440[0000000008de11f0]): waiting
50:48:059 SceIoAsync   D[SCEIO]: HLE\sceIo.cpp:2693 ASYNC sceIoReadAsync(4, 08df44a4, 4): deferring result

Hm, seems like it either somehow failed to wake the kfs io0 thread, or something went wrong there. I guess it must somehow be related to the fake thread changes.

Would be interesting to know how the SceIoAsync thread (there may be multiple, but the log looks like it should only have one) ends up, and if the kfs io0 thread is waiting still or something else.

Otherwise I guess it'd somehow be an issue waking the thread here?

ppsspp/Core/HLE/sceIo.cpp

Line 427 in 593e48b

SceUID threadID = f->waitingThreads.front();

-[Unknown]

[hrydgard]

OK so it turns out the game at least starts up with I/O timing method = Simulate UMD Timing. We could force it on for this game, I suppose, but it still seems worrying that it's this unstable.

It crashes pretty soon after the fourth time it reaches __IoFreeFd(fd, error); in __IoAsyncNotify.

Turns out my log was missing the end because the log thread stopped running when the main thread crashed. Could get more log by pressing Run in VS, one half line at a time, but instead added a sleep statement so I could get it all. This is how it ends, although it just looks like more of the same:

37:04:939 Main         D[SCEDISP]: HLE\sceDisplay.cpp:1105 2292=sceDisplayGetAccumulatedHcount()
37:04:939 Main         D[SCEGE]: HLE\sceGe.cpp:392 sceGeDrawSync(mode=0)  (0=wait for completion, 1=peek)
37:04:951 kfs io0      D[SCEIO]: HLE\sceIo.cpp:1401 0=sceIoLseekAsync(4, 0000000000cf7000, 0)
37:04:951 kfs io0      D[SCEIO]: HLE\sceIo.cpp:2146 0=sceIoWaitAsync(4, 08df4440[ffffffff08de11f0]): waiting
37:04:951 SceIoAsync   D[SCEIO]: HLE\sceIo.cpp:2716 ASYNC 13594624 = sceIoLseekAsync(4, cf7000, 0)
37:04:962 kfs io0      D[SCEIO]: HLE\sceIo.cpp:1117 0=sceIoReadAsync(4, 08df44a4, 4)
37:04:962 kfs io0      D[SCEIO]: HLE\sceIo.cpp:2146 0=sceIoWaitAsync(4, 08df4440[0000000008de11f0]): waiting
37:04:962 SceIoAsync   D[SCEIO]: HLE\sceIo.cpp:2698 ASYNC sceIoReadAsync(4, 08df44a4, 4): deferring result
37:04:974 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:04:974 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2b40, 4096, 4096)
37:04:974 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:04:974 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2f40, 4096, 4096)
37:04:974 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2b40)
37:04:974 idle0        D[CPU]: HLE\sceKernelInterrupt.cpp:151 Entering interrupt handler 0887b6a4
37:04:988 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:04:988 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2340, 4096, 4096)
37:04:988 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:04:988 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2740, 4096, 4096)
37:04:988 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2340)
37:04:988 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:04:989 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2b40, 4096, 4096)
37:04:989 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:04:989 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2f40, 4096, 4096)
37:04:989 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2b40)
37:04:989 idle0        D[CPU]: HLE\sceKernelInterrupt.cpp:151 Entering interrupt handler 0887b6a4
37:04:997 Main         D[SCEDISP]: HLE\sceDisplay.cpp:1105 2861=sceDisplayGetAccumulatedHcount()
37:04:997 Main         D[SCEDISP]: HLE\sceDisplay.cpp:1105 2861=sceDisplayGetAccumulatedHcount()
37:04:997 Main         D[SCECTRL]: HLE\sceCtrl.cpp:461 2=sceCtrlReadBufferPositive(09fbf980, 8)
37:05:015 Main         D[HLE]: JitCommon\JitBlockCache.cpp:166 Adding proxy root 088807cc to block at 08b49360
37:05:023 Main         D[SCEDISP]: HLE\sceDisplay.cpp:1105 2863=sceDisplayGetAccumulatedHcount()
37:05:023 Main         D[SCEGE]: HLE\sceGe.cpp:392 sceGeDrawSync(mode=0)  (0=wait for completion, 1=peek)
37:05:023 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:023 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2340, 4096, 4096)
37:05:023 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:023 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2740, 4096, 4096)
37:05:023 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2340)
37:05:023 idle0        D[CPU]: HLE\sceKernelInterrupt.cpp:151 Entering interrupt handler 0887b6a4
37:05:030 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:030 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2b40, 4096, 4096)
37:05:030 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:030 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2f40, 4096, 4096)
37:05:031 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2b40)
37:05:031 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:031 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2340, 4096, 4096)
37:05:031 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:031 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2740, 4096, 4096)
37:05:031 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2340)
37:05:031 idle0        D[CPU]: HLE\sceKernelInterrupt.cpp:151 Entering interrupt handler 0887b6a4
37:05:033 Main         D[SCEDISP]: HLE\sceDisplay.cpp:1105 3433=sceDisplayGetAccumulatedHcount()
37:05:033 Main         D[SCEDISP]: HLE\sceDisplay.cpp:1105 3433=sceDisplayGetAccumulatedHcount()
37:05:033 Main         D[SCECTRL]: HLE\sceCtrl.cpp:461 2=sceCtrlReadBufferPositive(09fbf980, 8)
37:05:033 kfs io0      D[SCEIO]: HLE\sceUmd.cpp:473 0=sceUmdWaitDriveStatCB(stat = 00000020, timeout = 1000000)
37:05:034 kfs io0      D[HLE]: HLE\HLE.cpp:504 Compiling syscall to sceKernelWaitSema
37:05:034 kfs io0      D[HLE]: HLE\HLE.cpp:504 Compiling syscall to sceKernelCreateFpl
37:05:035 kfs io0      D[HLE]: HLE\HLE.cpp:504 Compiling syscall to sceKernelAllocateFpl
37:05:035 kfs io0      D[HLE]: HLE\HLE.cpp:504 Compiling syscall to sceKernelSignalSema
37:05:036 kfs io0      D[SCEIO]: HLE\sceIo.cpp:1117 0=sceIoReadAsync(4, 08df7700, 53)
37:05:036 kfs io0      D[SCEIO]: HLE\sceIo.cpp:2146 0=sceIoWaitAsync(4, 08df4490[08de3f7408de11f0]): waiting
37:05:036 SceIoAsync   D[SCEIO]: HLE\sceIo.cpp:2698 ASYNC sceIoReadAsync(4, 08df7700, 35): deferring result
37:05:051 kfs io0      D[HLE]: HLE\HLE.cpp:504 Compiling syscall to sceKernelFreeFpl
37:05:051 kfs io0      D[HLE]: HLE\HLE.cpp:504 Compiling syscall to sceKernelDeleteFpl
37:05:051 Main         D[SCEDISP]: HLE\sceDisplay.cpp:1105 3439=sceDisplayGetAccumulatedHcount()
37:05:051 Main         D[SCEGE]: HLE\sceGe.cpp:392 sceGeDrawSync(mode=0)  (0=wait for completion, 1=peek)
37:05:051 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:051 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2b40, 4096, 4096)
37:05:051 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:051 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2f40, 4096, 4096)
37:05:052 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2b40)
37:05:052 idle0        D[CPU]: HLE\sceKernelInterrupt.cpp:151 Entering interrupt handler 0887b6a4
37:05:054 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:054 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2340, 4096, 4096)
37:05:054 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:054 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2740, 4096, 4096)
37:05:054 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2340)
37:05:054 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:054 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2b40, 4096, 4096)
37:05:054 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:272 ffffffff=sceSasGetEndFlag(08db3400)
37:05:054 snd_thread_m D[SCESAS]: HLE\sceSas.cpp:321 0=__sceSasCoreWithMix(08db3400, 08db2f40, 4096, 4096)
37:05:054 snd_thread_m D[SCEAUDIO]: HLE\sceAudio.cpp:355 512=sceAudioOutput2OutputBlocking(00008000, 08db2b40)
37:05:054 idle0        D[CPU]: HLE\sceKernelInterrupt.cpp:151 Entering interrupt handler 0887b6a4
37:05:056 Main         D[SCEDISP]: HLE\sceDisplay.cpp:977 0=sceDisplaySetFrameBuf(04000000, 512, 1, 0)
37:05:057 Main         D[SCEGE]: HLE\sceGe.cpp:336 sceGeListEnQueue(addr=09f7fc00, stall=00000000, cbid=00000000, param=09fbfa00)
37:05:057 Main         D[G3D]: GPU\GPUCommon.cpp:1139 Starting DL execution at 09f7fc00 - stall = 00000000
37:05:057 Main         D[G3D]: Common\FramebufferCommon.cpp:278 Est: 04000000 V: 0x0, R: 512x272, S: 512x272, STR: 512, THR:1, Z:440a8000 = 512x272
37:05:058 Main         I[FRAMEBUF]: Common\FramebufferCommon.cpp:452 Creating FBO for 04000000 : 512 x 272 x 1
37:05:058 Main         W[G3D]: Common\FramebufferCommon.cpp:1299 Memcpy fbo upload 04400000 -> 04000000

[unknownbrackets]

Does it help if you change the us = 100; to us = 0; under case IoAsyncOp::CLOSE:? I'm really not sure if that needs to delay. It seems to make a difference in the demo.

-[Unknown]

[hrydgard]

Yup, that makes it work. I guess CLOSE shouldn't have a delay indeed.

Thanks!

[hrydgard]

I think that's all of the reported regressions from the async changes... let's see if there are more. Or hopefully the opposite, maybe something started working :)

[unknownbrackets]

I'm hoping for positive timing impacts, I think next step would be to adjust timing and scale to throughput a bit. There could be a lingering complexity of like serializing disc reads from separate threads (from a timing perspective), but hopefully that's not a common problem.

-[Unknown]