diff --git a/Common/Log.h b/Common/Log.h index 9780815b5..aa289b995 100644 --- a/Common/Log.h +++ b/Common/Log.h @@ -91,6 +91,7 @@ void GenericLog(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, __attribute__((format(printf, 5, 6))) #endif ; +bool GenericLogEnabled(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type); #if defined(LOGGING) || defined(_DEBUG) || defined(DEBUGFAST) || defined(_WIN32) #define MAX_LOGLEVEL DEBUG_LEVEL diff --git a/Common/LogManager.cpp b/Common/LogManager.cpp index c66d8c233..0da1da940 100644 --- a/Common/LogManager.cpp +++ b/Common/LogManager.cpp @@ -46,6 +46,12 @@ void GenericLog(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, va_end(args); } +bool GenericLogEnabled(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type) { + if (LogManager::GetInstance()) + return g_Config.bEnableLogging && LogManager::GetInstance()->IsEnabled(level, type); + return false; +} + LogManager *LogManager::logManager_ = NULL; struct LogNameTableEntry { @@ -219,6 +225,13 @@ void LogManager::Log(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, const log->Trigger(level, msg); } +bool LogManager::IsEnabled(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type) { + LogChannel *log = log_[type]; + if (level > log->GetLevel() || !log->IsEnabled() || !log->HasListeners()) + return false; + return true; +} + void LogManager::Init() { logManager_ = new LogManager(); } diff --git a/Common/LogManager.h b/Common/LogManager.h index d0e75a94f..452ffdf86 100644 --- a/Common/LogManager.h +++ b/Common/LogManager.h @@ -140,6 +140,7 @@ public: void Log(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, const char *file, int line, const char *fmt, va_list args); + bool IsEnabled(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type); LogChannel *GetLogChannel(LogTypes::LOG_TYPE type) { return log_[type]; @@ -183,7 +184,7 @@ public: return ringLog_; } - static LogManager* GetInstance() { + static inline LogManager* GetInstance() { return logManager_; } diff --git a/Core/HLE/HLE.cpp b/Core/HLE/HLE.cpp index 13d5961bc..b2f95dfd8 100644 --- a/Core/HLE/HLE.cpp +++ b/Core/HLE/HLE.cpp @@ -15,6 +15,7 @@ // Official git repository and contact information can be found at // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/. +#include #include #include #include @@ -62,6 +63,7 @@ static std::vector moduleDB; static int delayedResultEvent = -1; static int hleAfterSyscall = HLE_AFTER_NOTHING; static const char *hleAfterSyscallReschedReason; +static const HLEFunction *latestSyscall = nullptr; void hleDelayResultFinish(u64 userdata, int cycleslate) { @@ -100,6 +102,7 @@ void HLEDoState(PointerWrap &p) void HLEShutdown() { hleAfterSyscall = HLE_AFTER_NOTHING; + latestSyscall = nullptr; moduleDB.clear(); } @@ -434,6 +437,7 @@ inline void updateSyscallStats(int modulenum, int funcnum, double total) inline void CallSyscallWithFlags(const HLEFunction *info) { + latestSyscall = info; const u32 flags = info->flags; if (flags & HLE_CLEAR_STACK_BYTES) { @@ -462,6 +466,7 @@ inline void CallSyscallWithFlags(const HLEFunction *info) inline void CallSyscallWithoutFlags(const HLEFunction *info) { + latestSyscall = info; info->func(); if (hleAfterSyscall != HLE_AFTER_NOTHING) @@ -554,3 +559,113 @@ void CallSyscall(MIPSOpcode op) updateSyscallStats(modulenum, funcnum, total); } } + +size_t hleFormatLogArgs(char *message, size_t sz, const char *argmask) { + char *p = message; + size_t used = 0; + +#define APPEND_FMT(...) do { \ + if (used < sz) { \ + size_t c = snprintf(p, sz - used, __VA_ARGS__); \ + used += c; \ + p += c; \ + } \ +} while (false) + + for (size_t i = 0, n = strlen(argmask); i < n; ++i) { + switch (argmask[i]) { + case 'p': + if (Memory::IsValidAddress(PARAM(i))) { + APPEND_FMT("%08x[%08x]", PARAM(i), Memory::Read_U32(PARAM(i))); + } else { + APPEND_FMT("%08x[invalid]", PARAM(i)); + } + break; + + case 's': + if (Memory::IsValidAddress(PARAM(i))) { + APPEND_FMT("%s", Memory::GetCharPointer(PARAM(i))); + } else { + APPEND_FMT("(invalid)"); + } + break; + + case 'x': + APPEND_FMT("%08x", PARAM(i)); + break; + + case 'i': + APPEND_FMT("%d", PARAM(i)); + break; + + default: + _assert_msg_(HLE, false, "Invalid argmask character: %c", argmask[i]); + APPEND_FMT(" -- invalid arg format: %c -- %08x", argmask[i], PARAM(i)); + break; + } + if (i + 1 < n) { + APPEND_FMT(", "); + } + } + + if (used > sz) { + message[sz - 1] = '\0'; + } else { + message[used] = '\0'; + } + +#undef APPEND_FMT + return used; +} + +u32 hleDoLog(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u32 res, char retmask, const char *argmask, const char *file, int line, const char *reportTag, const char *reason, ...) { + if (level > MAX_LOGLEVEL || !GenericLogEnabled(level, t)) { + return res; + } + + char formatted_reason[4096] = {0}; + if (reason != nullptr) { + va_list args; + va_start(args, reason); + formatted_reason[0] = ':'; + formatted_reason[1] = ' '; + vsnprintf(formatted_reason + 2, sizeof(formatted_reason) - 3, reason, args); + formatted_reason[sizeof(formatted_reason)] = '\0'; + va_end(args); + } + + char formatted_args[4096]; + hleFormatLogArgs(formatted_args, sizeof(formatted_args), argmask); + + const char *fmt; + if (retmask == 'x') { + fmt = "%08x=%s(%s)%s"; + } else if (retmask == 'i') { + fmt = "%d=%s(%s)%s"; + } else { + _assert_msg_(HLE, false, "Invalid return format: %c", retmask); + fmt = "%08x=%s(%s)%s"; + } + + GenericLog(level, t, file, line, fmt, res, latestSyscall->name, formatted_args, formatted_reason); + + if (reportTag != nullptr) { + // A blank string means always log, not just once. + if (reportTag[0] == '\0' || Reporting::ShouldLogOnce(reportTag)) { + // Here we want the original key, so that different args, etc. group together. + std::string key = std::string("%08x=") + latestSyscall->name + "(%s)"; + if (reason != nullptr) + key += std::string(": ") + reason; + + char formatted_message[8192]; + snprintf(formatted_message, sizeof(formatted_message), fmt, res, latestSyscall->name, formatted_args, formatted_reason); + Reporting::ReportMessageFormatted(key.c_str(), formatted_message); + } + } + + return res; +} + +u32 hleDoLog(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u32 res, char retmask, const char *argmask, const char *file, int line, const char *reportTag) { + return hleDoLog(t, level, res, retmask, argmask, file, line, reportTag, nullptr); +} diff --git a/Core/HLE/HLE.h b/Core/HLE/HLE.h index 46eb3dfd8..1515c8cfb 100644 --- a/Core/HLE/HLE.h +++ b/Core/HLE/HLE.h @@ -18,6 +18,7 @@ #pragma once #include "Common/CommonTypes.h" +#include "Common/Log.h" #include "Core/MIPS/MIPS.h" class PointerWrap; @@ -125,3 +126,20 @@ const HLEFunction *GetSyscallInfo(MIPSOpcode op); // For jit, takes arg: const HLEFunction * void *GetQuickSyscallFunc(MIPSOpcode op); +u32 hleDoLog(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u32 res, char retmask, const char *argmask, const char *file, int line, const char *reportTag, const char *reason, ...); +u32 hleDoLog(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u32 res, char retmask, const char *argmask, const char *file, int line, const char *reportTag); + +// Only one side of the ?: is evaluated (per c++ standard), so this should be safe. +#define hleLogHelper(t, level, res, retmask, argmask, ...) (LogTypes::level > MAX_LOGLEVEL ? res : hleDoLog(LogTypes::t, LogTypes::level, res, retmask, argmask, __FILE__, __LINE__, nullptr, __VA_ARGS__)) +#define hleLogError(t, res, argmask, ...) hleLogHelper(t, LERROR, res, 'x', argmask, __VA_ARGS__) +#define hleLogWarning(t, res, argmask, ...) hleLogHelper(t, LWARNING, res, 'x', argmask, __VA_ARGS__) +#define hleLogDebug(t, res, argmask, ...) hleLogHelper(t, LDEBUG, res, 'x', argmask, __VA_ARGS__) +#define hleLogSuccessX(t, res, argmask, ...) hleLogHelper(t, LDEBUG, res, 'x', argmask, __VA_ARGS__) +#define hleLogSuccessI(t, res, argmask, ...) hleLogHelper(t, LDEBUG, res, 'i', argmask, __VA_ARGS__) +#define hleLogSuccessVerboseX(t, res, argmask, ...) hleLogHelper(t, LVERBOSE, res, 'x', argmask, __VA_ARGS__) +#define hleLogSuccessVerboseI(t, res, argmask, ...) hleLogHelper(t, LVERBOSE, res, 'x', argmask, __VA_ARGS__) + +#define hleReportError(t, res, argmask, ...) hleDoLog(LogTypes::t, LogTypes::LERROR, res, 'x', argmask, __FILE__, __LINE__, "", __VA_ARGS__) +#define hleReportWarning(t, res, argmask, ...) hleDoLog(LogTypes::t, LogTypes::LWARNING, res, 'x', argmask, __FILE__, __LINE__, "", __VA_ARGS__) +#define hleReportDebug(t, res, argmask, ...) hleDoLog(LogTypes::t, LogTypes::LDEBUG, res, 'x', argmask, __FILE__, __LINE__, "", __VA_ARGS__) +#define hleReportVerbose(t, res, argmask, ...) hleDoLog(LogTypes::t, LogTypes::LVERBOSE, res, 'x', argmask, __FILE__, __LINE__, "", __VA_ARGS__) diff --git a/Core/HLE/sceKernelThread.cpp b/Core/HLE/sceKernelThread.cpp index 678f4f12a..8096841f9 100644 --- a/Core/HLE/sceKernelThread.cpp +++ b/Core/HLE/sceKernelThread.cpp @@ -3010,8 +3010,6 @@ SceUID sceKernelCreateCallback(const char *name, u32 entrypoint, u32 signalArg) int sceKernelDeleteCallback(SceUID cbId) { - DEBUG_LOG(SCEKERNEL, "sceKernelDeleteCallback(%i)", cbId); - u32 error; Callback *cb = kernelObjects.Get(cbId, error); if (cb) @@ -3022,38 +3020,35 @@ int sceKernelDeleteCallback(SceUID cbId) if (cb->nc.notifyCount != 0) readyCallbacksCount--; - return kernelObjects.Destroy(cbId); + return hleLogSuccessI(SCEKERNEL, kernelObjects.Destroy(cbId), "d"); + } else { + return hleLogError(SCEKERNEL, error, "i", "bad cbId"); } - return error; } // Generally very rarely used, but Numblast uses it like candy. int sceKernelNotifyCallback(SceUID cbId, int notifyArg) { - DEBUG_LOG(SCEKERNEL,"sceKernelNotifyCallback(%i, %i)", cbId, notifyArg); u32 error; Callback *cb = kernelObjects.Get(cbId, error); if (cb) { __KernelNotifyCallback(cbId, notifyArg); - return 0; + return hleLogSuccessI(SCEKERNEL, 0, "ii"); } else { - ERROR_LOG(SCEKERNEL, "sceKernelCancelCallback(%i) - bad cbId", cbId); - return error; + return hleLogError(SCEKERNEL, error, "ii", "bad cbId"); } } int sceKernelCancelCallback(SceUID cbId) { - DEBUG_LOG(SCEKERNEL, "sceKernelCancelCallback(%i)", cbId); u32 error; Callback *cb = kernelObjects.Get(cbId, error); if (cb) { // This just resets the notify count. cb->nc.notifyArg = 0; - return 0; + return hleLogSuccessI(SCEKERNEL, 0, "i"); } else { - ERROR_LOG(SCEKERNEL, "sceKernelCancelCallback(%i) - bad cbId", cbId); - return error; + return hleLogError(SCEKERNEL, error, "i", "bad cbId"); } } @@ -3062,10 +3057,9 @@ int sceKernelGetCallbackCount(SceUID cbId) u32 error; Callback *cb = kernelObjects.Get(cbId, error); if (cb) { - return cb->nc.notifyCount; + return hleLogSuccessVerboseI(SCEKERNEL, cb->nc.notifyCount, "i"); } else { - ERROR_LOG(SCEKERNEL, "sceKernelGetCallbackCount(%i) - bad cbId", cbId); - return error; + return hleLogError(SCEKERNEL, error, "i", "bad cbId"); } } @@ -3074,40 +3068,30 @@ int sceKernelReferCallbackStatus(SceUID cbId, u32 statusAddr) u32 error; Callback *c = kernelObjects.Get(cbId, error); if (c) { - DEBUG_LOG(SCEKERNEL, "sceKernelReferCallbackStatus(%i, %08x)", cbId, statusAddr); if (Memory::IsValidAddress(statusAddr) && Memory::Read_U32(statusAddr) != 0) { Memory::WriteStruct(statusAddr, &c->nc); + return hleLogSuccessI(SCEKERNEL, 0, "ip"); + } else { + return hleLogDebug(SCEKERNEL, 0, "ip", "struct size was 0"); } - return 0; } else { - ERROR_LOG(SCEKERNEL, "sceKernelReferCallbackStatus(%i, %08x) - bad cbId", cbId, statusAddr); - return error; + return hleLogError(SCEKERNEL, error, "ip", "bad cbId"); } } u32 sceKernelExtendThreadStack(u32 size, u32 entryAddr, u32 entryParameter) { if (size < 512) - { - ERROR_LOG_REPORT(SCEKERNEL, "sceKernelExtendThreadStack(%08x, %08x, %08x) - stack size too small", size, entryAddr, entryParameter); - return SCE_KERNEL_ERROR_ILLEGAL_STACK_SIZE; - } + return hleReportError(SCEKERNEL, SCE_KERNEL_ERROR_ILLEGAL_STACK_SIZE, "xxx", "stack size too small"); Thread *thread = __GetCurrentThread(); if (!thread) - { - ERROR_LOG_REPORT(SCEKERNEL, "sceKernelExtendThreadStack(%08x, %08x, %08x) - not on a thread?", size, entryAddr, entryParameter); - return -1; - } + return hleReportError(SCEKERNEL, -1, "xxx", "not on a thread?"); if (!thread->PushExtendedStack(size)) - { - ERROR_LOG_REPORT(SCEKERNEL, "sceKernelExtendThreadStack(%08x, %08x, %08x) - could not allocate new stack", size, entryAddr, entryParameter); - return SCE_KERNEL_ERROR_NO_MEMORY; - } + return hleReportError(SCEKERNEL, SCE_KERNEL_ERROR_NO_MEMORY, "xxx", "could not allocate new stack"); // The stack has been changed now, so it's do or die time. - DEBUG_LOG(SCEKERNEL, "sceKernelExtendThreadStack(%08x, %08x, %08x)", size, entryAddr, entryParameter); // Push the old SP, RA, and PC onto the stack (so we can restore them later.) Memory::Write_U32(currentMIPS->r[MIPS_REG_RA], thread->currentStack.end - 4); @@ -3121,7 +3105,7 @@ u32 sceKernelExtendThreadStack(u32 size, u32 entryAddr, u32 entryParameter) currentMIPS->r[MIPS_REG_SP] = thread->currentStack.end - 0x10; hleSkipDeadbeef(); - return 0; + return hleLogSuccessI(SCEKERNEL, 0, "xxx"); } void __KernelReturnFromExtendStack() diff --git a/Core/Reporting.cpp b/Core/Reporting.cpp index c7e2b05f3..647e6b9c6 100644 --- a/Core/Reporting.cpp +++ b/Core/Reporting.cpp @@ -403,6 +403,21 @@ namespace Reporting th.detach(); } + void ReportMessageFormatted(const char *message, const char *formatted) + { + if (!IsEnabled() || CheckSpamLimited()) + return; + + int pos = payloadBufferPos++ % PAYLOAD_BUFFER_SIZE; + Payload &payload = payloadBuffer[pos]; + payload.type = MESSAGE; + payload.string1 = message; + payload.string2 = formatted; + + std::thread th(Process, pos); + th.detach(); + } + void ReportCompatibility(const char *compat, int graphics, int speed, int gameplay) { if (!IsEnabled()) diff --git a/Core/Reporting.h b/Core/Reporting.h index a59ad9d7b..4684c15c1 100644 --- a/Core/Reporting.h +++ b/Core/Reporting.h @@ -65,6 +65,9 @@ namespace Reporting // Report a message string, using the format string as a key. void ReportMessage(const char *message, ...); + // The same, but with a preformatted version (message is still the key.) + void ReportMessageFormatted(const char *message, const char *formatted); + // Report the compatibility of the current game / configuration. void ReportCompatibility(const char *compat, int graphics, int speed, int gameplay);