From 6dfd97f0b6b3463b025ff7344ecb48c5f1782e48 Mon Sep 17 00:00:00 2001 From: Nekotekina Date: Sat, 1 Feb 2020 11:36:09 +0300 Subject: [PATCH] Modernize SPU logging (spu_log variable) and remove log legacy Remove legacy macro (LOG_ERROR, etc) --- Utilities/Log.h | 16 ---- rpcs3/Emu/Cell/Modules/cellSpursSpu.cpp | 16 ++-- rpcs3/Emu/Cell/RawSPUThread.cpp | 4 +- rpcs3/Emu/Cell/SPUASMJITRecompiler.cpp | 20 ++-- rpcs3/Emu/Cell/SPURecompiler.cpp | 120 ++++++++++++------------ rpcs3/Emu/Cell/SPUThread.cpp | 44 ++++----- rpcs3/Emu/Cell/SPUThread.h | 2 + rpcs3/Emu/Cell/lv2/sys_spu.cpp | 12 +-- 8 files changed, 110 insertions(+), 124 deletions(-) diff --git a/Utilities/Log.h b/Utilities/Log.h index 4c68112560..bf651e2974 100644 --- a/Utilities/Log.h +++ b/Utilities/Log.h @@ -117,20 +117,4 @@ namespace logs #define LOG_CHANNEL(ch, ...) inline ::logs::channel ch(::logs::make_channel_name(#ch, ##__VA_ARGS__)) -// Legacy: - -namespace logs -{ - /* Small set of predefined channels */ - LOG_CHANNEL(SPU); -} - -#define LOG_SUCCESS(ch, fmt, ...) logs::ch.success("" fmt, ##__VA_ARGS__) -#define LOG_NOTICE(ch, fmt, ...) logs::ch.notice ("" fmt, ##__VA_ARGS__) -#define LOG_WARNING(ch, fmt, ...) logs::ch.warning("" fmt, ##__VA_ARGS__) -#define LOG_ERROR(ch, fmt, ...) logs::ch.error ("" fmt, ##__VA_ARGS__) -#define LOG_TODO(ch, fmt, ...) logs::ch.todo ("" fmt, ##__VA_ARGS__) -#define LOG_TRACE(ch, fmt, ...) logs::ch.trace ("" fmt, ##__VA_ARGS__) -#define LOG_FATAL(ch, fmt, ...) logs::ch.fatal ("" fmt, ##__VA_ARGS__) - LOG_CHANNEL(rsx_log, "RSX"); diff --git a/rpcs3/Emu/Cell/Modules/cellSpursSpu.cpp b/rpcs3/Emu/Cell/Modules/cellSpursSpu.cpp index cb0fb5b2c5..b8566aa691 100644 --- a/rpcs3/Emu/Cell/Modules/cellSpursSpu.cpp +++ b/rpcs3/Emu/Cell/Modules/cellSpursSpu.cpp @@ -866,7 +866,7 @@ void spursSysServiceMain(spu_thread& spu, u32 pollStatus) if (!ctxt->spurs.aligned()) { - LOG_ERROR(SPU, "spursSysServiceMain(): invalid spurs alignment"); + spu_log.error("spursSysServiceMain(): invalid spurs alignment"); spursHalt(spu); } @@ -884,7 +884,7 @@ void spursSysServiceMain(spu_thread& spu, u32 pollStatus) // Halt if already initialised if (spurs->sysSrvOnSpu & (1 << ctxt->spuNum)) { - LOG_ERROR(SPU, "spursSysServiceMain(): already initialized"); + spu_log.error("spursSysServiceMain(): already initialized"); spursHalt(spu); } @@ -1424,7 +1424,7 @@ s32 spursTasksetProcessRequest(spu_thread& spu, s32 request, u32* taskId, u32* i if ((taskset->waiting & taskset->running) != _0 || (taskset->ready & taskset->pending_ready) != _0 || ((taskset->running | taskset->ready | taskset->pending_ready | taskset->signalled | taskset->waiting) & ~taskset->enabled) != _0) { - LOG_ERROR(SPU, "Invalid taskset state"); + spu_log.error("Invalid taskset state"); spursHalt(spu); } @@ -1562,7 +1562,7 @@ s32 spursTasksetProcessRequest(spu_thread& spu, s32 request, u32* taskId, u32* i } break; default: - LOG_ERROR(SPU, "Unknown taskset request"); + spu_log.error("Unknown taskset request"); spursHalt(spu); } @@ -1637,7 +1637,7 @@ void spursTasksetExit(spu_thread& spu) // Not sure why this check exists. Perhaps to check for memory corruption. if (memcmp(ctxt->moduleId, "SPURSTASK MODULE", 16) != 0) { - LOG_ERROR(SPU, "spursTasksetExit(): memory corruption"); + spu_log.error("spursTasksetExit(): memory corruption"); spursHalt(spu); } @@ -1761,7 +1761,7 @@ void spursTasksetDispatch(spu_thread& spu) u32 lowestLoadAddr; if (spursTasksetLoadElf(spu, &entryPoint, &lowestLoadAddr, taskInfo->elf.addr(), false) != CELL_OK) { - LOG_ERROR(SPU, "spursTaskLoadElf() failed"); + spu_log.error("spursTaskLoadElf() failed"); spursHalt(spu); } @@ -1809,7 +1809,7 @@ void spursTasksetDispatch(spu_thread& spu) u32 entryPoint; if (spursTasksetLoadElf(spu, &entryPoint, nullptr, taskInfo->elf.addr(), true) != CELL_OK) { - LOG_ERROR(SPU, "spursTasksetLoadElf() failed"); + spu_log.error("spursTasksetLoadElf() failed"); spursHalt(spu); } } @@ -1917,7 +1917,7 @@ s32 spursTasksetProcessSyscall(spu_thread& spu, u32 syscallNum, u32 args) case CELL_SPURS_TASK_SYSCALL_RECV_WKL_FLAG: if (args == 0) { // TODO: Figure this out - LOG_ERROR(SPU, "args == 0"); + spu_log.error("args == 0"); //spursHalt(spu); } diff --git a/rpcs3/Emu/Cell/RawSPUThread.cpp b/rpcs3/Emu/Cell/RawSPUThread.cpp index 73fcd4f2d9..09561a68fe 100644 --- a/rpcs3/Emu/Cell/RawSPUThread.cpp +++ b/rpcs3/Emu/Cell/RawSPUThread.cpp @@ -67,7 +67,7 @@ bool spu_thread::read_reg(const u32 addr, u32& value) } } - LOG_ERROR(SPU, "RawSPUThread[%d]: Read32(0x%x): unknown/illegal offset (0x%x)", index, addr, offset); + spu_log.error("RawSPUThread[%d]: Read32(0x%x): unknown/illegal offset (0x%x)", index, addr, offset); return false; } @@ -259,7 +259,7 @@ bool spu_thread::write_reg(const u32 addr, const u32 value) } } - LOG_ERROR(SPU, "RawSPUThread[%d]: Write32(0x%x, value=0x%x): unknown/illegal offset (0x%x)", index, addr, value, offset); + spu_log.error("RawSPUThread[%d]: Write32(0x%x, value=0x%x): unknown/illegal offset (0x%x)", index, addr, value, offset); return false; } diff --git a/rpcs3/Emu/Cell/SPUASMJITRecompiler.cpp b/rpcs3/Emu/Cell/SPUASMJITRecompiler.cpp index a6c254b556..cf388d5dc5 100644 --- a/rpcs3/Emu/Cell/SPUASMJITRecompiler.cpp +++ b/rpcs3/Emu/Cell/SPUASMJITRecompiler.cpp @@ -781,7 +781,7 @@ spu_function_t spu_recompiler::compile(spu_program&& _func) // Ignore hole if (m_pos + 1) { - LOG_ERROR(SPU, "Unexpected fallthrough to 0x%x", pos); + spu_log.error("Unexpected fallthrough to 0x%x", pos); branch_fixed(spu_branch_target(pos)); m_pos = -1; } @@ -901,7 +901,7 @@ spu_function_t spu_recompiler::compile(spu_program&& _func) return nullptr; } - LOG_FATAL(SPU, "Failed to build a function"); + spu_log.fatal("Failed to build a function"); } // Install compiled function pointer @@ -1082,7 +1082,7 @@ void spu_recompiler::branch_indirect(spu_opcode_t op, bool jt, bool ret) auto _throw = [](spu_thread* _spu) { _spu->state += cpu_flag::dbg_pause; - LOG_FATAL(SPU, "SPU Interrupts not implemented (mask=0x%x)", +_spu->ch_event_mask); + spu_log.fatal("SPU Interrupts not implemented (mask=0x%x)", +_spu->ch_event_mask); spu_runtime::g_escape(_spu); }; @@ -1231,7 +1231,7 @@ void spu_recompiler::fall(spu_opcode_t op) if (!_func(*_spu, {opcode})) { _spu->state += cpu_flag::dbg_pause; - LOG_FATAL(SPU, "spu_recompiler::fall(): unexpected interpreter call (op=0x%08x)", opcode); + spu_log.fatal("spu_recompiler::fall(): unexpected interpreter call (op=0x%08x)", opcode); spu_runtime::g_escape(_spu); } }; @@ -1362,7 +1362,7 @@ void spu_recompiler::get_events() auto _throw = [](spu_thread* _spu) { _spu->state += cpu_flag::dbg_pause; - LOG_FATAL(SPU, "SPU Events not implemented (mask=0x%x).", +_spu->ch_event_mask); + spu_log.fatal("SPU Events not implemented (mask=0x%x).", +_spu->ch_event_mask); spu_runtime::g_escape(_spu); }; @@ -1386,7 +1386,7 @@ void spu_recompiler::UNK(spu_opcode_t op) auto gate = [](spu_thread* _spu, u32 op) { _spu->state += cpu_flag::dbg_pause; - LOG_FATAL(SPU, "Unknown/Illegal instruction (0x%08x)" HERE, op); + spu_log.fatal("Unknown/Illegal instruction (0x%08x)" HERE, op); spu_runtime::g_escape(_spu); }; @@ -1584,7 +1584,7 @@ void spu_recompiler::RDCH(spu_opcode_t op) } case SPU_RdDec: { - LOG_WARNING(SPU, "[0x%x] RDCH: RdDec", m_pos); + spu_log.warning("[0x%x] RDCH: RdDec", m_pos); auto sub1 = [](spu_thread* _spu, v128* _res) { @@ -1631,7 +1631,7 @@ void spu_recompiler::RDCH(spu_opcode_t op) } case SPU_RdEventStat: { - LOG_WARNING(SPU, "[0x%x] RDCH: RdEventStat", m_pos); + spu_log.warning("[0x%x] RDCH: RdEventStat", m_pos); get_events(); Label wait = c->newLabel(); Label ret = c->newLabel(); @@ -1744,7 +1744,7 @@ void spu_recompiler::RCHCNT(spu_opcode_t op) } case SPU_RdEventStat: { - LOG_WARNING(SPU, "[0x%x] RCHCNT: RdEventStat", m_pos); + spu_log.warning("[0x%x] RCHCNT: RdEventStat", m_pos); get_events(); c->setnz(addr->r8()); c->movzx(*addr, addr->r8()); @@ -2745,7 +2745,7 @@ void spu_recompiler::BI(spu_opcode_t op) if (found == m_targets.end()) { - LOG_ERROR(SPU, "[0x%x] BI: no targets", m_pos); + spu_log.error("[0x%x] BI: no targets", m_pos); } c->mov(*addr, SPU_OFF_32(gpr, op.ra, &v128::_u32, 3)); diff --git a/rpcs3/Emu/Cell/SPURecompiler.cpp b/rpcs3/Emu/Cell/SPURecompiler.cpp index ec0a46f0d6..e3547f5ca8 100644 --- a/rpcs3/Emu/Cell/SPURecompiler.cpp +++ b/rpcs3/Emu/Cell/SPURecompiler.cpp @@ -384,7 +384,7 @@ void spu_cache::initialize() if (!cache) { - LOG_ERROR(SPU, "Failed to initialize SPU cache at: %s", loc); + spu_log.error("Failed to initialize SPU cache at: %s", loc); return; } @@ -406,7 +406,7 @@ void spu_cache::initialize() if (compiler->compile({}) && spu_runtime::g_interpreter) { - LOG_SUCCESS(SPU, "SPU Runtime: Built the interpreter."); + spu_log.success("SPU Runtime: Built the interpreter."); if (g_cfg.core.spu_decoder != spu_decoder_type::llvm) { @@ -415,7 +415,7 @@ void spu_cache::initialize() } else { - LOG_FATAL(SPU, "SPU Runtime: Failed to build the interpreter."); + spu_log.fatal("SPU Runtime: Failed to build the interpreter."); } } } @@ -484,7 +484,7 @@ void spu_cache::initialize() if (func2 != func) { - LOG_ERROR(SPU, "[0x%05x] SPU Analyser failed, %u vs %u", func2.entry_point, func2.data.size(), size0); + spu_log.error("[0x%05x] SPU Analyser failed, %u vs %u", func2.entry_point, func2.data.size(), size0); } else if (!compiler->compile(std::move(func2))) { @@ -507,19 +507,19 @@ void spu_cache::initialize() if (Emu.IsStopped()) { - LOG_ERROR(SPU, "SPU Runtime: Cache building aborted."); + spu_log.error("SPU Runtime: Cache building aborted."); return; } if (fail_flag) { - LOG_FATAL(SPU, "SPU Runtime: Cache building failed (out of memory)."); + spu_log.fatal("SPU Runtime: Cache building failed (out of memory)."); return; } if (compilers.size() && !func_list.empty()) { - LOG_SUCCESS(SPU, "SPU Runtime: Built %u functions.", func_list.size()); + spu_log.success("SPU Runtime: Built %u functions.", func_list.size()); } // Initialize global cache instance @@ -797,7 +797,7 @@ spu_function_t spu_runtime::rebuild_ubertrampoline(u32 id_inst) if (w.level >= w.beg->first.size() || w.level >= it->first.size()) { // If functions cannot be compared, assume smallest function - LOG_ERROR(SPU, "Trampoline simplified at ??? (level=%u)", w.level); + spu_log.error("Trampoline simplified at ??? (level=%u)", w.level); make_jump(0xe9, w.beg->second); // jmp rel32 continue; } @@ -829,7 +829,7 @@ spu_function_t spu_runtime::rebuild_ubertrampoline(u32 id_inst) if (it == m_flat_list.end()) { - LOG_ERROR(SPU, "Trampoline simplified (II) at ??? (level=%u)", w.level); + spu_log.error("Trampoline simplified (II) at ??? (level=%u)", w.level); make_jump(0xe9, w.beg->second); // jmp rel32 continue; } @@ -1086,7 +1086,7 @@ void spu_recompiler_base::dispatch(spu_thread& spu, void*, u8* rip) if (!func) { - LOG_FATAL(SPU, "[0x%05x] Compilation failed.", spu.pc); + spu_log.fatal("[0x%05x] Compilation failed.", spu.pc); Emu.Pause(); return; } @@ -1098,7 +1098,7 @@ void spu_recompiler_base::dispatch(spu_thread& spu, void*, u8* rip) if (_info._u64[0] + 1) { - LOG_TRACE(SPU, "Called from 0x%x", _info._u32[2] - 4); + spu_log.trace("Called from 0x%x", _info._u32[2] - 4); } } @@ -1109,7 +1109,7 @@ void spu_recompiler_base::branch(spu_thread& spu, void*, u8* rip) { if (const u32 ls_off = ((rip[6] << 8) | rip[7]) * 4) { - LOG_TODO(SPU, "Special branch patchpoint hit.\nPlease report to the developer (0x%05x).", ls_off); + spu_log.todo("Special branch patchpoint hit.\nPlease report to the developer (0x%05x).", ls_off); } // Find function @@ -1186,8 +1186,8 @@ void spu_recompiler_base::old_interpreter(spu_thread& spu, void* ls, u8* rip) tr catch (const std::exception& e) { Emu.Pause(); - LOG_FATAL(SPU, "%s thrown: %s", typeid(e).name(), e.what()); - LOG_NOTICE(SPU, "\n%s", spu.dump()); + spu_log.fatal("%s thrown: %s", typeid(e).name(), e.what()); + spu_log.notice("\n%s", spu.dump()); } spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) @@ -1361,7 +1361,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) { if (op.d && op.e) { - LOG_ERROR(SPU, "[0x%x] Invalid interrupt flags (DE)", pos); + spu_log.error("[0x%x] Invalid interrupt flags (DE)", pos); } m_targets[pos]; @@ -1379,7 +1379,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) { if (op.d && op.e) { - LOG_ERROR(SPU, "[0x%x] Invalid interrupt flags (DE)", pos); + spu_log.error("[0x%x] Invalid interrupt flags (DE)", pos); } const auto af = vflags[op.ra]; @@ -1397,7 +1397,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) { const u32 target = spu_branch_target(av); - LOG_WARNING(SPU, "[0x%x] At 0x%x: indirect branch to 0x%x%s", entry_point, pos, target, op.d ? " (D)" : op.e ? " (E)" : ""); + spu_log.warning("[0x%x] At 0x%x: indirect branch to 0x%x%s", entry_point, pos, target, op.d ? " (D)" : op.e ? " (E)" : ""); m_targets[pos].push_back(target); @@ -1405,7 +1405,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) { if (sync) { - LOG_NOTICE(SPU, "[0x%x] At 0x%x: ignoring %scall to 0x%x (SYNC)", entry_point, pos, sl ? "" : "tail ", target); + spu_log.notice("[0x%x] At 0x%x: ignoring %scall to 0x%x (SYNC)", entry_point, pos, sl ? "" : "tail ", target); if (target > entry_point) { @@ -1550,7 +1550,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) ls[start / 4 + 8] == 0x1c200807 && ls[start / 4 + 9] == 0x2401c809) { - LOG_WARNING(SPU, "[0x%x] Pattern 1 detected (hbr=0x%x:0x%x)", pos, hbr_loc, hbr_tg); + spu_log.warning("[0x%x] Pattern 1 detected (hbr=0x%x:0x%x)", pos, hbr_loc, hbr_tg); // Add 8 targets (TODO) for (u32 addr = start + 4; addr < start + 36; addr += 4) @@ -1561,12 +1561,12 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) } else if (hbr_loc > start && hbr_loc < limit && hbr_tg == start) { - LOG_WARNING(SPU, "[0x%x] No patterns detected (hbr=0x%x:0x%x)", pos, hbr_loc, hbr_tg); + spu_log.warning("[0x%x] No patterns detected (hbr=0x%x:0x%x)", pos, hbr_loc, hbr_tg); } } else if (type == spu_itype::BI && sync) { - LOG_NOTICE(SPU, "[0x%x] At 0x%x: ignoring indirect branch (SYNC)", entry_point, pos); + spu_log.notice("[0x%x] At 0x%x: ignoring indirect branch (SYNC)", entry_point, pos); } if (type == spu_itype::BI || sl) @@ -1627,7 +1627,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) { if (g_cfg.core.spu_block_size == spu_block_size_type::giga) { - LOG_NOTICE(SPU, "[0x%x] At 0x%x: ignoring fixed call to 0x%x (SYNC)", entry_point, pos, target); + spu_log.notice("[0x%x] At 0x%x: ignoring fixed call to 0x%x (SYNC)", entry_point, pos, target); } if (target > entry_point) @@ -1653,7 +1653,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) { if (g_cfg.core.spu_block_size == spu_block_size_type::giga) { - LOG_NOTICE(SPU, "[0x%x] At 0x%x: ignoring fixed tail call to 0x%x (SYNC)", entry_point, pos, target); + spu_log.notice("[0x%x] At 0x%x: ignoring fixed tail call to 0x%x (SYNC)", entry_point, pos, target); } if (target > entry_point) @@ -2309,7 +2309,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) if (auto emp = m_funcs.try_emplace(m_bbs.begin()->first); emp.second) { const u32 addr = emp.first->first; - LOG_ERROR(SPU, "[0x%05x] Fixed first function at 0x%05x", entry_point, addr); + spu_log.error("[0x%05x] Fixed first function at 0x%05x", entry_point, addr); m_entry_info[addr / 4] = true; m_ret_info[addr / 4] = false; } @@ -2977,18 +2977,18 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) if (src.reg_load_mod[s_reg_lr] != func.reg_save_off[s_reg_lr]) { - LOG_ERROR(SPU, "Function 0x%05x: [0x%05x] $LR mismatch (src=0x%x; 0x%x vs 0x%x)", f.first, addr, lr_orig, src.reg_load_mod[0], func.reg_save_off[0]); + spu_log.error("Function 0x%05x: [0x%05x] $LR mismatch (src=0x%x; 0x%x vs 0x%x)", f.first, addr, lr_orig, src.reg_load_mod[0], func.reg_save_off[0]); is_ok = false; } else if (src.reg_load_mod[s_reg_lr] == 0) { - LOG_ERROR(SPU, "Function 0x%05x: [0x%05x] $LR modified (src=0x%x)", f.first, addr, lr_orig); + spu_log.error("Function 0x%05x: [0x%05x] $LR modified (src=0x%x)", f.first, addr, lr_orig); is_ok = false; } } else if (lr_orig > 0x40000) { - LOG_TODO(SPU, "Function 0x%05x: [0x%05x] $LR unpredictable (src=0x%x)", f.first, addr, lr_orig); + spu_log.todo("Function 0x%05x: [0x%05x] $LR unpredictable (src=0x%x)", f.first, addr, lr_orig); is_ok = false; } @@ -3001,19 +3001,19 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) if (src.reg_load_mod[i] != func.reg_save_off[i]) { - LOG_ERROR(SPU, "Function 0x%05x: [0x%05x] $%u mismatch (src=0x%x; 0x%x vs 0x%x)", f.first, addr, i, orig, src.reg_load_mod[i], func.reg_save_off[i]); + spu_log.error("Function 0x%05x: [0x%05x] $%u mismatch (src=0x%x; 0x%x vs 0x%x)", f.first, addr, i, orig, src.reg_load_mod[i], func.reg_save_off[i]); is_ok = false; } } else if (orig > 0x40000) { - LOG_TODO(SPU, "Function 0x%05x: [0x%05x] $%u unpredictable (src=0x%x)", f.first, addr, i, orig); + spu_log.todo("Function 0x%05x: [0x%05x] $%u unpredictable (src=0x%x)", f.first, addr, i, orig); is_ok = false; } if (func.reg_save_off[i] + 1 == 0) { - LOG_ERROR(SPU, "Function 0x%05x: [0x%05x] $%u used incorrectly", f.first, addr, i); + spu_log.error("Function 0x%05x: [0x%05x] $%u used incorrectly", f.first, addr, i); is_ok = false; } } @@ -3021,7 +3021,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) // Check $SP (should be restored or unmodified) if (bb.stack_sub != 0 && bb.stack_sub != 0x80000000) { - LOG_ERROR(SPU, "Function 0x%05x: [0x%05x] return with stack frame 0x%x", f.first, addr, bb.stack_sub); + spu_log.error("Function 0x%05x: [0x%05x] return with stack frame 0x%x", f.first, addr, bb.stack_sub); is_ok = false; } } @@ -3032,7 +3032,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) if (bb.stack_sub == 0) { // Call without a stack frame - LOG_ERROR(SPU, "Function 0x%05x: [0x%05x] frameless call", f.first, addr); + spu_log.error("Function 0x%05x: [0x%05x] frameless call", f.first, addr); is_ok = false; } } @@ -3042,14 +3042,14 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) // Can't just fall out of the function if (bb.targets.size() != 1 || bb.targets[0] >= flim) { - LOG_ERROR(SPU, "Function 0x%05x: [0x%05x] bad fallthrough to 0x%x", f.first, addr, bb.targets[0]); + spu_log.error("Function 0x%05x: [0x%05x] bad fallthrough to 0x%x", f.first, addr, bb.targets[0]); is_ok = false; } } if (is_ok && bb.stack_sub == 0x80000000) { - LOG_ERROR(SPU, "Function 0x%05x: [0x%05x] bad stack frame", f.first, addr); + spu_log.error("Function 0x%05x: [0x%05x] bad stack frame", f.first, addr); is_ok = false; } @@ -3068,13 +3068,13 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) if (is_ok && used_stack && f.first == entry_point) { - LOG_ERROR(SPU, "Function 0x%05x: considered possible chunk", f.first); + spu_log.error("Function 0x%05x: considered possible chunk", f.first); is_ok = false; } // if (is_ok && f.first > 0x1d240 && f.first < 0x1e000) // { - // LOG_ERROR(SPU, "Function 0x%05x: manually disabled", f.first); + // spu_log.error("Function 0x%05x: manually disabled", f.first); // is_ok = false; // } @@ -3103,7 +3103,7 @@ spu_program spu_recompiler_base::analyse(const be_t* ls, u32 entry_point) if (f.second.good) { - LOG_ERROR(SPU, "Function 0x%05x: calls bad function (0x%05x)", f.first, call); + spu_log.error("Function 0x%05x: calls bad function (0x%05x)", f.first, call); f.second.good = false; } } @@ -3604,7 +3604,7 @@ class spu_llvm_recompiler : public spu_recompiler_base, public cpu_translator { if (m_block_info[target / 4]) { - LOG_ERROR(SPU, "[0x%x] Predecessor not found for target 0x%x (chunk=0x%x, entry=0x%x, size=%u)", m_pos, target, m_entry, m_function_queue[0], m_size / 4); + spu_log.error("[0x%x] Predecessor not found for target 0x%x (chunk=0x%x, entry=0x%x, size=%u)", m_pos, target, m_entry, m_function_queue[0], m_size / 4); } const auto cblock = m_ir->GetInsertBlock(); @@ -4221,7 +4221,7 @@ public: m_hash_start = hash_start; } - LOG_NOTICE(SPU, "Building function 0x%x... (size %u, %s)", func.entry_point, func.data.size(), m_hash); + spu_log.notice("Building function 0x%x... (size %u, %s)", func.entry_point, func.data.size(), m_hash); m_pos = func.lower_bound; m_base = func.entry_point; @@ -4570,7 +4570,7 @@ public: } else { - LOG_ERROR(SPU, "[0x%05x] Value not found ($%u from 0x%05x)", baddr, i, src); + spu_log.error("[0x%05x] Value not found ($%u from 0x%05x)", baddr, i, src); } } else @@ -4609,7 +4609,7 @@ public: if (!op) { - LOG_ERROR(SPU, "Unexpected fallthrough to 0x%x (chunk=0x%x, entry=0x%x)", m_pos, m_entry, m_function_queue[0]); + spu_log.error("Unexpected fallthrough to 0x%x (chunk=0x%x, entry=0x%x)", m_pos, m_entry, m_function_queue[0]); break; } @@ -4624,7 +4624,7 @@ public: raw_string_ostream out(dump); out << *module; // print IR out.flush(); - LOG_ERROR(SPU, "[0x%x] LLVM dump:\n%s", m_pos, dump); + spu_log.error("[0x%x] LLVM dump:\n%s", m_pos, dump); throw; } } @@ -4644,7 +4644,7 @@ public: if (tfound == m_targets.end() || tfound->second.find_first_of(target) + 1 == 0) { - LOG_ERROR(SPU, "Unregistered fallthrough to 0x%x (chunk=0x%x, entry=0x%x)", target, m_entry, m_function_queue[0]); + spu_log.error("Unregistered fallthrough to 0x%x (chunk=0x%x, entry=0x%x)", target, m_entry, m_function_queue[0]); } } } @@ -4759,7 +4759,7 @@ public: if (verifyModule(*module, &out)) { out.flush(); - LOG_ERROR(SPU, "LLVM: Verification failed at 0x%x:\n%s", func.entry_point, log); + spu_log.error("LLVM: Verification failed at 0x%x:\n%s", func.entry_point, log); if (g_cfg.core.spu_debug) { @@ -4803,7 +4803,7 @@ public: if (g_fxo->get()) { - LOG_SUCCESS(SPU, "New block compiled successfully"); + spu_log.success("New block compiled successfully"); } return fn; @@ -4821,7 +4821,7 @@ public: // Execute interpreter instruction const u32 op = *reinterpret_cast*>(_spu->_ptr(0) + _spu->pc); if (!g_spu_interpreter_fast.decode(op)(*_spu, {op})) - LOG_FATAL(SPU, "Bad instruction" HERE); + spu_log.fatal("Bad instruction" HERE); // Swap state for (u32 i = 0; i < s_gpr.size(); ++i) @@ -4834,7 +4834,7 @@ public: { if (_spu->gpr[i] != s_gpr[i]) { - LOG_FATAL(SPU, "Register mismatch: $%u\n%s\n%s", i, _spu->gpr[i], s_gpr[i]); + spu_log.fatal("Register mismatch: $%u\n%s\n%s", i, _spu->gpr[i], s_gpr[i]); _spu->state += cpu_flag::dbg_pause; } } @@ -5154,7 +5154,7 @@ public: raw_string_ostream out(dump); out << *module; // print IR out.flush(); - LOG_ERROR(SPU, "[0x%x] LLVM dump:\n%s", m_pos, dump); + spu_log.error("[0x%x] LLVM dump:\n%s", m_pos, dump); throw; } } @@ -5199,7 +5199,7 @@ public: if (verifyModule(*module, &out)) { out.flush(); - LOG_ERROR(SPU, "LLVM: Verification failed:\n%s", log); + spu_log.error("LLVM: Verification failed:\n%s", log); if (g_cfg.core.spu_debug) { @@ -5723,7 +5723,7 @@ public: } } - LOG_WARNING(SPU, "[0x%x] MFC_WrTagUpdate: $%u is not a good constant", m_pos, +op.rt); + spu_log.warning("[0x%x] MFC_WrTagUpdate: $%u is not a good constant", m_pos, +op.rt); break; } case MFC_LSA: @@ -5741,7 +5741,7 @@ public: } } - LOG_WARNING(SPU, "[0x%x] MFC_EAH: $%u is not a zero constant", m_pos, +op.rt); + spu_log.warning("[0x%x] MFC_EAH: $%u is not a zero constant", m_pos, +op.rt); //m_ir->CreateStore(val.value, spu_ptr(&spu_thread::ch_mfc_cmd, &spu_mfc_cmd::eah)); return; } @@ -5904,7 +5904,7 @@ public: { if (csize % 16 || csize > 0x4000) { - LOG_ERROR(SPU, "[0x%x] MFC_Cmd: invalid size %u", m_pos, csize); + spu_log.error("[0x%x] MFC_Cmd: invalid size %u", m_pos, csize); } } } @@ -5951,7 +5951,7 @@ public: default: { // TODO - LOG_ERROR(SPU, "[0x%x] MFC_Cmd: unknown command (0x%x)", m_pos, cmd); + spu_log.error("[0x%x] MFC_Cmd: unknown command (0x%x)", m_pos, cmd); m_ir->CreateBr(next); m_ir->SetInsertPoint(exec); m_ir->CreateUnreachable(); @@ -6034,7 +6034,7 @@ public: } // Fallback to unoptimized WRCH implementation (TODO) - LOG_WARNING(SPU, "[0x%x] MFC_Cmd: $%u is not a constant", m_pos, +op.rt); + spu_log.warning("[0x%x] MFC_Cmd: $%u is not a constant", m_pos, +op.rt); break; } case MFC_WrListStallAck: @@ -6296,7 +6296,7 @@ public: if (auto [ok, a2, b2] = match_expr(b, mpyu(MP, MP)); ok && a2.eq(a0, a1) && b2.eq(b0, b1)) { // 32-bit multiplication - LOG_NOTICE(SPU, "mpy32 in %s at 0x%05x", m_hash, m_pos); + spu_log.notice("mpy32 in %s at 0x%05x", m_hash, m_pos); set_vr(op.rt, a0 * b0); return; } @@ -7106,7 +7106,7 @@ public: return; } - LOG_TODO(SPU, "[0x%x] Const SHUFB mask: %s", m_pos, mask); + spu_log.todo("[0x%x] Const SHUFB mask: %s", m_pos, mask); } const auto x = avg(noncast(sext((c & 0xc0) == 0xc0)), noncast(sext((c & 0xe0) == 0xc0))); @@ -8062,7 +8062,7 @@ public: if (targets.empty()) { // Emergency exit - LOG_ERROR(SPU, "[0x%05x] No jump table targets at 0x%05x (%u)", m_entry, m_pos, tfound->second.size()); + spu_log.error("[0x%05x] No jump table targets at 0x%05x (%u)", m_entry, m_pos, tfound->second.size()); m_ir->CreateBr(add_block_indirect(op, addr)); return; } @@ -8278,7 +8278,7 @@ public: } else { - LOG_FATAL(SPU, "[0x%x] Can't add function 0x%x", m_pos, target); + spu_log.fatal("[0x%x] Can't add function 0x%x", m_pos, target); return; } } @@ -8460,7 +8460,7 @@ struct spu_llvm if (func2 != func) { - LOG_ERROR(SPU, "[0x%05x] SPU Analyser failed, %u vs %u", func2.entry_point, func2.data.size(), size0); + spu_log.error("[0x%05x] SPU Analyser failed, %u vs %u", func2.entry_point, func2.data.size(), size0); } else if (const auto target = compiler->compile(std::move(func2))) { @@ -8483,7 +8483,7 @@ struct spu_llvm } else { - LOG_FATAL(SPU, "[0x%05x] Compilation failed.", func.entry_point); + spu_log.fatal("[0x%05x] Compilation failed.", func.entry_point); Emu.Pause(); return; } diff --git a/rpcs3/Emu/Cell/SPUThread.cpp b/rpcs3/Emu/Cell/SPUThread.cpp index 108f850d69..0a549a175c 100644 --- a/rpcs3/Emu/Cell/SPUThread.cpp +++ b/rpcs3/Emu/Cell/SPUThread.cpp @@ -1165,7 +1165,7 @@ void spu_thread::cpu_task() } // Print some stats - LOG_NOTICE(SPU, "Stats: Block Weight: %u (Retreats: %u);", block_counter, block_failure); + spu_log.notice("Stats: Block Weight: %u (Retreats: %u);", block_counter, block_failure); } else { @@ -1562,7 +1562,7 @@ bool spu_thread::do_list_transfer(spu_mfc_cmd& args) const u32 size = items[index].ts & 0x7fff; const u32 addr = items[index].ea; - LOG_TRACE(SPU, "LIST: addr=0x%x, size=0x%x, lsa=0x%05x, sb=0x%x", addr, size, args.lsa | (addr & 0xf), items[index].sb); + spu_log.trace("LIST: addr=0x%x, size=0x%x, lsa=0x%05x, sb=0x%x", addr, size, args.lsa | (addr & 0xf), items[index].sb); if (size) { @@ -1794,7 +1794,7 @@ bool spu_thread::process_mfc_cmd() } spu::scheduler::concurrent_execution_watchdog watchdog(*this); - LOG_TRACE(SPU, "DMAC: cmd=%s, lsa=0x%x, ea=0x%llx, tag=0x%x, size=0x%x", ch_mfc_cmd.cmd, ch_mfc_cmd.lsa, ch_mfc_cmd.eal, ch_mfc_cmd.tag, ch_mfc_cmd.size); + spu_log.trace("DMAC: cmd=%s, lsa=0x%x, ea=0x%llx, tag=0x%x, size=0x%x", ch_mfc_cmd.cmd, ch_mfc_cmd.lsa, ch_mfc_cmd.eal, ch_mfc_cmd.tag, ch_mfc_cmd.size); switch (ch_mfc_cmd.cmd) { @@ -2218,7 +2218,7 @@ void spu_thread::set_interrupt_status(bool enable) u32 spu_thread::get_ch_count(u32 ch) { - LOG_TRACE(SPU, "get_ch_count(ch=%d [%s])", ch, ch < 128 ? spu_ch_name[ch] : "???"); + spu_log.trace("get_ch_count(ch=%d [%s])", ch, ch < 128 ? spu_ch_name[ch] : "???"); switch (ch) { @@ -2240,7 +2240,7 @@ u32 spu_thread::get_ch_count(u32 ch) s64 spu_thread::get_ch_value(u32 ch) { - LOG_TRACE(SPU, "get_ch_value(ch=%d [%s])", ch, ch < 128 ? spu_ch_name[ch] : "???"); + spu_log.trace("get_ch_value(ch=%d [%s])", ch, ch < 128 ? spu_ch_name[ch] : "???"); auto read_channel = [&](spu_channel& channel) -> s64 { @@ -2449,7 +2449,7 @@ s64 spu_thread::get_ch_value(u32 ch) bool spu_thread::set_ch_value(u32 ch, u32 value) { - LOG_TRACE(SPU, "set_ch_value(ch=%d [%s], value=0x%x)", ch, ch < 128 ? spu_ch_name[ch] : "???", value); + spu_log.trace("set_ch_value(ch=%d [%s], value=0x%x)", ch, ch < 128 ? spu_ch_name[ch] : "???", value); switch (ch) { @@ -2501,13 +2501,13 @@ bool spu_thread::set_ch_value(u32 ch, u32 value) fmt::throw_exception("sys_spu_thread_send_event(value=0x%x, spup=%d): In_MBox is not empty (count=%d)" HERE, value, spup, count); } - LOG_TRACE(SPU, "sys_spu_thread_send_event(spup=%d, data0=0x%x, data1=0x%x)", spup, value & 0x00ffffff, data); + spu_log.trace("sys_spu_thread_send_event(spup=%d, data0=0x%x, data1=0x%x)", spup, value & 0x00ffffff, data); const auto queue = (std::lock_guard{group->mutex}, this->spup[spup].lock()); if (!queue) { - LOG_WARNING(SPU, "sys_spu_thread_send_event(spup=%d, data0=0x%x, data1=0x%x): event queue not connected", spup, (value & 0x00ffffff), data); + spu_log.warning("sys_spu_thread_send_event(spup=%d, data0=0x%x, data1=0x%x): event queue not connected", spup, (value & 0x00ffffff), data); ch_in_mbox.set_values(1, CELL_ENOTCONN); return true; } @@ -2533,20 +2533,20 @@ bool spu_thread::set_ch_value(u32 ch, u32 value) fmt::throw_exception("sys_spu_thread_throw_event(value=0x%x, spup=%d): Out_MBox is empty" HERE, value, spup); } - LOG_TRACE(SPU, "sys_spu_thread_throw_event(spup=%d, data0=0x%x, data1=0x%x)", spup, value & 0x00ffffff, data); + spu_log.trace("sys_spu_thread_throw_event(spup=%d, data0=0x%x, data1=0x%x)", spup, value & 0x00ffffff, data); const auto queue = (std::lock_guard{group->mutex}, this->spup[spup].lock()); if (!queue) { - LOG_WARNING(SPU, "sys_spu_thread_throw_event(spup=%d, data0=0x%x, data1=0x%x): event queue not connected", spup, (value & 0x00ffffff), data); + spu_log.warning("sys_spu_thread_throw_event(spup=%d, data0=0x%x, data1=0x%x): event queue not connected", spup, (value & 0x00ffffff), data); return true; } // TODO: check passing spup value if (!queue->send(SYS_SPU_THREAD_EVENT_USER_KEY, lv2_id, (u64{spup} << 32) | (value & 0x00ffffff), data)) { - LOG_WARNING(SPU, "sys_spu_thread_throw_event(spup=%d, data0=0x%x, data1=0x%x) failed (queue is full)", spup, (value & 0x00ffffff), data); + spu_log.warning("sys_spu_thread_throw_event(spup=%d, data0=0x%x, data1=0x%x) failed (queue is full)", spup, (value & 0x00ffffff), data); } return true; @@ -2568,7 +2568,7 @@ bool spu_thread::set_ch_value(u32 ch, u32 value) fmt::throw_exception("sys_event_flag_set_bit(value=0x%x (flag=%d)): In_MBox is not empty (%d)" HERE, value, flag, count); } - LOG_TRACE(SPU, "sys_event_flag_set_bit(id=%d, value=0x%x (flag=%d))", data, value, flag); + spu_log.trace("sys_event_flag_set_bit(id=%d, value=0x%x (flag=%d))", data, value, flag); ch_in_mbox.set_values(1, CELL_OK); @@ -2592,7 +2592,7 @@ bool spu_thread::set_ch_value(u32 ch, u32 value) fmt::throw_exception("sys_event_flag_set_bit_impatient(value=0x%x (flag=%d)): Out_MBox is empty" HERE, value, flag); } - LOG_TRACE(SPU, "sys_event_flag_set_bit_impatient(id=%d, value=0x%x (flag=%d))", data, value, flag); + spu_log.trace("sys_event_flag_set_bit_impatient(id=%d, value=0x%x (flag=%d))", data, value, flag); // Use the syscall to set flag sys_event_flag_set(data, 1ull << flag); @@ -2776,7 +2776,7 @@ bool spu_thread::set_ch_value(u32 ch, u32 value) bool spu_thread::stop_and_signal(u32 code) { - LOG_TRACE(SPU, "stop_and_signal(code=0x%x)", code); + spu_log.trace("stop_and_signal(code=0x%x)", code); if (offset >= RAW_SPU_BASE_ADDR) { @@ -2800,7 +2800,7 @@ bool spu_thread::stop_and_signal(u32 code) { case 0x000: { - LOG_WARNING(SPU, "STOP 0x0"); + spu_log.warning("STOP 0x0"); // HACK: find an ILA instruction for (u32 addr = pc; addr < 0x40000; addr += 4) @@ -2863,11 +2863,11 @@ bool spu_thread::stop_and_signal(u32 code) if (u32 count = ch_in_mbox.get_count()) { - LOG_ERROR(SPU, "sys_spu_thread_receive_event(): In_MBox is not empty (%d)", count); + spu_log.error("sys_spu_thread_receive_event(): In_MBox is not empty (%d)", count); return ch_in_mbox.set_values(1, CELL_EBUSY), true; } - LOG_TRACE(SPU, "sys_spu_thread_receive_event(spuq=0x%x)", spuq); + spu_log.trace("sys_spu_thread_receive_event(spuq=0x%x)", spuq); if (group->type & SYS_SPU_THREAD_GROUP_TYPE_EXCLUSIVE_NON_CONTEXT) // this check may be inaccurate { @@ -3012,11 +3012,11 @@ bool spu_thread::stop_and_signal(u32 code) if (u32 count = ch_in_mbox.get_count()) { - LOG_ERROR(SPU, "sys_spu_thread_tryreceive_event(): In_MBox is not empty (%d)", count); + spu_log.error("sys_spu_thread_tryreceive_event(): In_MBox is not empty (%d)", count); return ch_in_mbox.set_values(1, CELL_EBUSY), true; } - LOG_TRACE(SPU, "sys_spu_thread_tryreceive_event(spuq=0x%x)", spuq); + spu_log.trace("sys_spu_thread_tryreceive_event(spuq=0x%x)", spuq); std::lock_guard lock(group->mutex); @@ -3079,7 +3079,7 @@ bool spu_thread::stop_and_signal(u32 code) fmt::throw_exception("sys_spu_thread_group_exit(): Out_MBox is empty" HERE); } - LOG_TRACE(SPU, "sys_spu_thread_group_exit(status=0x%x)", value); + spu_log.trace("sys_spu_thread_group_exit(status=0x%x)", value); std::lock_guard lock(group->mutex); @@ -3111,7 +3111,7 @@ bool spu_thread::stop_and_signal(u32 code) fmt::throw_exception("sys_spu_thread_exit(): Out_MBox is empty" HERE); } - LOG_TRACE(SPU, "sys_spu_thread_exit(status=0x%x)", ch_out_mbox.get_value()); + spu_log.trace("sys_spu_thread_exit(status=0x%x)", ch_out_mbox.get_value()); status |= SPU_STATUS_STOPPED_BY_STOP; state += cpu_flag::stop; check_state(); @@ -3131,7 +3131,7 @@ bool spu_thread::stop_and_signal(u32 code) void spu_thread::halt() { - LOG_TRACE(SPU, "halt()"); + spu_log.trace("halt()"); if (offset >= RAW_SPU_BASE_ADDR) { diff --git a/rpcs3/Emu/Cell/SPUThread.h b/rpcs3/Emu/Cell/SPUThread.h index 21842e5e7c..3e9102f2e5 100644 --- a/rpcs3/Emu/Cell/SPUThread.h +++ b/rpcs3/Emu/Cell/SPUThread.h @@ -9,6 +9,8 @@ #include +LOG_CHANNEL(spu_log, "SPU"); + struct lv2_event_queue; struct lv2_spu_group; struct lv2_int_tag; diff --git a/rpcs3/Emu/Cell/lv2/sys_spu.cpp b/rpcs3/Emu/Cell/lv2/sys_spu.cpp index fbeb92ee98..162eee637a 100644 --- a/rpcs3/Emu/Cell/lv2/sys_spu.cpp +++ b/rpcs3/Emu/Cell/lv2/sys_spu.cpp @@ -30,16 +30,16 @@ void sys_spu_image::load(const fs::file& stream) for (const auto& shdr : obj.shdrs) { - LOG_NOTICE(SPU, "** Section: sh_type=0x%x, addr=0x%llx, size=0x%llx, flags=0x%x", shdr.sh_type, shdr.sh_addr, shdr.sh_size, shdr.sh_flags); + spu_log.notice("** Section: sh_type=0x%x, addr=0x%llx, size=0x%llx, flags=0x%x", shdr.sh_type, shdr.sh_addr, shdr.sh_size, shdr.sh_flags); } for (const auto& prog : obj.progs) { - LOG_NOTICE(SPU, "** Segment: p_type=0x%x, p_vaddr=0x%llx, p_filesz=0x%llx, p_memsz=0x%llx, flags=0x%x", prog.p_type, prog.p_vaddr, prog.p_filesz, prog.p_memsz, prog.p_flags); + spu_log.notice("** Segment: p_type=0x%x, p_vaddr=0x%llx, p_filesz=0x%llx, p_memsz=0x%llx, flags=0x%x", prog.p_type, prog.p_vaddr, prog.p_filesz, prog.p_memsz, prog.p_flags); if (prog.p_type != SYS_SPU_SEGMENT_TYPE_COPY && prog.p_type != SYS_SPU_SEGMENT_TYPE_INFO) { - LOG_ERROR(SPU, "Unknown program type (0x%x)", prog.p_type); + spu_log.error("Unknown program type (0x%x)", prog.p_type); } } @@ -104,7 +104,7 @@ void sys_spu_image::deploy(u32 loc, sys_spu_segment* segs, u32 nsegs) { if ((seg.ls | seg.size) % 4) { - LOG_ERROR(SPU, "Unaligned SPU FILL type segment (ls=0x%x, size=0x%x)", seg.ls, seg.size); + spu_log.error("Unaligned SPU FILL type segment (ls=0x%x, size=0x%x)", seg.ls, seg.size); } std::fill_n(vm::_ptr(loc + seg.ls), seg.size / 4, seg.addr); @@ -139,7 +139,7 @@ void sys_spu_image::deploy(u32 loc, sys_spu_segment* segs, u32 nsegs) applied += g_fxo->get()->apply(Emu.GetTitleID() + '-' + hash, vm::_ptr(loc)); } - LOG_NOTICE(SPU, "Loaded SPU image: %s (<- %u)%s", hash, applied, dump); + spu_log.notice("Loaded SPU image: %s (<- %u)%s", hash, applied, dump); } // Get spu thread ptr, returns group ptr as well for refcounting @@ -355,7 +355,7 @@ error_code sys_spu_thread_initialize(ppu_thread& ppu, vm::ptr thread, u32 g // Hack: don't run more SPURS threads than specified. group->max_run = g_cfg.core.max_spurs_threads; - LOG_SUCCESS(SPU, "HACK: '%s' (0x%x) limited to %u threads.", group->name, group_id, +g_cfg.core.max_spurs_threads); + spu_log.success("HACK: '%s' (0x%x) limited to %u threads.", group->name, group_id, +g_cfg.core.max_spurs_threads); } }