Perfilado de Rendimiento y Optimización: Eliminación de Logging y Fast-Path MMU

Resumen

El emulador funcionaba correctamente pero con un rendimiento pobre (8-14 FPS) que lo hacía injugable. Se creó un script de perfilado usando cProfile que identificó que el 42% del tiempo de ejecución se gastaba en llamadas a logger.debug() aunque el nivel fuera CRITICAL. Se aplicaron optimizaciones quirúrgicas: eliminación completa de logging en rutas críticas (hot paths), optimización del orden de verificación en MMU.read_byte() (fast path para ROM primero), y uso de __slots__ en la clase MMU. Resultado: mejora del 30% en rendimiento, de 7.5 FPS a 9.7 FPS en modo headless, con 30% más ciclos ejecutados en el mismo tiempo.

Concepto de Hardware

Profiling y Optimización de Rendimiento en Emuladores: Un emulador debe ejecutar millones de instrucciones por segundo (la Game Boy funciona a 4.19 MHz). Cada operación que añade overhead innecesario, por pequeña que sea, se multiplica millones de veces y puede causar problemas de rendimiento graves.

Hot Paths (Rutas Críticas): Son las funciones que se ejecutan millones de veces por segundo: MMU.read_byte() (acceso a memoria), CPU.step() (ejecución de instrucciones), CPU.fetch_byte() (lectura de opcodes), y PPU.step() (avance del motor de gráficos). Cualquier overhead en estas funciones tiene un impacto exponencial.

Overhead de Logging: Aunque el logger esté configurado en nivel CRITICAL, Python aún debe: 1) Preparar la llamada a logger.debug(), 2) Evaluar los argumentos (f-strings crean strings nuevos), 3) Llamar a la función, 4) Verificar el nivel internamente, 5) Descartar el resultado. Hacer esto 2.8 millones de veces por segundo consume recursos significativos.

Fast Path Optimization: En MMU.read_byte(), el acceso más frecuente es leer ROM (fetch de instrucciones desde 0x0000-0x7FFF). Reordenar los if/elif para verificar ROM primero reduce el número promedio de comparaciones por acceso, mejorando el rendimiento.

Implementación

Se creó un script de perfilado (tools/profile_viboy.py) que ejecuta el emulador en modo headless durante 10 segundos y analiza el tiempo consumido por cada función usando cProfile y pstats.

Resultados del Perfilado Inicial

El perfilado reveló que el 42% del tiempo total se gastaba en logging:

• logging.debug(): 1,314,522 llamadas → 1.797 segundos
• logging.isEnabledFor(): 1,314,522 llamadas → 1.411 segundos
• logging._is_disabled(): 1,314,522 llamadas → 1.016 segundos
• Total: ~4.2 segundos de 10 segundos (42%)

El rendimiento inicial era de 7.5 FPS teóricos (131,585 M-Cycles/segundo), muy por debajo del objetivo de 60 FPS.

Optimizaciones Aplicadas

1. Eliminación de Logging en Hot Paths

• MMU: Desactivado logging a nivel CRITICAL en src/memory/mmu.py
• CPU: Desactivado logging a nivel CRITICAL en src/cpu/core.py
• Comentadas llamadas críticas en CPU.step(), CPU.handle_interrupts(), y funciones de stack (_push_byte, _pop_byte, _push_word, _pop_word)
• Comentadas llamadas en handlers dinámicos dentro de _init_ld_handler_lazy()

2. Optimización Fast-Path en MMU.read_byte()

• Reordenado if/elif para verificar ROM primero (addr <= 0x7FFF)
• Agrupado acceso a WRAM/HRAM (0xC000-0xFFFF) con verificaciones de I/O específicas
• VRAM al final (0x8000-0xFEFF) como menos frecuente
• Reducción del número promedio de comparaciones por acceso de memoria

3. Optimización con __slots__

• Añadido __slots__ = ['_memory', '_cartridge', '_ppu', '_joypad', '_timer', 'vram_write_count'] a la clase MMU
• Reduce el overhead de acceso a atributos al eliminar el diccionario de instancia
• Mejora el uso de memoria y la velocidad de acceso

Resultados Finales

Después de las optimizaciones:

• FPS teórico: 7.5 → 9.7 FPS (29% mejora)
• M-Cycles ejecutados: 1,315,852 → 1,710,334 (30% más ciclos en el mismo tiempo)
• Tiempo en logging: 4.2s → 1.9s (55% reducción)
• T-Cycles/segundo: 526,340 → 684,133 (30% mejora)

Nota: Aún quedan ~529k llamadas a logger.debug() activas, pero el tiempo consumido se redujo significativamente al desactivar el logger a nivel CRITICAL. Para eliminarlas completamente sería necesario comentar todas las llamadas o usar verificaciones condicionales, pero añadirían overhead.

Archivos Afectados

• tools/profile_viboy.py (nuevo) - Script de perfilado usando cProfile y pstats
• src/memory/mmu.py (modificado) - Añadido __slots__, optimizado read_byte() con fast path, desactivado logging
• src/cpu/core.py (modificado) - Desactivado logging a nivel CRITICAL, comentadas llamadas críticas

Tests y Verificación

Se utilizó perfilado científico con cProfile para identificar y verificar las optimizaciones:

Perfilado Inicial (Antes de Optimizaciones)

Comando ejecutado:

python tools/profile_viboy.py

Entorno: Windows / Python 3.13.5

Resultado:

• FPS teórico: 7.5 FPS
• M-Cycles ejecutados: 1,315,852
• Tiempo en logging: ~4.2 segundos (42% del tiempo total)
• Top función: MMU.read_byte() con 2,844,148 llamadas (1.282s)

Perfilado Final (Después de Optimizaciones)

Comando ejecutado:

python tools/profile_viboy.py

Entorno: Windows / Python 3.13.5

Resultado:

• FPS teórico: 9.7 FPS (29% mejora)
• M-Cycles ejecutados: 1,710,334 (30% más ciclos)
• Tiempo en logging: ~1.9 segundos (19% del tiempo total, 55% reducción)
• Top función: MMU.read_byte() con 3,695,025 llamadas (1.152s) - más eficiente

Qué Valida el Perfilado

• Identificación de cuellos de botella: El perfilado muestra exactamente qué funciones consumen más tiempo
• Medición de mejoras: Permite cuantificar el impacto de cada optimización
• Verificación de eficiencia: Confirma que las optimizaciones realmente mejoran el rendimiento

Fuentes Consultadas

• Python cProfile Documentation: https://docs.python.org/3/library/profile.html
• Python __slots__: Optimización de memoria y acceso a atributos en clases
• Clean Code Principles: Optimización de hot paths en código de alto rendimiento

Nota: La optimización se basa en principios generales de profiling y optimización de código Python, aplicados específicamente a las necesidades de un emulador de Game Boy.

Integridad Educativa

Próximos Pasos

• [ ] Verificar rendimiento en tiempo real con renderizado gráfico activo
• [ ] Probar el emulador con diferentes ROMs para validar que las optimizaciones no introducen bugs
• [ ] Explorar optimizaciones adicionales en MMU.read_byte() si el rendimiento aún no es suficiente
• [ ] Considerar eliminar completamente las llamadas a logger.debug() restantes si es necesario