Diagnóstico de Flujo CPU y Escrituras a VRAM

Fecha: 2025-12-30 | Step ID: 0382 | Estado: VERIFIED

Resumen

Se implementa instrumentación completa para diagnosticar por qué VRAM permanece vacía (0/6144) tras 120 segundos en pkmn.gb, a pesar de que el renderizado funciona (checkerboard correcto) y el Joypad funciona (polling confirmado en Steps previos).

El diagnóstico revela que la CPU SÍ escribe a VRAM (10,000+ escrituras), pero está ejecutando una rutina de borrado masivo (PC:0x36E3 escribe zeros) seguida de carga parcial de tiles (18.08% no-cero). El juego entonces entra en un loop de polling en Bank 28 (PCs 0x614D-0x6153), esperando condiciones que el emulador no proporciona.

Contexto y Objetivo

Problema a Resolver

Tras los Steps 0380-0381, confirmamos que:

✅ El renderizado funciona (checkerboard visible)
✅ El Joypad funciona (24,803 escrituras a P1, lectura de filas correcta)
❌ VRAM permanece vacía (0/6144 bytes no-cero tras 120 segundos)

Hipótesis a verificar:

H1 (CPU/flujo): La CPU está atascada en un bucle/espera y nunca llega a cargar tiles.
H2 (VRAM bloqueada): La CPU intenta cargar tiles pero las escrituras a 0x8000–0x9FFF se bloquean incorrectamente.

Objetivo del Step

Determinar cuál hipótesis (H1 o H2) es real mediante instrumentación de:

Escrituras a VRAM (0x8000-0x9FFF)
PC sampler y detección de bucles
Estado de interrupciones (IE/IF/IME)

Concepto de Hardware

Acceso a VRAM por Modos PPU (Pan Docs)

Según Pan Docs - VRAM Access:

VRAM (0x8000-0x9FFF): Área donde se cargan tiles (Tile Data) y tilemaps (Tile Maps).
Restricción de acceso: En hardware real, la CPU no puede acceder a VRAM durante PPU Mode 3 (pixel transfer). En otros modos (Mode 0 = H-Blank, Mode 1 = V-Blank, Mode 2 = OAM Search), la CPU sí puede acceder.
LCDC (0xFF40): Controla el estado del LCD. Bit 7=1 activa el LCD.

Rol de VBlank y Timer (Pan Docs)

Según Pan Docs - Interrupts:

VBlank (bit 0 de IE/IF): Interrupción generada al inicio del período V-Blank (LY=144). Muchos juegos cargan tiles durante V-Blank para evitar artefactos visuales.
Timer (bit 2 de IE/IF): Interrupción generada por el Timer al desbordar TIMA.
IME (Interrupt Master Enable): Flag global que habilita/deshabilita el procesamiento de interrupciones.
Si IE/IME/IF están mal manejados, el juego puede quedar polleando esperando una interrupción que nunca llega, lo que bloquea la progresión (incluyendo la carga de tiles).

Implementación

Tarea 1: Instrumentación de Escrituras a VRAM (MMU)

Se modificó src/core/cpp/MMU.cpp para agregar:

Contadores globales: vram_write_total_step382_ y vram_write_nonzero_step382_.
Logs limitados: Solo las primeras 50 escrituras con información completa:
- PC actual (debug_current_pc)
- Dirección y valor (addr, value)
- Modo PPU, LY, LCDC (si PPU está conectada)
- Si la escritura estaría bloqueada en Mode 3 (Blocked:YES/NO)
Resúmenes cada 1000 escrituras: Total, no-cero, ratio.

Tarea 2: PC Sampler y Detección de Bucles (CPU)

Se modificó src/core/cpp/CPU.cpp para agregar:

Muestreo cada 10,000 instrucciones: PC, Bank, IME, IE, IF, HALT (solo primeras 50 muestras).
Detección de bucles: Si el mismo PC se repite en múltiples muestras consecutivas, logge ar alerta.
Transiciones de HALT: Loggear cuando la CPU entra/sale del estado HALT.

Tarea 3: Verificación de Interrupciones (IE/IF/IME)

Se reutilizó la instrumentación existente de [IE-WRITE-TRACE] (ya presente en MMU.cpp) para verificar:

Escrituras a IE (0xFFFF)
Qué interrupciones se habilitan
Estado de IME (reportado por el PC sampler)

Tests y Verificación

Compilación

cd /media/fabini/8CD1-4C30/ViboyColor
python3 setup.py build_ext --inplace > build_log_step0382.txt 2>&1
# Exit code: 0 (éxito)

Ejecución Controlada (30 segundos)

cd /media/fabini/8CD1-4C30/ViboyColor
timeout 30 python3 main.py roms/pkmn.gb > logs/step0382_cpu_vram_probe.log 2>&1
# Exit code: 124 (timeout correcto)

Extracción de Evidencia

# Escrituras a VRAM
grep -E "\[MMU-VRAM-(WRITE|BLOCK|WRITE-SUMMARY)\]" logs/step0382_cpu_vram_probe.log | head -n 120

# PC sampler / bucles
grep -E "\[CPU-(SAMPLE|LOOP-DETECT|HALT)\]" logs/step0382_cpu_vram_probe.log | head -n 120

# Estado de interrupciones
grep -E "\[IE-WRITE-TRACE\]" logs/step0382_cpu_vram_probe.log | head -n 60

# Errores
grep -i "error\|exception\|traceback" logs/step0382_cpu_vram_probe.log | head -n 60
# (No se encontraron errores)

Resultados - Escrituras a VRAM

[MMU-VRAM-WRITE] #1 | PC:0x36E3 | Addr:0x8000 | Val:0x00 | Mode:0 | LY:83 | LCDC:0x81 | Blocked:NO
[MMU-VRAM-WRITE] #2 | PC:0x36E3 | Addr:0x8001 | Val:0x00 | Mode:0 | LY:83 | LCDC:0x81 | Blocked:NO
...
[MMU-VRAM-WRITE] #50 | PC:0x36E3 | Addr:0x8031 | Val:0x00 | Mode:2 | LY:88 | LCDC:0x81 | Blocked:NO
[MMU-VRAM-WRITE-SUMMARY] Total:1000 | NonZero:0 | Ratio:0.00%
...
[MMU-VRAM-WRITE-SUMMARY] Total:8000 | NonZero:0 | Ratio:0.00%
[MMU-VRAM-WRITE-SUMMARY] Total:9000 | NonZero:808 | Ratio:8.98%
[MMU-VRAM-WRITE-SUMMARY] Total:10000 | NonZero:1808 | Ratio:18.08%

Resultados - PC Sampler

[CPU-SAMPLE] #1 | Instrs:10000 | PC:0x1F80 | Bank:1 | IME:0 | IE:0x00 | IF:0x01 | HALT:0
[CPU-SAMPLE] #2 | Instrs:20000 | PC:0x1F85 | Bank:1 | IME:0 | IE:0x00 | IF:0x01 | HALT:0
...
[CPU-SAMPLE] #11 | Instrs:110000 | PC:0x1CFA | Bank:1 | IME:0 | IE:0x0D | IF:0x00 | HALT:0
[CPU-SAMPLE] #12 | Instrs:120000 | PC:0x6151 | Bank:28 | IME:1 | IE:0x0D | IF:0x00 | HALT:0
[CPU-SAMPLE] #13 | Instrs:130000 | PC:0x614F | Bank:28 | IME:1 | IE:0x0D | IF:0x00 | HALT:0
...
[CPU-SAMPLE] #50 | Instrs:500000 | PC:0x6153 | Bank:28 | IME:1 | IE:0x0D | IF:0x00 | HALT:0

Resultados - Interrupciones

[IE-WRITE-TRACE] PC:0x1FAE Bank:1 | 0x00 -> 0x0D
[IE-WRITE-TRACE]   Interrupciones habilitadas: V-Blank Timer Serial 
[IE-WRITE-TRACE] ⚠️ V-BLANK INTERRUPT HABILITADA en PC:0x1FAE

Validación de Módulo Compilado C++

✅ Todos los logs provienen de código C++ compilado (tags [MMU-VRAM-WRITE], [CPU-SAMPLE]).

Análisis de Resultados

✅ Confirmación: CPU SÍ Escribe a VRAM

10,000+ escrituras a VRAM detectadas en 30 segundos.
PC: 0x36E3 (rutina de limpieza conocida de Steps previos).
Modo PPU: Algunas escrituras se marcan como Blocked:YES en Mode 3, pero la mayoría son en Mode 0/2 (no bloqueadas).
CRÍTICO: Las primeras 8,000 escrituras son todas ceros (Val:0x00).
A partir de escritura #9000: 808 no-cero (8.98%).
Total final: 1,808/10,000 no-cero (18.08%).

✅ Confirmación: CPU Ejecutándose Normalmente

NO hay bucle infinito: PC avanza por múltiples ubicaciones.
Cambio de banco detectado: Bank 1 → Bank 28 alrededor de 120,000 instrucciones.
Polling en rango 0x614D-0x6153 (Bank 28) - comportamiento normal de espera.
IME=1, IE=0x0D (V-Blank+Timer+Serial habilitadas).
NO en HALT.

🔍 Conclusión

El problema es una combinación de H1 y comportamiento de inicialización:

La CPU SÍ escribe a VRAM (descarta H2 pura: no es un bloqueo completo).
Pero está ejecutando una rutina de borrado masivo (PC:0x36E3 escribe zeros).
Luego carga algunos tiles (18.08%), pero insuficientes o en ubicación incorrecta.
El juego entra en modo de espera/polling (Bank 28, PCs 0x614D-0x6153), esperando condiciones que el emulador no proporciona.

La causa raíz es que el juego está esperando algo (probablemente carga de datos desde ROM o evento específico) pero nuestro emulador no está proporcionando las condiciones correctas para que progrese.

Próximo paso (Step 0383): Investigar qué está esperando el juego en Bank 28 (PCs 0x614D-0x6153). Posibles causas:

Espera de interrupción específica (Timer, Serial)
Espera de lectura de ROM (bancos adicionales)
Espera de estado de hardware (PPU, Timer)
Bug en opcodes relacionados con saltos condicionales o HALT

Archivos Modificados

src/core/cpp/MMU.hpp - Declaración de contadores y función get_vram_write_stats()
src/core/cpp/MMU.cpp - Instrumentación de escrituras a VRAM (Step 0382)
src/core/cpp/CPU.hpp - Declaración de miembros para PC sampler
src/core/cpp/CPU.cpp - PC sampler y detección de bucles