libretro/ppsspp
1
0
Fork 0
mirror of https://github.com/libretro/ppsspp.git synced 2025-02-22 01:40:30 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Merge pull request #940 from unknownbrackets/logging

Browse Source 
Add a VERBOSE logging level + show thread name in log
This commit is contained in:
Henrik Rydgård 2013-03-11 02:21:25 -07:00
commit b770ba7809
12 changed files with 79 additions and 31 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

13
Common/Log.h
View File

@ -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 <signal.h>
@ -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_) \

32
Common/LogManager.cpp
View File

@ -26,6 +26,9 @@
#include <e32debug.h>
#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
@ -165,15 +168,34 @@ 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);
#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.

1
Common/LogManager.h
View File

@ -30,6 +30,7 @@
#define MAX_MESSAGES 8000
#define MAX_MSGLEN 1024
extern const char *hleCurrentThreadName;
// pure virtual interface
class LogListener

2
Core/CoreTiming.cpp
View File

@ -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;

15
Core/HLE/sceDisplay.cpp
View File

@ -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;

6
Core/HLE/sceKernel.cpp
View File

@ -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"
@ -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();
@ -442,7 +443,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)

4
Core/HLE/sceKernelInterrupt.cpp
View File

@ -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();

8
Core/HLE/sceKernelMutex.cpp
View File

@ -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);

23
Core/HLE/sceKernelThread.cpp
View File

@ -20,6 +20,7 @@
#include <queue>
#include <algorithm>
#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");
@ -1981,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");
}
@ -1999,7 +2008,7 @@ void sceKernelSleepThread()
//the homebrew PollCallbacks
void sceKernelSleepThreadCB()
{
DEBUG_LOG(HLE, "sceKernelSleepThreadCB()");
VERBOSE_LOG(HLE, "sceKernelSleepThreadCB()");
__KernelSleepThread(true);
__KernelCheckCallbacks();
}
@ -2360,12 +2369,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 +2389,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);
}

2
Core/HLE/sceKernelThread.h
View File

@ -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);

1
android/jni/NativeApp.cpp
View File

@ -65,6 +65,7 @@ public:
{
switch (level)
{
case LogTypes::LVERBOSE:
case LogTypes::LDEBUG:
case LogTypes::LINFO:
ILOG("%s", msg);

3
headless/Headless.cpp
View File

@ -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;