Skip to content
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

scePowerSetClockFrequency seems to cause timing issues when set repeatedly #2104

Closed
thedax opened this issue Jun 6, 2013 · 16 comments
Closed

Comments

@thedax
Copy link
Collaborator

thedax commented Jun 6, 2013

Some games like Project Diva 2nd tend to ramp up or slow down the CPU, bus, and PLL speeds as needed(switching between 222/222/111 and 333/333/166), but it seems to cause timing drifts over time. If you let the intro/attract sequences of Diva 2nd run for about 10-20 minutes, the animations of the 3d characters begins to get sluggish, and when it cuts out to demo a song, the scene never seems to finish animating the 'intro' sequence, simply playing the music in the background.

Now here's the interesting thing: if we hardcode the CPU/PLL/Bus speed to 333(or perhaps 222, I didn't test with that), the timing issues magically vanish.

@unknownbrackets
Copy link
Collaborator

How frequently does it call it? Does it call it with any numbers between 222/333?

-[Unknown]

@thedax
Copy link
Collaborator Author

thedax commented Jun 6, 2013

I'm not exactly understanding how the timestamps work in PPSSPP's logging, but here's what it's done up to the point that it begins to 'slow down':

Another thing to note: The VPS isn't affected by this.

26:49:325 EmuThread.cpp:75 I[BOOT]: Done.
26:49:788 ELF\PBPReader.cpp:41 I[LOAD]: Loading PBP, version = 00010000
26:53:454 EmuScreen.cpp:54 I[BOOT]: Starting up hardware.
26:53:455 System.cpp:70 I[HLE]: PPSSPP v0.7.6-1142-gcc60b89
26:53:455 MemMap.cpp:82 I[MM]: Memory system initialized. RAM at 0000000008C00000 (mirror at 0 @ 0000000087FF0000, uncached @ 00000000C7FF0000)
26:53:520 Loaders.cpp:103 I[LOAD]: Identifying file...
26:53:520 PSPLoaders.cpp:67 I[LOAD]: ULJM05681 : 初音ミク -Project DIVA- 2nd
26:53:521 PSPLoaders.cpp:132 I[LOAD]: Loading disc0:/PSP_GAME/SYSDIR/EBOOT.BIN...
26:53:521 HLE\sceKernelMemory.cpp:162 I[HLE]: Kernel and user memory pools initialized
26:53:521 HLE\sceIo.cpp:261 I[HLE]: Starting up I/O...
26:53:521 FileUtil.cpp:204 I[COMMON]: CreateFullPath: path E:\Programming\Development\PC\ppsspp\ppsspp-dax\memstick
26:53:521 FileUtil.cpp:208 I[COMMON]: CreateFullPath: path exists E:\Programming\Development\PC\ppsspp\ppsspp-dax\memstick
26:53:521 FileUtil.cpp:204 I[COMMON]: CreateFullPath: path E:\Programming\Development\PC\ppsspp\ppsspp-dax\flash0
26:53:521 FileUtil.cpp:208 I[COMMON]: CreateFullPath: path exists E:\Programming\Development\PC\ppsspp\ppsspp-dax\flash0
26:53:524 FileUtil.cpp:204 I[COMMON]: CreateFullPath: path Cheats
26:53:524 FileUtil.cpp:208 I[COMMON]: CreateFullPath: path exists Cheats
26:53:524 FileUtil.cpp:204 I[COMMON]: CreateFullPath: path E:\Programming\Development\PC\ppsspp\ppsspp-dax\memstick\PSP\PPSSPP_STATE
26:53:524 FileUtil.cpp:208 I[COMMON]: CreateFullPath: path exists E:\Programming\Development\PC\ppsspp\ppsspp-dax\memstick\PSP\PPSSPP_STATE
26:53:563 HLE\sceKernel.cpp:131 I[HLE]: Kernel initialized.
26:53:570 E:\Programming\Development\PC\ppsspp\ppsspp-dax\Core/ELF/ElfReader.h:58 I[LOAD]: ElfReader: 000000000DA10040
26:53:572 Util\BlockAllocator.cpp:359 I[HLE]: -----------
26:53:572 Util\BlockAllocator.cpp:363 I[HLE]: Block: 08800000 - 08804000 size 00004000 taken=0 tag=(untitled)
26:53:572 Util\BlockAllocator.cpp:363 I[HLE]: Block: 08804000 - 08d4f900 size 0054b900 taken=1 tag=ELF
26:53:572 Util\BlockAllocator.cpp:363 I[HLE]: Block: 08d4f900 - 0a000000 size 012b0700 taken=0 tag=(untitled)
26:53:572 ELF\ElfReader.cpp:516 N[LOAD]: ELF loading completed successfully.
26:53:622 HLE\sceKernelModule.cpp:546 I[LOAD]: Module PdvApp: 08c5bfd0 08bae424 08bae43c
26:53:622 HLE\sceKernelModule.cpp:715 I[HLE]: Exporting ent 0 named PdvApp, 2 funcs, 4 vars, resident 08bae6b8
26:53:622 HLE\sceKernelModule.cpp:938 I[LOAD]: Module entry: 08804000
26:53:753 root N[BOOT]: EmuScreen.cpp:99 Loading E:\Games\diva-2nd.iso...
26:53:753 root I[HLE]: HLE\sceKernelThread.cpp:1883 276=sceKernelCreateThread(name=user_main, entry=08804114, prio=20, stacksize=229376)
26:53:753 root I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=276, argSize=33, argPtr=09fffe00)
26:53:753 root I[HLE]: HLE\sceKernelThread.cpp:2012 __KernelReturnFromThread: 0
26:53:753 user_main I[HLE]: Util\BlockAllocator.cpp:359 -----------
26:53:753 user_main I[HLE]: Util\BlockAllocator.cpp:363 Block: 08800000 - 08804000 size 00004000 taken=0 tag=(untitled)
26:53:753 user_main I[HLE]: Util\BlockAllocator.cpp:363 Block: 08804000 - 08d4f900 size 0054b900 taken=1 tag=ELF
26:53:753 user_main I[HLE]: Util\BlockAllocator.cpp:363 Block: 08d4f900 - 09f00000 size 011b0700 taken=1 tag=UserSbrk
26:53:753 user_main I[HLE]: Util\BlockAllocator.cpp:363 Block: 09f00000 - 09fc7c00 size 000c7c00 taken=0 tag=(untitled)
26:53:753 user_main I[HLE]: Util\BlockAllocator.cpp:363 Block: 09fc7c00 - 09fffc00 size 00038000 taken=1 tag=stack/user_main
26:53:753 user_main I[HLE]: Util\BlockAllocator.cpp:363 Block: 09fffc00 - 0a000000 size 00000400 taken=0 tag=stack/root
26:53:811 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 282=sceKernelCreateThread(name=igPSPPowerManager, entry=0894b0c4, prio=10, stacksize=65536
)
26:53:812 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=282, argSize=4, argPtr=08d5753c)
26:53:818 user_main E[HLE]: HLE\sceKernelThread.cpp:2795 Failed to access deferred info for thread: user_main
26:53:818 user_main E[HLE]: HLE\sceKernelThread.cpp:2795 Failed to access deferred info for thread: user_main
26:54:305 user_main I[HLE]: GLES\Framebuffer.cpp:432 Creating FBO for 00000000 : 480 x 272 x 3
26:54:647 user_main I[HLE]: HLE\scePspNpDrm_user.cpp:9 call sceNpDrmSetLicenseeKey(08bbc70c)
26:54:648 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 368=sceKernelCreateThread(name=CriThread, entry=08b0cb50, prio=20, stacksize=8192)
26:54:648 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=368, argSize=4, argPtr=09fff470)
26:54:648 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 371=sceKernelCreateThread(name=CriThread, entry=08b0cb50, prio=20, stacksize=8192)
26:54:648 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=371, argSize=4, argPtr=09fff470)
26:54:648 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 374=sceKernelCreateThread(name=CriThread, entry=08b0cb50, prio=20, stacksize=8192)
26:54:648 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=374, argSize=4, argPtr=09fff470)
26:54:814 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 395=sceKernelCreateThread(name=SceWaveMain, entry=0886afbc, prio=10, stacksize=512)
26:54:814 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=395, argSize=12, argPtr=08d16ea0)
26:54:816 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 396=sceKernelCreateThread(name=CRI ADX Audio, entry=08b57af0, prio=16, stacksize=32768)
26:54:816 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=396, argSize=0, argPtr=00000000)
26:54:816 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 397=sceKernelCreateThread(name=CRI ADX File, entry=08b57b68, prio=18, stacksize=16384)
26:54:816 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=397, argSize=0, argPtr=00000000)
26:54:819 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 399=sceKernelCreateThread(name=CRI Wave out, entry=08b75afc, prio=10, stacksize=16384)
26:54:820 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=399, argSize=0, argPtr=00000000)
26:54:870 user_main I[HLE]: GLES\Framebuffer.cpp:432 Creating FBO for 00088000 : 480 x 272 x 3
27:09:364 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(222,222,111)
27:18:853 user_main W[HLE]: HLE\sceMpeg.cpp:332 sceMpegInit()
27:18:856 user_main I[HLE]: HLE\sceMpeg.cpp:412 09373bf0=sceMpegCreate(08d1c350, 09373bc0, 65536, 08d1c354, 512, 0, 0)
27:18:857 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 403=sceKernelCreateThread(name=soundThread, entry=08a32980, prio=11, stacksize=2048)
27:18:857 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 405=sceKernelCreateThread(name=SofdecThread, entry=08a30394, prio=32, stacksize=8192)
27:18:857 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=403, argSize=4, argPtr=08d1c5cc)
27:18:857 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=405, argSize=4, argPtr=09fff540)
27:18:860 SofdecThread I[ME]: HLE\sceMpeg.cpp:282 Stream offset: 2048, Stream size: 0x172E000
27:18:860 SofdecThread I[ME]: HLE\sceMpeg.cpp:283 First timestamp: 90000, Last timestamp: 8213115
27:18:860 SofdecThread I[ME]: HLE\sceMpeg.cpp:282 Stream offset: 2048, Stream size: 0x172E000
27:18:860 SofdecThread I[ME]: HLE\sceMpeg.cpp:283 First timestamp: 90000, Last timestamp: 8213115
27:18:882 SofdecThread I[HLE]: GLES\Framebuffer.cpp:652 Destroying FBO for 00000000 : 480 x 272 x 3
27:18:882 SofdecThread I[HLE]: GLES\Framebuffer.cpp:652 Destroying FBO for 00088000 : 480 x 272 x 3
28:44:988 SofdecThread E[HLE]: HLE\sceMpeg.cpp:663 sceMpegAvcDecodeStop(08d1c350, 00000200, 09fa1130, 09fa1134)
28:44:989 soundThread I[HLE]: HLE\sceKernelThread.cpp:2030 sceKernelExitThread(0)
28:45:005 SofdecThread W[HLE]: HLE\sceMpeg.cpp:1145 UNIMPL sceMpegFlushAllStream(08d1c350)
28:45:006 SofdecThread E[HLE]: HLE\sceMpeg.cpp:809 UNIMPL sceMpegAvcDecodeFlush(08d1c350)
28:45:006 SofdecThread I[HLE]: HLE\sceKernelThread.cpp:2030 sceKernelExitThread(0)
28:45:035 user_main E[HLE]: HLE\sceMpeg.cpp:1000 sceMpegFinish(...)
28:45:038 user_main I[HLE]: GLES\Framebuffer.cpp:432 Creating FBO for 00000000 : 480 x 272 x 3
28:45:041 idle0 I[HLE]: GLES\Framebuffer.cpp:432 Creating FBO for 00088000 : 480 x 272 x 3
28:45:221 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
28:45:222 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
28:55:955 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(222,222,111)
29:12:638 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
29:59:606 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(222,222,111)
30:15:789 user_main W[HLE]: HLE\sceMpeg.cpp:332 sceMpegInit()
30:15:807 user_main I[HLE]: HLE\sceMpeg.cpp:412 093743c8=sceMpegCreate(08d1c350, 09374398, 65536, 08d1c354, 512, 0, 0)
30:15:807 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 409=sceKernelCreateThread(name=soundThread, entry=08a32980, prio=11, stacksize=2048)
30:15:807 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 411=sceKernelCreateThread(name=SofdecThread, entry=08a30394, prio=32, stacksize=8192)
30:15:807 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=409, argSize=4, argPtr=08d1c5cc)
30:15:807 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=411, argSize=4, argPtr=09fff540)
30:15:840 SofdecThread I[ME]: HLE\sceMpeg.cpp:282 Stream offset: 2048, Stream size: 0x172E000
30:15:840 SofdecThread I[ME]: HLE\sceMpeg.cpp:283 First timestamp: 90000, Last timestamp: 8213115
30:15:840 SofdecThread I[ME]: HLE\sceMpeg.cpp:282 Stream offset: 2048, Stream size: 0x172E000
30:15:840 SofdecThread I[ME]: HLE\sceMpeg.cpp:283 First timestamp: 90000, Last timestamp: 8213115
30:15:882 SofdecThread I[HLE]: GLES\Framebuffer.cpp:652 Destroying FBO for 00000000 : 480 x 272 x 3
30:15:882 SofdecThread I[HLE]: GLES\Framebuffer.cpp:652 Destroying FBO for 00088000 : 480 x 272 x 3
31:45:974 SofdecThread E[HLE]: HLE\sceMpeg.cpp:663 sceMpegAvcDecodeStop(08d1c350, 00000200, 09fa1130, 09fa1134)
31:45:974 soundThread I[HLE]: HLE\sceKernelThread.cpp:2030 sceKernelExitThread(0)
31:45:991 SofdecThread W[HLE]: HLE\sceMpeg.cpp:1145 UNIMPL sceMpegFlushAllStream(08d1c350)
31:45:991 SofdecThread E[HLE]: HLE\sceMpeg.cpp:809 UNIMPL sceMpegAvcDecodeFlush(08d1c350)
31:45:991 SofdecThread I[HLE]: HLE\sceKernelThread.cpp:2030 sceKernelExitThread(0)
31:46:018 user_main E[HLE]: HLE\sceMpeg.cpp:1000 sceMpegFinish(...)
31:46:021 user_main I[HLE]: GLES\Framebuffer.cpp:432 Creating FBO for 00000000 : 480 x 272 x 3
31:46:027 idle0 I[HLE]: GLES\Framebuffer.cpp:432 Creating FBO for 00088000 : 480 x 272 x 3
31:46:207 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
31:46:208 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
31:56:956 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(222,222,111)
32:13:640 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
32:59:308 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(222,222,111)
33:15:474 user_main W[HLE]: HLE\sceMpeg.cpp:332 sceMpegInit()
33:15:492 user_main I[HLE]: HLE\sceMpeg.cpp:412 093743c8=sceMpegCreate(08d1c350, 09374398, 65536, 08d1c354, 512, 0, 0)
33:15:492 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 415=sceKernelCreateThread(name=soundThread, entry=08a32980, prio=11, stacksize=2048)
33:15:492 user_main I[HLE]: HLE\sceKernelThread.cpp:1883 417=sceKernelCreateThread(name=SofdecThread, entry=08a30394, prio=32, stacksize=8192)
33:15:492 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=415, argSize=4, argPtr=08d1c5cc)
33:15:492 user_main I[HLE]: HLE\sceKernelThread.cpp:1926 sceKernelStartThread(thread=417, argSize=4, argPtr=09fff540)
33:15:525 SofdecThread I[ME]: HLE\sceMpeg.cpp:282 Stream offset: 2048, Stream size: 0x172E000
33:15:525 SofdecThread I[ME]: HLE\sceMpeg.cpp:283 First timestamp: 90000, Last timestamp: 8213115
33:15:525 SofdecThread I[ME]: HLE\sceMpeg.cpp:282 Stream offset: 2048, Stream size: 0x172E000
33:15:525 SofdecThread I[ME]: HLE\sceMpeg.cpp:283 First timestamp: 90000, Last timestamp: 8213115
33:15:570 SofdecThread I[HLE]: GLES\Framebuffer.cpp:652 Destroying FBO for 00000000 : 480 x 272 x 3
33:15:571 SofdecThread I[HLE]: GLES\Framebuffer.cpp:652 Destroying FBO for 00088000 : 480 x 272 x 3
34:45:660 SofdecThread E[HLE]: HLE\sceMpeg.cpp:663 sceMpegAvcDecodeStop(08d1c350, 00000200, 09fa1130, 09fa1134)
34:45:660 soundThread I[HLE]: HLE\sceKernelThread.cpp:2030 sceKernelExitThread(0)
34:45:676 SofdecThread W[HLE]: HLE\sceMpeg.cpp:1145 UNIMPL sceMpegFlushAllStream(08d1c350)
34:45:676 SofdecThread E[HLE]: HLE\sceMpeg.cpp:809 UNIMPL sceMpegAvcDecodeFlush(08d1c350)
34:45:676 SofdecThread I[HLE]: HLE\sceKernelThread.cpp:2030 sceKernelExitThread(0)
34:45:703 user_main E[HLE]: HLE\sceMpeg.cpp:1000 sceMpegFinish(...)
34:45:706 user_main I[HLE]: GLES\Framebuffer.cpp:432 Creating FBO for 00000000 : 480 x 272 x 3
34:45:711 idle0 I[HLE]: GLES\Framebuffer.cpp:432 Creating FBO for 00088000 : 480 x 272 x 3
34:45:892 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
34:45:892 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
34:56:643 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(222,222,111)
35:13:343 user_main I[HLE]: HLE\scePower.cpp:226 scePowerSetClockFrequency(333,333,166)
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 272: Thread "idle0": pc= 08000000 sp= 083fff00 RUN (wt=0 wid=0 wv= 00000000 )
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 273: Thread "idle1": pc= 08000000 sp= 083fef00 READY (wt=0 wid=0 wv= 00000000 )
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 274: Module "PdvApp": name=PdvApp gp=08c5bfd0 entry=08804000
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 276: Thread "user_main": pc= 0898c134 sp= 09fff620 READY (wt=12 wid=0 wv= 00000000 )
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 277: MemoryPart "UserSbrk": MemPart: 08d50000 - 09f00700 size: 011b0700
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 278: CallBack "APPLICATION_EXIT": thread=276, argument= 00000000
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 279: CallBack "PowerCallBack": thread=276, argument= 00000000
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 280: CallBack "UMD_OPEN": thread=276, argument= 00000000
35:14:505 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 281: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 282: Thread "igPSPPowerManager": pc= 08947bb8 sp= 09fc7a90 WAIT (wt=2 wid=282 wv= 0000000
0 )
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 283: CallBack "AlchemyExit": thread=282, argument= 00000000
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 284: CallBack "AlchemyPower": thread=282, argument= 00000000
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 285: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 286: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 287: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 288: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 289: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 290: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 291: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 292: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 293: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 294: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 295: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 296: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 297: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 298: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 299: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 300: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 301: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 302: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 303: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 304: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 305: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 306: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 307: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 308: Semaphore "igSemaphore": -
35:14:506 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 309: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 312: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 313: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 314: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 315: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 316: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 317: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 318: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 319: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 320: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 321: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 322: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 323: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 324: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 325: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 326: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 327: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 328: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 329: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 330: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 331: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 332: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 333: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 334: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 335: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 336: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 337: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 338: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 339: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 340: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 341: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 342: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 343: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 344: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 345: Semaphore "igSemaphore": -
35:14:507 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 346: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 347: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 348: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 349: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 350: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 351: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 352: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 353: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 354: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 355: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 356: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 357: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 358: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 359: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 360: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 361: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 362: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 363: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 364: Semaphore "igSemaphore": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 365: Semaphore "igSyncFifoSequence": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 366: Mutex "CriCsPsp": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 367: EventFlag "CriCond": init=00000000 cur=00000000 numwait=0
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 368: Thread "CriThread": pc= 08b0b4b8 sp= 09fb7a70 WAIT (wt=4 wid=367 wv= 00000000 )
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 369: Mutex "CriCsPsp": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 370: EventFlag "CriCond": init=00000000 cur=00000000 numwait=0
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 371: Thread "CriThread": pc= 08b0b4b8 sp= 09fb5a70 WAIT (wt=4 wid=370 wv= 00000000 )
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 372: Mutex "CriCsPsp": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 373: EventFlag "CriCond": init=00000000 cur=00000000 numwait=0
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 374: Thread "CriThread": pc= 08b0b4b8 sp= 09fb3a70 WAIT (wt=4 wid=373 wv= 00000000 )
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 375: Mutex "CriCsPsp": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 376: Mutex "CriCsPsp": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 377: Mutex "CriCsPsp": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 378: Mutex "CriCsPsp": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 379: Mutex "CriCsPsp": -
35:14:508 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 380: Mutex "CriCsPsp": -
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 381: Mutex "CriCsPsp": -
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 382: Mutex "CriCsPsp": -
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 383: CallBack "crifsioutil_PowerCallback": thread=368, argument= 00000000
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 384: CallBack "crifsioutil_MsCallback": thread=368, argument= 00000000
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 387: OpenFile "disc0:/PSP_GAME/USRDIR/media/afs/Diva2Script.cpk": Seekpos: 00000000
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 390: OpenFile "disc0:/PSP_GAME/USRDIR/media/afs/Diva2Sound.cpk": Seekpos: 00000000
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 393: OpenFile "disc0:/PSP_GAME/USRDIR/media/afs/Diva2Data.cpk": Seekpos: 00000000
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 394: EventFlag "SceWaveMainEvf": init=00000000 cur=00000000 numwait=0
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 395: Thread "SceWaveMain": pc= 0886b15c sp= 09fffe50 WAIT (wt=4 wid=394 wv= 00000000 )
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 396: Thread "CRI ADX Audio": pc= 08b57b40 sp= 09fb1ab0 READY (wt=12 wid=0 wv= 00000000 )
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 397: Thread "CRI ADX File": pc= 08b57bc0 sp= 09fa9ab0 READY (wt=12 wid=0 wv= 00000000 )
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 398: Mutex "CriCsPsp": -
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 399: Thread "CRI Wave out": pc= 0886af30 sp= 09fa5a50 WAIT (wt=10 wid=7 wv= 00000100 )
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:461 KO 400: LwMutex "CRI Wave Mutex": -
35:14:509 idle0 I[HLE]: HLE\sceKernel.cpp:142 Shutting down kernel - 120 kernel objects alive
35:14:509 GLES\Framebuffer.cpp:652 I[HLE]: Destroying FBO for 00000000 : 480 x 272 x 3
35:14:509 GLES\Framebuffer.cpp:652 I[HLE]: Destroying FBO for 00088000 : 480 x 272 x 3
35:14:510 HLE\sceKernelMemory.cpp:188 I[HLE]: Shutting down user memory pool:
35:14:510 Util\BlockAllocator.cpp:359 I[HLE]: -----------
35:14:510 Util\BlockAllocator.cpp:363 I[HLE]: Block: 08800000 - 0a000000 size 01800000 taken=0 tag=(untitled)
35:14:510 HLE\sceKernelMemory.cpp:191 I[HLE]: Shutting down "kernel" memory pool:
35:14:510 Util\BlockAllocator.cpp:359 I[HLE]: -----------
35:14:510 Util\BlockAllocator.cpp:363 I[HLE]: Block: 08000000 - 08400000 size 00400000 taken=0 tag=threadrethack
35:14:513 MemMap.cpp:101 I[MM]: Memory system shut down.

@unknownbrackets
Copy link
Collaborator

The timestamps are MM:SS:sss of the current local time. I've been thinking having the same into gameplay per gameclock would be much more useful...

If a game plays around with the clock rate a lot, events may happen at the wrong times. For example, vblank, vtimers, alarms, all wait timeouts, etc. That's because it's translated to ticks and time of set, and not adjusted.

Could try rescaling all events by the new/old hz ratio on change, hmm. But really, just a few changes like that shouldn't cause an issue, I'd have thought...

-[Unknown]

@thedax
Copy link
Collaborator Author

thedax commented Jun 6, 2013

Do you think a debug log would possibly shed any more light on this?

@unknownbrackets
Copy link
Collaborator

Hmm, not sure. Maybe. Also, I have some minor changes to these funcs sitting around, maybe it's calling others. This doesn't help, does it?

https://github.com/unknownbrackets/ppsspp/compare/power

-[Unknown]

@Squall-Leonhart
Copy link

could that be what is going on with BBS in #2066 ?

@thedax
Copy link
Collaborator Author

thedax commented Jun 9, 2013

@unknownbrackets : Adding the new code from your power branch didn't really help. The animations in Diva 2nd still get choppy after about the same amount of time as before. Thanks for having a look at it, though. I appreciate it.

@thedax
Copy link
Collaborator Author

thedax commented Jun 12, 2013

Another interesting tidbit: If you go to the main menu after it begins to 'lag', and then try to go to any option on the main menu, it hangs forever.

Edit: What the? It loaded after about 15 seconds..that was odd. But it's still interesting. Also, after it loads, the 'lag' seems to go away.

@hrydgard
Copy link
Owner

Maybe should check if it happens on the real PSP too :)

@thedax
Copy link
Collaborator Author

thedax commented Jun 12, 2013

@hrydgard : It doesn't seem to happen on the real PSP. I let Diva 2nd run for a good 25 minutes on its own and the animations were perfectly fluid.

@unknownbrackets
Copy link
Collaborator

Sounds like this is actually just #2010 in disguise, since it temporarily sets to 333 and we have some very delicious fudge factors for that mhz.

-[Unknown]

@unknownbrackets
Copy link
Collaborator

Do the timing changes in #4286 improve this? Or the changes to gpu timing delicious fudge?

-[Unknown]

@thedax
Copy link
Collaborator Author

thedax commented Oct 24, 2013

It seems to be fixed now, yes. But I'm going to do some more in depth testing(e.g. go back a few revisions and see if it was indeed fixed by either).

@thedax
Copy link
Collaborator Author

thedax commented Oct 24, 2013

Yeah, I'm pretty sure your stuff fixed it. As for which commit did, I dunno yet. I'll bisect it later out of curiosity, but at 0.9.1-2123-g6c5a2ea, the bug still existed, and the next available buildbot build(v0.9.1-2145-gbadf33a) did the trick.

@unknownbrackets
Copy link
Collaborator

I expected 9c874c7 to fix it, so it's probably that one.

scePowerSetClockFrequency() used to act as a DeLorean, but it doesn't anymore. So I'm going to close this issue.

-[Unknown]

@thedax
Copy link
Collaborator Author

thedax commented Oct 24, 2013

@unknownbrackets: Yeah, that was the one. I tested the commit just before it and the bug still existed, so indeed, that one is the answer.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants