From 118050485fe76713512173142194efb0928f7a30 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Sun, 10 Mar 2013 22:25:03 -0700 Subject: [PATCH 1/6] Show the current thread name in the log file. This is very useful, although it kinda entwines the logging a bit more than might be desired. --- Common/LogManager.cpp | 30 ++++++++++++++++++++++++++---- Common/LogManager.h | 1 + Core/HLE/sceKernelThread.cpp | 18 ++++++++++++++++-- Core/HLE/sceKernelThread.h | 2 +- 4 files changed, 44 insertions(+), 7 deletions(-) diff --git a/Common/LogManager.cpp b/Common/LogManager.cpp index 956a1ae23..1159a75c3 100644 --- a/Common/LogManager.cpp +++ b/Common/LogManager.cpp @@ -26,6 +26,9 @@ #include #endif +// Don't need to savestate this. +const char *hleCurrentThreadName = NULL; + // Unfortunately this is quite slow. #define LOG_MSC_OUTPUTDEBUG false // #define LOG_MSC_OUTPUTDEBUG true @@ -169,11 +172,30 @@ void LogManager::Log(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, const char formattedTime[13]; Common::Timer::GetTimeFormatted(formattedTime); +#ifdef _WIN32 + const char *fileshort = strrchr(file, '\\'); +#else + const char *fileshort = strrchr(file, '/'); +#endif + if (fileshort != NULL) + file = fileshort + 1; + char *msgPos = msg; - msgPos += sprintf(msgPos, "%s %s:%d %c[%s]: ", - formattedTime, - file, line, level_to_char[(int)level], - log->GetShortName()); + if (hleCurrentThreadName != NULL) + { + msgPos += sprintf(msgPos, "%s %-12.12s %c[%s]: %s:%d ", + formattedTime, + hleCurrentThreadName, level_to_char[(int)level], + log->GetShortName(), + file, line); + } + else + { + msgPos += sprintf(msgPos, "%s %s:%d %c[%s]: ", + formattedTime, + file, line, level_to_char[(int)level], + log->GetShortName()); + } msgPos += vsnprintf(msgPos, MAX_MSGLEN, format, args); // This will include the null terminator. diff --git a/Common/LogManager.h b/Common/LogManager.h index 20b9130c4..faf94f798 100644 --- a/Common/LogManager.h +++ b/Common/LogManager.h @@ -30,6 +30,7 @@ #define MAX_MESSAGES 8000 #define MAX_MSGLEN 1024 +extern const char *hleCurrentThreadName; // pure virtual interface class LogListener diff --git a/Core/HLE/sceKernelThread.cpp b/Core/HLE/sceKernelThread.cpp index 9a1b14440..a7286f105 100644 --- a/Core/HLE/sceKernelThread.cpp +++ b/Core/HLE/sceKernelThread.cpp @@ -20,6 +20,7 @@ #include #include +#include "Common/LogManager.h" #include "HLE.h" #include "HLETables.h" #include "../MIPS/MIPSInt.h" @@ -684,6 +685,8 @@ void __KernelThreadingDoState(PointerWrap &p) p.Do(actionAfterCallback); __KernelRestoreActionType(actionAfterCallback, ActionAfterCallback::Create); + hleCurrentThreadName = __KernelGetThreadName(currentThread); + p.DoMarker("sceKernelThread"); } @@ -833,6 +836,7 @@ void __KernelThreadingShutdown() currentThread = 0; intReturnHackAddr = 0; curModule = 0; + hleCurrentThreadName = NULL; } const char *__KernelGetThreadName(SceUID threadID) @@ -1202,7 +1206,10 @@ u32 __KernelDeleteThread(SceUID threadID, int exitStatus, const char *reason, bo __KernelTriggerWait(WAITTYPE_THREADEND, threadID, exitStatus, reason, dontSwitch); if (currentThread == threadID) + { currentThread = 0; + hleCurrentThreadName = NULL; + } if (currentCallbackThreadID == threadID) { currentCallbackThreadID = 0; @@ -1426,6 +1433,7 @@ void __KernelSetupRootThread(SceUID moduleID, int args, const char *argp, int pr if (prevThread && prevThread->isRunning()) __KernelChangeReadyState(currentThread, true); currentThread = id; + hleCurrentThreadName = "root"; thread->nt.status = THREADSTATUS_RUNNING; // do not schedule strcpy(thread->nt.name, "root"); @@ -2360,12 +2368,18 @@ void __KernelSwitchContext(Thread *target, const char *reason) __KernelChangeReadyState(cur, oldUID, true); } - currentThread = target->GetUID(); if (target) { + currentThread = target->GetUID(); + hleCurrentThreadName = target->nt.name; __KernelChangeReadyState(target, currentThread, false); target->nt.status = (target->nt.status | THREADSTATUS_RUNNING) & ~THREADSTATUS_READY; } + else + { + currentThread = 0; + hleCurrentThreadName = NULL; + } __KernelLoadContext(&target->context); @@ -2374,7 +2388,7 @@ void __KernelSwitchContext(Thread *target, const char *reason) if (!(fromIdle && toIdle)) { DEBUG_LOG(HLE,"Context switched: %s -> %s (%s) (%i - pc: %08x -> %i - pc: %08x)", - oldName, target->GetName(), + oldName, hleCurrentThreadName, reason, oldUID, oldPC, currentThread, currentMIPS->pc); } diff --git a/Core/HLE/sceKernelThread.h b/Core/HLE/sceKernelThread.h index fd0039c49..aec38bb2b 100644 --- a/Core/HLE/sceKernelThread.h +++ b/Core/HLE/sceKernelThread.h @@ -24,7 +24,6 @@ #include "sceKernelModule.h" #include "HLE.h" - void sceKernelChangeThreadPriority(); int __KernelCreateThread(const char *threadName, SceUID moduleID, u32 entry, u32 prio, int stacksize, u32 attr, u32 optionAddr); int sceKernelCreateThread(const char *threadName, u32 entry, u32 prio, int stacksize, u32 attr, u32 optionAddr); @@ -116,6 +115,7 @@ KernelObject *__KernelCallbackObject(); void __KernelScheduleWakeup(int threadnumber, s64 usFromNow); SceUID __KernelGetCurThread(); +const char *__KernelGetThreadName(SceUID threadID); void __KernelSaveContext(ThreadContext *ctx); void __KernelLoadContext(ThreadContext *ctx); From a34cf0bb795bdcf1d4a709e3d9bbfb01b310c451 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Sun, 10 Mar 2013 22:31:47 -0700 Subject: [PATCH 2/6] Add a VERBOSE logging level, for noisy logging. The debug log is hard to look at because it has so much unneeded info. --- Common/Log.h | 13 ++++++++----- Common/LogManager.cpp | 2 +- android/jni/NativeApp.cpp | 1 + headless/Headless.cpp | 3 +++ 4 files changed, 13 insertions(+), 6 deletions(-) diff --git a/Common/Log.h b/Common/Log.h index b027fc296..c01835df7 100644 --- a/Common/Log.h +++ b/Common/Log.h @@ -22,6 +22,7 @@ #define WARNING_LEVEL 3 // Something is suspicious. #define INFO_LEVEL 4 // General information. #define DEBUG_LEVEL 5 // Detailed debugging - might make things slow. +#define VERBOSE_LEVEL 6 // Noisy debugging - sometimes needed but usually unimportant. #if !defined(_WIN32) && !defined(PANDORA) #include @@ -64,6 +65,7 @@ enum LOG_LEVELS { LWARNING = WARNING_LEVEL, LINFO = INFO_LEVEL, LDEBUG = DEBUG_LEVEL, + LVERBOSE = VERBOSE_LEVEL, }; #define LOGTYPES_LEVELS LogTypes::LOG_LEVELS @@ -92,11 +94,12 @@ void GenericLog(LOGTYPES_LEVELS level, LOGTYPES_TYPE type, GenericLog(v, t, __FILE__, __LINE__, __VA_ARGS__); \ } -#define ERROR_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LERROR, __VA_ARGS__) } -#define WARN_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LWARNING, __VA_ARGS__) } -#define NOTICE_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LNOTICE, __VA_ARGS__) } -#define INFO_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LINFO, __VA_ARGS__) } -#define DEBUG_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LDEBUG, __VA_ARGS__) } +#define ERROR_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LERROR, __VA_ARGS__) } +#define WARN_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LWARNING, __VA_ARGS__) } +#define NOTICE_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LNOTICE, __VA_ARGS__) } +#define INFO_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LINFO, __VA_ARGS__) } +#define DEBUG_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LDEBUG, __VA_ARGS__) } +#define VERBOSE_LOG(t,...) { GENERIC_LOG(LogTypes::t, LogTypes::LVERBOSE, __VA_ARGS__) } #if MAX_LOGLEVEL >= DEBUG_LEVEL #define _dbg_assert_(_t_, _a_) \ diff --git a/Common/LogManager.cpp b/Common/LogManager.cpp index 1159a75c3..3b0d6d097 100644 --- a/Common/LogManager.cpp +++ b/Common/LogManager.cpp @@ -168,7 +168,7 @@ void LogManager::Log(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, const if (!log || !log->IsEnabled() || level > log->GetLevel() || ! log->HasListeners()) return; - static const char level_to_char[7] = "-NEWID"; + static const char level_to_char[8] = "-NEWIDV"; char formattedTime[13]; Common::Timer::GetTimeFormatted(formattedTime); diff --git a/android/jni/NativeApp.cpp b/android/jni/NativeApp.cpp index 1d1e9a487..715bcb390 100644 --- a/android/jni/NativeApp.cpp +++ b/android/jni/NativeApp.cpp @@ -65,6 +65,7 @@ public: { switch (level) { + case LogTypes::LVERBOSE: case LogTypes::LDEBUG: case LogTypes::LINFO: ILOG("%s", msg); diff --git a/headless/Headless.cpp b/headless/Headless.cpp index 96ddf0061..adefaaf35 100644 --- a/headless/Headless.cpp +++ b/headless/Headless.cpp @@ -27,6 +27,9 @@ public: { switch (level) { + case LogTypes::LVERBOSE: + fprintf(stderr, "V %s", msg); + break; case LogTypes::LDEBUG: fprintf(stderr, "D %s", msg); break; From 913dca69efe444cc94729b4352fd595d0b6ce9e6 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Sun, 10 Mar 2013 22:56:24 -0700 Subject: [PATCH 3/6] Turn down logging for things that can be inferred. If you see a thread switch for a vblank wait, you know what happened. --- Core/CoreTiming.cpp | 2 +- Core/HLE/sceDisplay.cpp | 15 +++++++-------- Core/HLE/sceKernelInterrupt.cpp | 4 ++-- Core/HLE/sceKernelThread.cpp | 5 +++-- 4 files changed, 13 insertions(+), 13 deletions(-) diff --git a/Core/CoreTiming.cpp b/Core/CoreTiming.cpp index 77776468b..ea33031d7 100644 --- a/Core/CoreTiming.cpp +++ b/Core/CoreTiming.cpp @@ -527,7 +527,7 @@ void Idle(int maxIdle) } } - DEBUG_LOG(CPU, "Idle for %i cycles! (%f ms)", cyclesDown, cyclesDown / (float)(CPU_HZ * 0.001f)); + VERBOSE_LOG(CPU, "Idle for %i cycles! (%f ms)", cyclesDown, cyclesDown / (float)(CPU_HZ * 0.001f)); idledCycles += cyclesDown; currentMIPS->downcount -= cyclesDown; diff --git a/Core/HLE/sceDisplay.cpp b/Core/HLE/sceDisplay.cpp index 2eebe46f1..7b415d1e2 100644 --- a/Core/HLE/sceDisplay.cpp +++ b/Core/HLE/sceDisplay.cpp @@ -529,7 +529,7 @@ u32 sceDisplayGetFramebuf(u32 topaddrPtr, u32 linesizePtr, u32 pixelFormatPtr, i } u32 sceDisplayWaitVblankStart() { - DEBUG_LOG(HLE,"sceDisplayWaitVblankStart()"); + VERBOSE_LOG(HLE,"sceDisplayWaitVblankStart()"); vblankWaitingThreads.push_back(WaitVBlankInfo(__KernelGetCurThread())); __KernelWaitCurThread(WAITTYPE_VBLANK, 0, 0, 0, false, "vblank start waited"); return 0; @@ -537,7 +537,7 @@ u32 sceDisplayWaitVblankStart() { u32 sceDisplayWaitVblank() { if (!isVblank) { - DEBUG_LOG(HLE,"sceDisplayWaitVblank()"); + VERBOSE_LOG(HLE,"sceDisplayWaitVblank()"); vblankWaitingThreads.push_back(WaitVBlankInfo(__KernelGetCurThread())); __KernelWaitCurThread(WAITTYPE_VBLANK, 0, 0, 0, false, "vblank waited"); return 0; @@ -549,7 +549,7 @@ u32 sceDisplayWaitVblank() { } u32 sceDisplayWaitVblankStartMulti(int vblanks) { - DEBUG_LOG(HLE,"sceDisplayWaitVblankStartMulti()"); + VERBOSE_LOG(HLE,"sceDisplayWaitVblankStartMulti()"); vblankWaitingThreads.push_back(WaitVBlankInfo(__KernelGetCurThread(), vblanks)); __KernelWaitCurThread(WAITTYPE_VBLANK, 0, 0, 0, false, "vblank start multi waited"); return 0; @@ -557,7 +557,7 @@ u32 sceDisplayWaitVblankStartMulti(int vblanks) { u32 sceDisplayWaitVblankCB() { if (!isVblank) { - DEBUG_LOG(HLE,"sceDisplayWaitVblankCB()"); + VERBOSE_LOG(HLE,"sceDisplayWaitVblankCB()"); vblankWaitingThreads.push_back(WaitVBlankInfo(__KernelGetCurThread())); __KernelWaitCurThread(WAITTYPE_VBLANK, 0, 0, 0, true, "vblank waited"); return 0; @@ -569,22 +569,21 @@ u32 sceDisplayWaitVblankCB() { } u32 sceDisplayWaitVblankStartCB() { - DEBUG_LOG(HLE,"sceDisplayWaitVblankStartCB()"); + VERBOSE_LOG(HLE,"sceDisplayWaitVblankStartCB()"); vblankWaitingThreads.push_back(WaitVBlankInfo(__KernelGetCurThread())); __KernelWaitCurThread(WAITTYPE_VBLANK, 0, 0, 0, true, "vblank start waited"); return 0; } u32 sceDisplayWaitVblankStartMultiCB(int vblanks) { - DEBUG_LOG(HLE,"sceDisplayWaitVblankStartMultiCB()"); + VERBOSE_LOG(HLE,"sceDisplayWaitVblankStartMultiCB()"); vblankWaitingThreads.push_back(WaitVBlankInfo(__KernelGetCurThread(), vblanks)); __KernelWaitCurThread(WAITTYPE_VBLANK, 0, 0, 0, true, "vblank start multi waited"); return 0; } u32 sceDisplayGetVcount() { - // Too spammy - // DEBUG_LOG(HLE,"%i=sceDisplayGetVcount()", vCount); + VERBOSE_LOG(HLE,"%i=sceDisplayGetVcount()", vCount); hleEatMicro(2); return vCount; diff --git a/Core/HLE/sceKernelInterrupt.cpp b/Core/HLE/sceKernelInterrupt.cpp index b0196b75d..468243ad1 100644 --- a/Core/HLE/sceKernelInterrupt.cpp +++ b/Core/HLE/sceKernelInterrupt.cpp @@ -66,7 +66,7 @@ static bool inInterrupt; void sceKernelCpuSuspendIntr() { - //LOG(HLE,"sceKernelCpuSuspendIntr"); // very spammy + VERBOSE_LOG(HLE, "sceKernelCpuSuspendIntr"); int returnValue; if (__InterruptsEnabled()) { @@ -82,7 +82,7 @@ void sceKernelCpuSuspendIntr() void sceKernelCpuResumeIntr(u32 enable) { - //LOG(HLE,"sceKernelCpuResumeIntr(%i)", enable); // very spammy + VERBOSE_LOG(HLE, "sceKernelCpuResumeIntr(%i)", enable); if (enable) { __EnableInterrupts(); diff --git a/Core/HLE/sceKernelThread.cpp b/Core/HLE/sceKernelThread.cpp index a7286f105..b92f792ee 100644 --- a/Core/HLE/sceKernelThread.cpp +++ b/Core/HLE/sceKernelThread.cpp @@ -1989,11 +1989,12 @@ static void __KernelSleepThread(bool doCallbacks) { return; } - DEBUG_LOG(HLE,"sceKernelSleepThread() - wakeupCount decremented to %i", thread->nt.wakeupCount); if (thread->nt.wakeupCount > 0) { thread->nt.wakeupCount--; + DEBUG_LOG(HLE, "sceKernelSleepThread() - wakeupCount decremented to %i", thread->nt.wakeupCount); RETURN(0); } else { + VERBOSE_LOG(HLE, "sceKernelSleepThread()", thread->nt.wakeupCount); RETURN(0); __KernelWaitCurThread(WAITTYPE_SLEEP, 0, 0, 0, doCallbacks, "thread slept"); } @@ -2007,7 +2008,7 @@ void sceKernelSleepThread() //the homebrew PollCallbacks void sceKernelSleepThreadCB() { - DEBUG_LOG(HLE, "sceKernelSleepThreadCB()"); + VERBOSE_LOG(HLE, "sceKernelSleepThreadCB()"); __KernelSleepThread(true); __KernelCheckCallbacks(); } From da3af79f3bb0d0844d97aca6402e9f43d49bc083 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Sun, 10 Mar 2013 22:57:27 -0700 Subject: [PATCH 4/6] Turn down logging for LwMutexes. No one seems to have run into issues with these for a while, and they are quite noisy, since games use them as lightweight locks. --- Core/HLE/sceKernelMutex.cpp | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/Core/HLE/sceKernelMutex.cpp b/Core/HLE/sceKernelMutex.cpp index cd87a8f19..173e5bb88 100644 --- a/Core/HLE/sceKernelMutex.cpp +++ b/Core/HLE/sceKernelMutex.cpp @@ -839,7 +839,7 @@ int sceKernelTryLockLwMutex_600(u32 workareaPtr, int count) int sceKernelLockLwMutex(u32 workareaPtr, int count, u32 timeoutPtr) { - DEBUG_LOG(HLE, "sceKernelLockLwMutex(%08x, %i, %08x)", workareaPtr, count, timeoutPtr); + VERBOSE_LOG(HLE, "sceKernelLockLwMutex(%08x, %i, %08x)", workareaPtr, count, timeoutPtr); NativeLwMutexWorkarea workarea; Memory::ReadStruct(workareaPtr, &workarea); @@ -874,7 +874,7 @@ int sceKernelLockLwMutex(u32 workareaPtr, int count, u32 timeoutPtr) int sceKernelLockLwMutexCB(u32 workareaPtr, int count, u32 timeoutPtr) { - DEBUG_LOG(HLE, "sceKernelLockLwMutexCB(%08x, %i, %08x)", workareaPtr, count, timeoutPtr); + VERBOSE_LOG(HLE, "sceKernelLockLwMutexCB(%08x, %i, %08x)", workareaPtr, count, timeoutPtr); NativeLwMutexWorkarea workarea; Memory::ReadStruct(workareaPtr, &workarea); @@ -898,7 +898,7 @@ int sceKernelLockLwMutexCB(u32 workareaPtr, int count, u32 timeoutPtr) if (std::find(mutex->waitingThreads.begin(), mutex->waitingThreads.end(), threadID) == mutex->waitingThreads.end()) mutex->waitingThreads.push_back(threadID); __KernelWaitLwMutex(mutex, timeoutPtr); - __KernelWaitCurThread(WAITTYPE_LWMUTEX, workarea.uid, count, timeoutPtr, true, "lwmutex waited"); + __KernelWaitCurThread(WAITTYPE_LWMUTEX, workarea.uid, count, timeoutPtr, true, "lwmutex cb waited"); // Return value will be overwritten by wait. return 0; @@ -910,7 +910,7 @@ int sceKernelLockLwMutexCB(u32 workareaPtr, int count, u32 timeoutPtr) int sceKernelUnlockLwMutex(u32 workareaPtr, int count) { - DEBUG_LOG(HLE, "sceKernelUnlockLwMutex(%08x, %i)", workareaPtr, count); + VERBOSE_LOG(HLE, "sceKernelUnlockLwMutex(%08x, %i)", workareaPtr, count); NativeLwMutexWorkarea workarea; Memory::ReadStruct(workareaPtr, &workarea); From 9c6cfeeb262c3292f4adfae49f2ed838f378b786 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Sun, 10 Mar 2013 23:52:11 -0700 Subject: [PATCH 5/6] Fix logging during savestate. --- Core/HLE/sceKernel.cpp | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/Core/HLE/sceKernel.cpp b/Core/HLE/sceKernel.cpp index 572581b67..6891cb3e0 100644 --- a/Core/HLE/sceKernel.cpp +++ b/Core/HLE/sceKernel.cpp @@ -20,6 +20,7 @@ #include "../MIPS/MIPSCodeUtils.h" #include "../MIPS/MIPSInt.h" +#include "Common/LogManager.h" #include "../FileSystems/FileSystem.h" #include "../FileSystems/MetaFileSystem.h" #include "../PSPLoaders.h" @@ -29,7 +30,6 @@ #include "../../GPU/GPUInterface.h" #include "../../GPU/GPUState.h" - #include "__sceAudio.h" #include "sceAtrac.h" #include "sceAudio.h" @@ -442,7 +442,10 @@ void KernelObjectPool::DoState(PointerWrap &p) ERROR_LOG(HLE, "Unable to load state: different kernel object storage."); if (p.mode == p.MODE_READ) + { + hleCurrentThreadName = NULL; kernelObjects.Clear(); + } p.DoArray(occupied, maxCount); for (int i = 0; i < maxCount; ++i) From 4f1d2f0584335b949e2c3b63281b93a07df53167 Mon Sep 17 00:00:00 2001 From: "Unknown W. Brackets" Date: Mon, 11 Mar 2013 00:18:59 -0700 Subject: [PATCH 6/6] Also clear the logging thread name on shutdown. --- Core/HLE/sceKernel.cpp | 1 + 1 file changed, 1 insertion(+) diff --git a/Core/HLE/sceKernel.cpp b/Core/HLE/sceKernel.cpp index 6891cb3e0..7f82ee5a8 100644 --- a/Core/HLE/sceKernel.cpp +++ b/Core/HLE/sceKernel.cpp @@ -128,6 +128,7 @@ void __KernelShutdown() } kernelObjects.List(); INFO_LOG(HLE, "Shutting down kernel - %i kernel objects alive", kernelObjects.GetCount()); + hleCurrentThreadName = NULL; kernelObjects.Clear(); __FontShutdown();