Modernize SPU logging (spu_log variable) and remove log legacy

Remove legacy macro (LOG_ERROR, etc)
This commit is contained in:
Nekotekina 2020-02-01 11:36:09 +03:00
parent 327bb2d8f0
commit 6dfd97f0b6
8 changed files with 110 additions and 124 deletions

View File

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

View File

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

View File

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

View File

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

View File

@ -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<u32>* ls, u32 entry_point)
@ -1361,7 +1361,7 @@ spu_program spu_recompiler_base::analyse(const be_t<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<u32>* 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<spu_cache>())
{
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<const be_t<u32>*>(_spu->_ptr<u8>(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<u32>(&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<u8[16]>(sext<s8[16]>((c & 0xc0) == 0xc0)), noncast<u8[16]>(sext<s8[16]>((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;
}

View File

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

View File

@ -9,6 +9,8 @@
#include <map>
LOG_CHANNEL(spu_log, "SPU");
struct lv2_event_queue;
struct lv2_spu_group;
struct lv2_int_tag;

View File

@ -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<u32>(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<patch_engine>()->apply(Emu.GetTitleID() + '-' + hash, vm::_ptr<u8>(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<u32> 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);
}
}