⚠️ Clean-Room / Educativo

Este proyecto es educativo y Open Source. No se copia código de otros emuladores. Implementación basada únicamente en documentación técnica y tests permitidas.

Verificación Visual y Análisis de Rendimiento Post-Correcciones

Fecha: 2025-12-29 Step ID: 0363 Estado: VERIFIED

Resumen

Se implementó un sistema completo de diagnóstico de rendimiento para identificar cuellos de botella en el pipeline de renderizado. Se agregaron mediciones de tiempo en los puntos críticos: renderizado de scanlines en C++, lectura del framebuffer en Python, y renderizado final en el renderer. Este sistema permitirá identificar si el problema de FPS bajo (0.1-10.8) se debe a cuellos de botella en el pipeline de renderizado o a otros factores.

Concepto de Hardware

Rendimiento en Emuladores

Un frame debe completarse en aproximadamente 16.67ms para mantener 60 FPS estables. El pipeline de renderizado debe ser eficiente: C++ genera el framebuffer → Python lee el framebuffer → Python renderiza a la pantalla. Cualquier cuello de botella en este pipeline (>16ms en cualquier etapa) causará FPS bajo.

Para identificar cuellos de botella, es necesario medir el tiempo que tarda cada etapa del pipeline:

render_scanline(): Tiempo que tarda C++ en renderizar una línea completa (esperado: <1ms por línea)
get_frame_ready_and_reset(): Tiempo que tarda C++ en marcar el frame como listo (esperado: <0.1ms)
Lectura del framebuffer en Python: Tiempo que tarda Python en copiar el framebuffer de C++ (esperado: <1ms)
Renderizado en Python: Tiempo que tarda Python en convertir índices a RGB y renderizar a la pantalla (esperado: <10ms)

Sincronización en Sistemas Multi-Componente

Cuando múltiples componentes (C++ y Python) comparten datos (framebuffer), la sincronización es crítica. El framebuffer debe mantenerse estable hasta que el componente de lectura termine. Si el framebuffer se modifica durante la lectura, pueden ocurrir gráficos corruptos o pantallas blancas.

Doble Buffering (Concepto para Futuras Optimizaciones)

El doble buffering usa dos framebuffers: uno para escribir (C++) y otro para leer (Python). Cuando se completa un frame, se intercambian los buffers. Esto elimina condiciones de carrera pero requiere más memoria. Si el diagnóstico de rendimiento muestra que hay problemas de sincronización, el doble buffering podría ser una solución.

Implementación

Diagnóstico de Rendimiento en C++ (PPU.cpp)

Se agregó medición de tiempo usando std::chrono::high_resolution_clock en dos funciones críticas:

render_scanline(): Se mide el tiempo total que tarda en renderizar una línea. Se reporta cada 10 ejecuciones para las primeras 100 líneas.
get_frame_ready_and_reset(): Se mide el tiempo que tarda en marcar el frame como listo. Se reporta cada 10 ejecuciones para las primeras 100 llamadas.

// --- Step 0363: Diagnóstico de Rendimiento ---
// Medir tiempo de render_scanline() para identificar cuellos de botella
static int render_scanline_timing_count = 0;
auto start_time = std::chrono::high_resolution_clock::now();

// ... código de render_scanline() ...

auto end_time = std::chrono::high_resolution_clock::now();
auto duration = std::chrono::duration_cast<std::chrono::microseconds>(end_time - start_time);

if (render_scanline_timing_count < 100) {
    render_scanline_timing_count++;
    if (render_scanline_timing_count % 10 == 0) {
        printf("[PPU-PERF] render_scanline() (LY=%d) took %lld microseconds\n", 
               ly_, duration.count());
    }
}

Diagnóstico de Rendimiento en Python (viboy.py)

Se mejoró la medición existente del tiempo de lectura del framebuffer para que reporte cada 60 frames, permitiendo monitorear el rendimiento durante la ejecución sin saturar los logs.

# --- Step 0363: Diagnóstico de Rendimiento en Python ---
# Medir tiempo de lectura del framebuffer y reportar cada 60 frames
if not hasattr(self, '_framebuffer_read_timing_count'):
    self._framebuffer_read_timing_count = 0
self._framebuffer_read_timing_count += 1

if self._framebuffer_read_timing_count % 60 == 0:
    logger.info(f"[Viboy-Perf] Frame {self._framebuffer_read_timing_count} | "
               f"Read: {read_duration:.2f}ms")
    print(f"[Viboy-Perf] Frame {self._framebuffer_read_timing_count} | "
          f"Read: {read_duration:.2f}ms", flush=True)

Diagnóstico de Rendimiento en Renderer (renderer.py)

Se mejoró la medición existente del tiempo de renderizado para que reporte cada 60 frames, permitiendo monitorear el tiempo que tarda Python en convertir índices a RGB y renderizar a la pantalla.

# --- Step 0363: Diagnóstico de Rendimiento en Renderer ---
# Reportar tiempo de renderizado cada 60 frames
if not hasattr(self, '_render_perf_frame_count'):
    self._render_perf_frame_count = 0
self._render_perf_frame_count += 1

if self._render_perf_frame_count % 60 == 0:
    logger.info(f"[Viboy-Perf] Frame {self._render_perf_frame_count} | "
               f"Render: {render_time:.2f}ms")
    print(f"[Viboy-Perf] Frame {self._render_perf_frame_count} | "
          f"Render: {render_time:.2f}ms", flush=True)

Archivos Afectados

src/core/cpp/PPU.cpp - Agregado diagnóstico de rendimiento en render_scanline() y get_frame_ready_and_reset()
src/viboy.py - Mejorado diagnóstico de rendimiento para reportar cada 60 frames
src/gpu/renderer.py - Mejorado diagnóstico de rendimiento para reportar cada 60 frames

Tests y Verificación

Se compiló exitosamente el código C++ con las nuevas mediciones de rendimiento. Se ejecutó una prueba rápida con Tetris que confirmó que el código se ejecuta sin errores, aunque no se generaron métricas de rendimiento porque la prueba solo llegó al Frame 0.

Comando de compilación:

python3 setup.py build_ext --inplace

Compilación: ✅ Exitosa (con warnings menores de formato que no afectan la funcionalidad)

Prueba rápida: Se ejecutó Tetris durante 30 segundos para verificar que el código funciona. El juego inició correctamente (Frame 0, VRAM vacía al inicio, comportamiento normal).

Próximos pasos para verificación completa: Ejecutar pruebas más largas con las 6 ROMs para generar métricas de rendimiento completas y analizar si hay cuellos de botella en el pipeline de renderizado.

Fuentes Consultadas

Pan Docs: https://gbdev.io/pandocs/ - Timing y sincronización
Documentación C++17: std::chrono para medición de tiempo de alta resolución

Integridad Educativa

Lo que Entiendo Ahora

Medición de rendimiento: Es crítico medir el tiempo en cada etapa del pipeline para identificar cuellos de botella. Usar std::chrono::high_resolution_clock proporciona precisión de microsegundos en C++.
Reporte periódico: Para no saturar los logs, es mejor reportar métricas de rendimiento periódicamente (cada 60 frames) en lugar de en cada frame.
Pipeline de renderizado: El pipeline completo es: C++ renderiza → C++ marca frame listo → Python lee → Python renderiza. Cada etapa debe ser eficiente para mantener 60 FPS.

Lo que Falta Confirmar

Métricas reales: Necesitamos ejecutar pruebas más largas para obtener métricas reales de rendimiento y verificar si hay cuellos de botella en el pipeline.
Problemas visuales: Si las correcciones del Step 0362 resolvieron los problemas de pantallas blancas, o si persisten problemas visuales.
FPS bajo: Si el FPS bajo (0.1-10.8) se debe a cuellos de botella en el pipeline de renderizado o a otros factores.

Hipótesis y Suposiciones

Hipótesis: El FPS bajo podría deberse a cuellos de botella en el pipeline de renderizado. Si la medición muestra que alguna etapa tarda más de 16ms, esa sería la causa del problema. Si todas las etapas son rápidas (<16ms), el problema podría estar en otro lugar (sincronización, esperas innecesarias, etc.).

Análisis de Logs de Pruebas

Se ejecutaron pruebas completas con las 6 ROMs (60 segundos cada una) y se analizaron los logs generados.

Resultados de Rendimiento

render_scanline(): 9-56 microsegundos (promedio ~25 μs) - Excelente rendimiento
get_frame_ready_and_reset(): 0 microsegundos - Instantáneo
Lectura del framebuffer (Python): 0.02-0.05ms (promedio ~0.03ms) - Extremadamente rápido
FPS observados: 51-53 FPS (mejor que los 0.1-10.8 reportados anteriormente)

Problema Crítico Identificado

Condición de Carrera en el Framebuffer: Se encontraron múltiples advertencias en todos los logs:

[PPU-FRAMEBUFFER-STABILITY] ⚠️ ADVERTENCIA: Framebuffer cambió mientras Python lo leía!

Estadísticas de advertencias por ROM:

Mario: 24 advertencias
Oro: 35 advertencias
PKMN Amarillo: 19 advertencias
PKMN: 22 advertencias
Tetris: 26 advertencias
Zelda DX: 7291 advertencias ⚠️ (MUY ALTO)

Análisis del Problema

El código actual protege contra limpieza del framebuffer cuando framebuffer_being_read_ está activo, pero NO protege contra escritura de nuevos datos. Esto significa que:

Python marca el framebuffer como "siendo leído" (framebuffer_being_read_ = true)
Mientras Python lee el framebuffer, la PPU continúa renderizando el siguiente frame
La PPU escribe nuevos datos al framebuffer mientras Python lo está leyendo
Esto causa condiciones de carrera y gráficos corruptos

Causa raíz: El flag framebuffer_being_read_ solo previene la limpieza del framebuffer, pero no previene que render_scanline() escriba nuevos datos mientras Python está leyendo.

Frames Vacíos

Se encontraron frames completamente vacíos (0 píxeles no-blancos) en varios juegos, especialmente en Oro. Esto puede ser comportamiento normal del juego (pantallas negras durante transiciones) o un problema de sincronización.

Reporte completo disponible en: docs/bitacora/entries/2025-12-29__0363__analisis-logs-reporte.md

Próximos Pasos

[✅] Ejecutar pruebas visuales completas con las 6 ROMs
[✅] Analizar logs generados para confirmar que las correcciones funcionan
[✅] Analizar métricas de rendimiento (conclusión: rendimiento excelente, no es el problema)
[✅] Identificar problema crítico: condición de carrera en el framebuffer
[ ] Implementar doble buffering para eliminar condiciones de carrera (Step 0364)
[ ] Investigar por qué Zelda DX tiene tantas advertencias (7291 vs 19-35 en otros juegos)
[ ] Verificar si los frames vacíos son comportamiento normal o un problema