Log context switch time, shorten logging a bit.

This is really useful for seeing why games are slow or hanging.
This commit is contained in:
Unknown W. Brackets 2013-08-25 10:25:49 -07:00
parent 2d806b4820
commit 8d7eb265be
3 changed files with 19 additions and 10 deletions

View file

@ -163,7 +163,7 @@ u32 __AudioEnqueue(AudioChannel &chan, int chanNum, bool blocking) {
AudioChannelWaitInfo waitInfo = {__KernelGetCurThread(), blockSamples};
chan.waitingThreads.push_back(waitInfo);
// Also remember the value to return in the waitValue.
__KernelWaitCurThread(WAITTYPE_AUDIOCHANNEL, (SceUID)chanNum + 1, ret, 0, false, "blocking audio waited");
__KernelWaitCurThread(WAITTYPE_AUDIOCHANNEL, (SceUID)chanNum + 1, ret, 0, false, "blocking audio");
// Fall through to the sample queueing, don't want to lose the samples even though
// we're getting full. The PSP would enqueue after blocking.

View file

@ -407,9 +407,9 @@ void __KernelReturnFromInterrupt()
{
// Otherwise, we reschedule when dispatch was enabled, or switch back otherwise.
if (__KernelIsDispatchEnabled())
__KernelReSchedule("return from interrupt");
__KernelReSchedule("left interrupt");
else
__KernelSwitchToThread(threadBeforeInterrupt, "return from interrupt");
__KernelSwitchToThread(threadBeforeInterrupt, "left interrupt");
}
}

View file

@ -822,6 +822,9 @@ int actionAfterMipsCall;
// Doesn't need state saving.
WaitTypeFuncs waitTypeFuncs[NUM_WAITTYPES];
// Doesn't really need state saving, just for logging purposes.
static u64 lastSwitchCycles = 0;
//////////////////////////////////////////////////////////////////////////
//STATE END
//////////////////////////////////////////////////////////////////////////
@ -971,6 +974,7 @@ void __KernelThreadingInit()
g_inCbCount = 0;
currentCallbackThreadID = 0;
readyCallbacksCount = 0;
lastSwitchCycles = 0;
idleThreadHackAddr = kernelMemory.Alloc(blockSize, false, "threadrethack");
Memory::Memcpy(idleThreadHackAddr, idleThreadCode, sizeof(idleThreadCode));
@ -1025,6 +1029,7 @@ void __KernelThreadingDoState(PointerWrap &p)
__KernelRestoreActionType(actionAfterCallback, ActionAfterCallback::Create);
hleCurrentThreadName = __KernelGetThreadName(currentThread);
lastSwitchCycles = CoreTiming::GetTicks();
p.DoMarker("sceKernelThread");
}
@ -3010,7 +3015,7 @@ void __KernelSwitchContext(Thread *target, const char *reason)
{
u32 oldPC = 0;
SceUID oldUID = 0;
const char *oldName = "(none)";
const char *oldName = hleCurrentThreadName != NULL ? hleCurrentThreadName : "(none)";
Thread *cur = __GetCurrentThread();
if (cur) // It might just have been deleted.
@ -3019,10 +3024,6 @@ void __KernelSwitchContext(Thread *target, const char *reason)
oldPC = currentMIPS->pc;
oldUID = cur->GetUID();
// Profile on Windows shows this takes time, skip it.
if (DEBUG_LEVEL <= MAX_LOGLEVEL)
oldName = cur->GetName();
// Normally this is taken care of in __KernelNextThread().
if (cur->isRunning())
__KernelChangeReadyState(cur, oldUID, true);
@ -3043,15 +3044,23 @@ void __KernelSwitchContext(Thread *target, const char *reason)
hleCurrentThreadName = NULL;
}
#if DEBUG_LEVEL <= MAX_LOGLEVEL || DEBUG_LOG == NOTICE_LOG
bool fromIdle = oldUID == threadIdleID[0] || oldUID == threadIdleID[1];
bool toIdle = currentThread == threadIdleID[0] || currentThread == threadIdleID[1];
if (!(fromIdle && toIdle))
{
DEBUG_LOG(HLE,"Context switched: %s -> %s (%s) (%i - pc: %08x -> %i - pc: %08x)",
u64 nowCycles = CoreTiming::GetTicks();
s64 consumedCycles = nowCycles - lastSwitchCycles;
lastSwitchCycles = nowCycles;
DEBUG_LOG(HLE, "Context switch: %s -> %s (%i->%i, pc: %08x->%08x, %s) +%lldus",
oldName, hleCurrentThreadName,
oldUID, currentThread,
oldPC, currentMIPS->pc,
reason,
oldUID, oldPC, currentThread, currentMIPS->pc);
cyclesToUs(consumedCycles));
}
#endif
if (target)
{