scawful/yaze
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Update emu guide and set emu logs to debug

Browse Source
This commit is contained in:
scawful
2025-10-06 19:36:22 -04:00
parent bdd585dae1
commit e41ea0df46
7 changed files with 155 additions and 70 deletions
Download Patch File Download Diff File Expand all files Collapse all files

16
src/app/emu/audio/apu.cc
View File

@@ -38,7 +38,7 @@ void Apu::Init() {
}
void Apu::Reset() {
LOG_INFO("APU", "Reset called");
LOG_DEBUG("APU", "Reset called");
spc700_.Reset(true);
dsp_.Reset();
for (int i = 0; i < 0x10000; i++) {
@@ -59,7 +59,7 @@ void Apu::Reset() {
timer_[i].counter = 0;
timer_[i].enabled = false;
}
LOG_INFO("APU", "Reset complete - IPL ROM readable, PC will be at $%04X",
LOG_DEBUG("APU", "Reset complete - IPL ROM readable, PC will be at $%04X",
spc700_.read_word(0xFFFE));
}
@@ -88,9 +88,9 @@ void Apu::RunCycles(uint64_t master_cycles) {
static uint64_t last_ipl_log = 0;
if (rom_readable_ && current_pc >= 0xFFD6 && current_pc <= 0xFFED) {
if (cycles_ - last_ipl_log > 10000) {
LOG_INFO("APU", "IPL ROM loop: PC=$%04X Y=$%02X Ports: F4=$%02X F5=$%02X F6=$%02X F7=$%02X",
LOG_DEBUG("APU", "IPL ROM loop: PC=$%04X Y=$%02X Ports: F4=$%02X F5=$%02X F6=$%02X F7=$%02X",
current_pc, spc700_.Y, in_ports_[0], in_ports_[1], in_ports_[2], in_ports_[3]);
LOG_INFO("APU", " Out ports: F4=$%02X F5=$%02X F6=$%02X F7=$%02X ZP: $00=$%02X $01=$%02X",
LOG_DEBUG("APU", " Out ports: F4=$%02X F5=$%02X F6=$%02X F7=$%02X ZP: $00=$%02X $01=$%02X",
out_ports_[0], out_ports_[1], out_ports_[2], out_ports_[3], ram[0x00], ram[0x01]);
last_ipl_log = cycles_;
}
@@ -183,7 +183,7 @@ uint8_t Apu::Read(uint16_t adr) {
uint8_t val = in_ports_[adr - 0xf4];
port_read_count++;
if (port_read_count < 10) { // Reduced to prevent logging overflow crash
LOG_INFO("APU", "SPC read port $%04X (F%d) = $%02X at PC=$%04X",
LOG_DEBUG("APU", "SPC read port $%04X (F%d) = $%02X at PC=$%04X",
adr, adr - 0xf4 + 4, val, spc700_.PC);
}
return val;
@@ -234,7 +234,7 @@ void Apu::Write(uint16_t adr, uint8_t val) {
// IPL ROM mapping: initially enabled; writing 1 to bit7 disables IPL ROM.
rom_readable_ = (val & 0x80) == 0;
if (old_rom_readable != rom_readable_) {
LOG_INFO("APU", "Control register $F1 = $%02X - IPL ROM %s at PC=$%04X",
LOG_DEBUG("APU", "Control register $F1 = $%02X - IPL ROM %s at PC=$%04X",
val, rom_readable_ ? "ENABLED" : "DISABLED", spc700_.PC);
// When IPL ROM is disabled, reset transfer tracking
if (!rom_readable_) {
@@ -259,7 +259,7 @@ void Apu::Write(uint16_t adr, uint8_t val) {
out_ports_[adr - 0xf4] = val;
port_write_count++;
if (port_write_count < 10) { // Reduced to prevent logging overflow crash
LOG_INFO("APU", "SPC wrote port $%04X (F%d) = $%02X at PC=$%04X [APU_cycles=%llu]",
LOG_DEBUG("APU", "SPC wrote port $%04X (F%d) = $%02X at PC=$%04X [APU_cycles=%llu]",
adr, adr - 0xf4 + 4, val, spc700_.PC, cycles_);
}
@@ -273,7 +273,7 @@ void Apu::Write(uint16_t adr, uint8_t val) {
if (ram[0x00] < 0x80) {
transfer_size_ = 1; // Assume 1-byte bootstrap transfer
in_transfer_ = true;
LOG_INFO("APU", "Detected small transfer start: dest=$%02X%02X, size=%d",
LOG_DEBUG("APU", "Detected small transfer start: dest=$%02X%02X, size=%d",
ram[0x01], ram[0x00], transfer_size_);
}
}

13
src/app/emu/audio/internal/instructions.cc
View File

@@ -28,8 +28,8 @@ void Spc700::MOVS(uint16_t address) {
break;
case 1:
write(this->adr, A); // Use saved address
if (this->adr == 0x00F4) {
LOG_INFO("SPC", "MOVS wrote A=$%02X to F4!", A);
if (this->adr == 0x00F4 && movs_log++ < 10) {
LOG_DEBUG("SPC", "MOVS wrote A=$%02X to F4!", A);
}
bstep = 0;
break;
@@ -44,19 +44,20 @@ void Spc700::MOVSX(uint16_t address) {
}
void Spc700::MOVSY(uint16_t address) {
static int movsy_log = 0;
switch (bstep) {
case 0:
this->adr = address;
read(this->adr);
bstep++;
if (this->adr == 0x00F4) {
LOG_INFO("SPC", "MOVSY bstep=0: Will write Y=$%02X to F4 at PC=$%04X", Y, PC);
if (this->adr == 0x00F4 && movsy_log < 10) {
LOG_DEBUG("SPC", "MOVSY bstep=0: Will write Y=$%02X to F4 at PC=$%04X", Y, PC);
}
break;
case 1:
write(this->adr, Y);
if (this->adr == 0x00F4) {
LOG_INFO("SPC", "MOVSY bstep=1: Wrote Y=$%02X to F4 at PC=$%04X", Y, PC);
if (this->adr == 0x00F4 && movsy_log++ < 10) {
LOG_DEBUG("SPC", "MOVSY bstep=1: Wrote Y=$%02X to F4 at PC=$%04X", Y, PC);
}
bstep = 0;
break;

41
src/app/emu/audio/spc700.cc
View File

@@ -30,7 +30,7 @@ void Spc700::Reset(bool hard) {
void Spc700::RunOpcode() {
static int entry_log = 0;
if ((PC >= 0xFFF0 && PC <= 0xFFFF) && entry_log++ < 5) {
LOG_INFO("SPC", "RunOpcode ENTRY: PC=$%04X step=%d bstep=%d", PC, step, bstep);
LOG_DEBUG("SPC", "RunOpcode ENTRY: PC=$%04X step=%d bstep=%d", PC, step, bstep);
}
if (reset_wanted_) {
@@ -55,20 +55,21 @@ void Spc700::RunOpcode() {
}
if (step == 0) {
// Debug: Comprehensive IPL ROM tracing for transfer protocol debugging
// (Only enabled for first few iterations to avoid log spam)
static int spc_exec_count = 0;
bool in_critical_range = (PC >= 0xFFCF && PC <= 0xFFFF);
bool is_transfer_loop = (PC >= 0xFFD6 && PC <= 0xFFED);
// Increased logging limits to capture full transfer (112 bytes)
if (in_critical_range && spc_exec_count++ < 200) {
LOG_INFO("SPC", "Execute: PC=$%04X step=0 bstep=%d Y=%02X A=%02X", PC, bstep, Y, A);
// Reduced logging limits - only log first few iterations
if (in_critical_range && spc_exec_count++ < 5) {
LOG_DEBUG("SPC", "Execute: PC=$%04X step=0 bstep=%d Y=%02X A=%02X", PC, bstep, Y, A);
}
if (is_transfer_loop && spc_exec_count < 300) {
if (is_transfer_loop && spc_exec_count < 10) {
// Read ports and RAM[$00] to track transfer state
uint8_t f4_val = callbacks_.read(0xF4);
uint8_t f5_val = callbacks_.read(0xF5);
uint8_t ram0_val = callbacks_.read(0x00);
LOG_INFO("SPC", "TRANSFER LOOP: PC=$%04X Y=%02X A=%02X F4=%02X F5=%02X RAM0=%02X bstep=%d",
LOG_DEBUG("SPC", "TRANSFER LOOP: PC=$%04X Y=%02X A=%02X F4=%02X F5=%02X RAM0=%02X bstep=%d",
PC, Y, A, f4_val, f5_val, ram0_val, bstep);
}
@@ -78,7 +79,9 @@ void Spc700::RunOpcode() {
// Set base cycle count from lookup table
last_opcode_cycles_ = spc700_cycles[opcode];
} else {
LOG_INFO("SPC", "Continuing multi-step: PC=$%04X bstep=%d opcode=$%02X", PC, bstep, opcode);
if (spc_exec_count < 5) {
LOG_DEBUG("SPC", "Continuing multi-step: PC=$%04X bstep=%d opcode=$%02X", PC, bstep, opcode);
}
}
step = 1;
return;
@@ -94,7 +97,7 @@ void Spc700::RunOpcode() {
static int exec_log = 0;
if ((PC >= 0xFFF0 && PC <= 0xFFFF) && exec_log++ < 5) {
LOG_INFO("SPC", "About to ExecuteInstructions: PC=$%04X step=%d bstep=%d opcode=$%02X", PC, step, bstep, opcode);
LOG_DEBUG("SPC", "About to ExecuteInstructions: PC=$%04X step=%d bstep=%d opcode=$%02X", PC, step, bstep, opcode);
}
ExecuteInstructions(opcode);
@@ -102,13 +105,13 @@ void Spc700::RunOpcode() {
static int reset_log = 0;
if (step == 1) {
if (bstep == 0) {
if ((PC >= 0xFFF0 && PC <= 0xFFFF) && reset_log++ < 20) {
LOG_INFO("SPC", "Resetting step: PC=$%04X opcode=$%02X bstep=%d", PC, opcode, bstep);
if ((PC >= 0xFFF0 && PC <= 0xFFFF) && reset_log++ < 5) {
LOG_DEBUG("SPC", "Resetting step: PC=$%04X opcode=$%02X bstep=%d", PC, opcode, bstep);
}
step = 0;
} else {
if ((PC >= 0xFFF0 && PC <= 0xFFFF) || reset_log++ < 20) {
LOG_INFO("SPC", "NOT resetting step: PC=$%04X opcode=$%02X bstep=%d", PC, opcode, bstep);
if ((PC >= 0xFFF0 && PC <= 0xFFFF) && reset_log++ < 5) {
LOG_DEBUG("SPC", "NOT resetting step: PC=$%04X opcode=$%02X bstep=%d", PC, opcode, bstep);
}
}
}
@@ -1072,11 +1075,8 @@ void Spc700::ExecuteInstructions(uint8_t opcode) {
break;
}
case 0xc4: { // movs dp
LOG_INFO("SPC", "Case 0xC4 reached: bstep=%d PC=$%04X", bstep, PC);
uint16_t adr = dp();
LOG_INFO("SPC", "About to call MOVS: bstep=%d adr=$%04X", bstep, adr);
MOVS(adr);
LOG_INFO("SPC", "After MOVS: bstep=%d", bstep);
break;
}
case 0xc5: { // movs abs
@@ -1113,7 +1113,7 @@ void Spc700::ExecuteInstructions(uint8_t opcode) {
adr = dp(); // Save address for bstep=1
}
if (adr == 0x00F4 && bstep == 1) {
LOG_INFO("SPC", "MOVSY writing Y=$%02X to F4 at PC=$%04X", Y, PC);
LOG_DEBUG("SPC", "MOVSY writing Y=$%02X to F4 at PC=$%04X", Y, PC);
}
MOVSY(adr); // Use saved address
break;
@@ -1347,10 +1347,11 @@ void Spc700::ExecuteInstructions(uint8_t opcode) {
Y++;
PSW.Z = (Y == 0);
PSW.N = (Y & 0x80);
// Critical: Log Y increment in transfer loop (FFE4 is INC Y in IPL ROM)
if (PC >= 0xFFE4 && PC <= 0xFFE6) {
LOG_INFO("SPC", "INC Y executed at PC=$%04X: Y changed from $%02X to $%02X (Z=%d N=%d)",
PC - 1, old_y, Y, PSW.Z, PSW.N);
// Log Y increment in transfer loop for first few iterations only
static int incy_log = 0;
if (PC >= 0xFFE4 && PC <= 0xFFE6 && incy_log++ < 10) {
LOG_DEBUG("SPC", "INC Y executed at PC=$%04X: Y changed from $%02X to $%02X (Z=%d N=%d)",
PC - 1, old_y, Y, PSW.Z, PSW.N);
}
break;
}

8
src/app/emu/cpu/cpu.cc
View File

@@ -61,7 +61,7 @@ void Cpu::RunOpcode() {
uint8_t low_byte = ReadByte(0xfffc);
uint8_t high_byte = ReadByte(0xfffd);
PC = low_byte | (high_byte << 8);
LOG_INFO("CPU", "Reset vector: $FFFC=$%02X $FFFD=$%02X -> PC=$%04X",
LOG_DEBUG("CPU", "Reset vector: $FFFC=$%02X $FFFD=$%02X -> PC=$%04X",
low_byte, high_byte, PC);
return;
}
@@ -80,7 +80,7 @@ void Cpu::RunOpcode() {
PB, PC, irq_wanted_, nmi_wanted_, GetInterruptFlag());
}
if (irq_wanted_ || nmi_wanted_) {
LOG_INFO("CPU", "CPU waking from WAIT - irq=%d nmi=%d", irq_wanted_, nmi_wanted_);
LOG_DEBUG("CPU", "CPU waking from WAIT - irq=%d nmi=%d", irq_wanted_, nmi_wanted_);
waiting_ = false;
callbacks_.idle(false);
CheckInt();
@@ -124,7 +124,7 @@ void Cpu::RunOpcode() {
}
if (should_log) {
LOG_INFO("CPU", "Exec #%d: $%02X:%04X opcode=$%02X",
LOG_DEBUG("CPU", "Exec #%d: $%02X:%04X opcode=$%02X",
instruction_count, PB, PC - 1, opcode);
}
@@ -140,7 +140,7 @@ void Cpu::RunOpcode() {
}
} else {
if (stuck_count > 50) {
LOG_INFO("CPU", "Moved from $%02X:%04X (was stuck %d times) to $%02X:%04X",
LOG_DEBUG("CPU", "Moved from $%02X:%04X (was stuck %d times) to $%02X:%04X",
PB, last_stuck_pc, stuck_count, PB, PC - 1);
}
stuck_count = 0;

4
src/app/emu/memory/memory.cc
View File

@@ -26,9 +26,9 @@ void MemoryImpl::Initialize(const std::vector<uint8_t>& rom_data,
ram_.resize(sram_size_);
std::fill(ram_.begin(), ram_.end(), 0);
LOG_INFO("Memory", "LoROM initialized: ROM size=$%06X (%zuKB) SRAM size=$%04X",
LOG_DEBUG("Memory", "LoROM initialized: ROM size=$%06X (%zuKB) SRAM size=$%04X",
rom_size_, rom_size_ / 1024, sram_size_);
LOG_INFO("Memory", "Reset vector at ROM offset $7FFC-$7FFD = $%02X%02X",
LOG_DEBUG("Memory", "Reset vector at ROM offset $7FFC-$7FFD = $%02X%02X",
rom_data[0x7FFD], rom_data[0x7FFC]);
}

28
src/app/emu/snes.cc
View File

@@ -31,7 +31,7 @@ uint8_t input_read(Input* input) {
} // namespace
void Snes::Init(std::vector<uint8_t>& rom_data) {
LOG_INFO("SNES", "Initializing emulator with ROM size %zu bytes", rom_data.size());
LOG_DEBUG("SNES", "Initializing emulator with ROM size %zu bytes", rom_data.size());
// Initialize the CPU, PPU, and APU
ppu_.Init();
@@ -42,11 +42,11 @@ void Snes::Init(std::vector<uint8_t>& rom_data) {
Reset(true);
running_ = true;
LOG_INFO("SNES", "Emulator initialization complete");
LOG_DEBUG("SNES", "Emulator initialization complete");
}
void Snes::Reset(bool hard) {
LOG_INFO("SNES", "Reset called (hard=%d)", hard);
LOG_DEBUG("SNES", "Reset called (hard=%d)", hard);
cpu_.Reset(hard);
apu_.Reset();
ppu_.Reset();
@@ -84,14 +84,14 @@ void Snes::Reset(bool hard) {
memory_.set_open_bus(0);
next_horiz_event = 16;
InitAccessTime(false);
LOG_INFO("SNES", "Reset complete - CPU will start at $%02X:%04X", cpu_.PB, cpu_.PC);
LOG_DEBUG("SNES", "Reset complete - CPU will start at $%02X:%04X", cpu_.PB, cpu_.PC);
}
void Snes::RunFrame() {
// Debug: Log every 60th frame
static int frame_log_count = 0;
if (frame_log_count % 60 == 0) {
LOG_INFO("SNES", "Frame %d: CPU=$%02X:%04X vblank=%d frames_=%d",
LOG_DEBUG("SNES", "Frame %d: CPU=$%02X:%04X vblank=%d frames_=%d",
frame_log_count, cpu_.PB, cpu_.PC, in_vblank_, frames_);
}
frame_log_count++;
@@ -99,7 +99,7 @@ void Snes::RunFrame() {
// Debug: Log vblank loop entry
static int vblank_loop_count = 0;
if (in_vblank_ && vblank_loop_count++ < 10) {
LOG_INFO("SNES", "RunFrame: Entering vblank loop (in_vblank_=true)");
LOG_DEBUG("SNES", "RunFrame: Entering vblank loop (in_vblank_=true)");
}
while (in_vblank_) {
@@ -111,7 +111,7 @@ void Snes::RunFrame() {
// Debug: Log active frame loop entry
static int active_loop_count = 0;
if (!in_vblank_ && active_loop_count++ < 10) {
LOG_INFO("SNES", "RunFrame: Entering active frame loop (in_vblank_=false, frame=%d, frames_=%d)",
LOG_DEBUG("SNES", "RunFrame: Entering active frame loop (in_vblank_=false, frame=%d, frames_=%d)",
frame, frames_);
}
@@ -219,7 +219,7 @@ void Snes::RunCycle() {
// end of vblank
static int vblank_end_count = 0;
if (vblank_end_count++ < 10) {
LOG_INFO("SNES", "VBlank END - v_pos=0, setting in_vblank_=false at frame %d", frames_);
LOG_DEBUG("SNES", "VBlank END - v_pos=0, setting in_vblank_=false at frame %d", frames_);
}
in_vblank_ = false;
in_nmi_ = false;
@@ -247,7 +247,7 @@ void Snes::RunCycle() {
static int vblank_start_count = 0;
if (vblank_start_count++ < 10) {
LOG_INFO("SNES", "VBlank START - v_pos=%d, setting in_vblank_=true at frame %d",
LOG_DEBUG("SNES", "VBlank START - v_pos=%d, setting in_vblank_=true at frame %d",
memory_.v_pos(), frames_);
}
@@ -260,7 +260,7 @@ void Snes::RunCycle() {
}
static int nmi_log_count = 0;
if (nmi_log_count++ < 10) {
LOG_INFO("SNES", "VBlank NMI check: nmi_enabled_=%d, calling Nmi()=%s",
LOG_DEBUG("SNES", "VBlank NMI check: nmi_enabled_=%d, calling Nmi()=%s",
nmi_enabled_, nmi_enabled_ ? "YES" : "NO");
}
if (nmi_enabled_) {
@@ -307,7 +307,7 @@ uint8_t Snes::ReadBBus(uint8_t adr) {
static uint8_t last_f4 = 0xFF, last_f5 = 0xFF;
bool value_changed = ((adr & 0x3) == 0 && val != last_f4) || ((adr & 0x3) == 1 && val != last_f5);
if (value_changed || cpu_port_read_count++ < 5) {
LOG_INFO("SNES", "CPU read APU port $21%02X (F%d) = $%02X at PC=$%02X:%04X [AFTER CatchUp: APU_cycles=%llu CPU_cycles=%llu]",
LOG_DEBUG("SNES", "CPU read APU port $21%02X (F%d) = $%02X at PC=$%02X:%04X [AFTER CatchUp: APU_cycles=%llu CPU_cycles=%llu]",
0x40 + (adr & 0x3), (adr & 0x3) + 4, val, cpu_.PB, cpu_.PC, apu_.GetCycles(), cycles_);
if ((adr & 0x3) == 0) last_f4 = val;
if ((adr & 0x3) == 1) last_f5 = val;
@@ -421,7 +421,7 @@ void Snes::WriteBBus(uint8_t adr, uint8_t val) {
apu_.in_ports_[adr & 0x3] = val;
static int cpu_port_write_count = 0;
if (cpu_port_write_count++ < 10) { // Reduced to prevent crash
LOG_INFO("SNES", "CPU wrote APU port $21%02X (F%d) = $%02X at PC=$%02X:%04X",
LOG_DEBUG("SNES", "CPU wrote APU port $21%02X (F%d) = $%02X at PC=$%02X:%04X",
0x40 + (adr & 0x3), (adr & 0x3) + 4, val, cpu_.PB, cpu_.PC);
}
@@ -457,7 +457,7 @@ void Snes::WriteReg(uint16_t adr, uint8_t val) {
// Log ALL writes to $4200 unconditionally
static int write_4200_count = 0;
if (write_4200_count++ < 20) {
LOG_INFO("SNES", "Write $%02X to $4200 at PC=$%02X:%04X (NMI=%d IRQ_H=%d IRQ_V=%d JOY=%d)",
LOG_DEBUG("SNES", "Write $%02X to $4200 at PC=$%02X:%04X (NMI=%d IRQ_H=%d IRQ_V=%d JOY=%d)",
val, cpu_.PB, cpu_.PC, (val & 0x80) ? 1 : 0, (val & 0x10) ? 1 : 0,
(val & 0x20) ? 1 : 0, (val & 0x01) ? 1 : 0);
}
@@ -477,7 +477,7 @@ void Snes::WriteReg(uint16_t adr, uint8_t val) {
bool old_nmi = nmi_enabled_;
nmi_enabled_ = val & 0x80;
if (old_nmi != nmi_enabled_) {
LOG_INFO("SNES", ">>> NMI enabled CHANGED: %d -> %d <<<",
LOG_DEBUG("SNES", ">>> NMI enabled CHANGED: %d -> %d <<<",
old_nmi, nmi_enabled_);
}
cpu_.set_int_delay(true);