domingo, 14 de diciembre de 2014

Por qué la ejecución era tan leeenta en el depurador

Hace unos días comenté que había estado renegando para depurar un proyecto en Windows porque al correrlo en el depurador la ejecución tardaba 17 veces más de lo normal. Encontré en aquel momento un workaround para salir del paso, pero no sabía entonces la causa real del problema. Cerré el post prometiendo escribir si la averiguaba, y ahora vengo a cumplir con eso. Ya encontré la causa, y una solución muy simple que, como siempre, estará incluida en ZinjaI para la próxima versión (muy pronto).

El problema lo encontré como una semana antes de que lo publicara en el blog: un exe tardaba 8 segundos en hacer algo fuera de gdb, y 140 dentro. Solo me pasaba en Windows. Mi (limitado pero no nulo) conocimiento de cómo se supone que trabaja internamente gdb me decía que eso no tenía sentido, no me imaginaba de donde podía venir el problema. En ese momento intenté hacer un profiling de mi aplicación, con gprof (desde el menú herramientas de ZinjaI), para tratar de determinar dónde se tardaba tanto. Los resultados fueron desconcertantes: en los tiempos informados por gprof no había diferencia sustancial entre correr dentro o fuera del depurador. Probé hasta compilar yo mismo mi propio gdb actualizado y hacerle profiling al depurador también para ver dónde se comía tanto tiempo: y tampoco encontré nada. El tiempo perdido no salía en ningún reporte. Era como que no pasaba más tiempo... o tal vez solo era que el tiempo se detenía un poco como en las películas de ciencia ficción, pero no me dio la sensación de estar acercándome a la velocidad de la luz como para producir tal efecto.

Agotadas mis ideas, hice lo que único que se me ocurrió: preguntar en stackoverflow. Aunque muchas veces busqué y encontré ahí respuestas muy interesantes a preguntas difíciles, es la primera vez que me registro para preguntar yo mismo (como comentario al margen, me sorprendió muy gratamente la mecánica del sitio). Después de varios días sin respuestas útiles, alguien sugirió que probara otros depuradores para comparar los tiempos y ver si tenían el mismo problema. Normalmente el otro depurador es el de Visual, pero sospechaba que ese sí hacía cosas "raras" en debug que podían tornar más lento un programa, así que estaba fuera de la discusión. Pero el lector sugirió OllyDbg, una herramienta excelente que usé alguna vez hace mucho para analizar a nivel assembler algunos exes de los que no tenía ni fuentes ni información de depuración. Yo ponía las manos en el fuego por que OllyDbg no iba a hacerle nada raro a mi exe. Mi gran sorpresa fue que al probarlo en OllyDbg también tardaba una eternidad, y exactamente la misma eternidad que en gdb.

Y entonces caí en la cuenta de que no era un problema de gdb, sino de Windows, ya que a varios depuradores les afectaba por igual. Esto me hizo volver a googlear pero ahora con diferentes criterios de búsqueda gracias a la nueva revelación, y en cinco minutos encontré la repuesta. Básicamente, cuando se corre en un depurador Windows, Windows instrumenta las funciones que manejan el heap del proceso depurado, agregando cosas como verificaciones de integridad, desactivando algunas optimizaciones, etc. Y ahí está la gran diferencia de tiempo. Los funciones de C++ que gestionan la memoria dinámica (como malloc y free, detrás de new y delete) descansan en funciones que provee el sistema (son como wrappers), y son estas las que Windows reemplaza al depurar. Digamos que cambia un dll por otro si el proceso se lanzó de cierta forma. Por suerte, este comportamiento especial se puede desactivar.

Cómo solucionar el problema en las distintas versiones de ZinjaI

La solución es tan simple como definir una variable de entorno: _NO_DEBUG_HEAP en 1. Y esto aplica para prácticamente cualquier depurador (incluyendo al del propio Visual Studio). Una vez definida la variable en 1, el programa corre en gdb en los mismos 8 segundos en los que lo hace fuera. Desde ZinjaI, actualmente lo pueden probar definiendo la variable en las opciones del proyecto, en el último campo de la pestaña General. Pero para la próxima versión lo hará solo siempre, y de forma transparente (ya que lo más normal es que no aprovechemos mucho lo que hace este heap especial). Y podrá desactivarse eventualmente desde las preferencias. Con este y muchos otros cambios, la depuración en ZinjaI va tomando otro color.

No hay comentarios:

Publicar un comentario