Rastrear usos intensivos de CPU en aplicaciones web

En este artículo vamos a presentar una estrategia para intentar localizar problemas en aplicaciones web que se traducen en usos intensivos de CPU.

La estrategia aquí presentada no es la única posible, pero yo la he utilizado con éxito.

Antes de comenzar

Antes de hacer nada de lo que se expone en este artículo, es necesario destacar que durante el periodo de análisis de la aplicación web se producen momentos de mucho ‘stress’ en el servidor de aplicaciones, con lo que es fundamental que todas estas pruebas se realicen en un entorno aislado en el que se haya podido reproducir el problema.

Además para facilitar la tarea es recomendable que el pool de aplicación asignado a la aplicación web esté dedicado únicamente a ella, ya que de lo contrario se puede generar un ruido innecesario.

Un punto fundamental antes de comenzar es que tenemos que haber conseguido previamente reproducir el problema; esto quiere decir que la manera más eficaz de realizar este tipo de análisis es siendo capaces de provocar el uso intensivo de CPU.

Requisitos

Para poder analizar la información necesaria para localizar el problema, necesitaremos una serie de herramientas (gratuitas) que necesitaremos instalar por un lado en el servidor web y por otro en el equipo donde realizaremos los análisis (si es distinto del servidor)

Herramienta	URL Descarga	Cliente / Servidor
Debug Diagnostic Tool 1.2	Enlace externo	Servidor
WinDbg	Enlace externo	Cliente
SOS.dll	Disponible en la carpeta del Framework 2.0	Cliente

La instalación de la herramienta de diagnóstico “Debug Diagnostic Tool 1.2” puede ser un poco “enrevesada” ya que tiene reconocidos problemas cuando se instala en un equipo que no esté en inglés. Para las instrucciones de instalación en este tipo de sistemas, podemos consultar el artículo correspondiente publicado hace un tiempo [acceso].

Captura de información

Lo primero que tenemos que hacer es capturar la información necesaria para realizar posteriores análisis e intentar determinar el origen de los problemas. Esta información se recoge en forma de “volcados” o “dumps” y se realizará en el servidor mediante la herramienta “Debug Diagnostic Tool 1.2”

Pasos para realizar el volcado correctamente:

1. Realizamos una llamada a la aplicación web para que se inicie el proceso ‘w3wp’ correspondiente, por si acaso.

2. Iniciamos sesión en el servidor.

3. Abrimos la consola de IIS, seleccionamos el servidor y hacemos doble clic en “Procesos de trabajo” en la sección de la derecha correspondiente a “IIS”

4. En la ventana que se abre aparecen todos los pools de aplicaciones que están activos, tendremos que apuntar el ID del proceso que nos interesa (el correspondiente al pool de aplicación de nuestra aplicación web)

5. Arrancamos la herramienta “Debug Diagnostic Tool” y cancelamos la ventana emergente que aparece.

6. Vamos a la pestaña “proceses” y localizamos el correspondiente al ID obtenido anteriormente.

7. Realizamos las operaciones necesarias en la aplicación web hasta conseguir que se dispare el uso de CPU

8. En el momento en el conseguimos el comportamiento incorrecto, tenemos que realizar un volcado de memoria mediante la herramienta de Debug. Para esto, hacemos clic con el botón derecho del ratón sobre el proceso y seleccionamos “Create full user dump”

9. Una vez finalizado el volcado, nos aparecerá el siguiente mensaje, indicando además en qué ubicación de disco se ha generado dicho volcado.

10. Listo, hemos generado el volcado correctamente

En ocasiones en función del grado de uso u ocupación del proceso, es posible que en lugar del mensaje de éxito nos aparezca un mensaje de que NO se ha podido generar el volcado. Esto suele suceder porque llegado un grado “X” de uso, el pool se recicla como parte de su configuración anti-errores. Para evitar que esto nos afecte, tendremos que cambiar ese comportamiento en la “Configuración avanzada” del pool de aplicación, la opción aparece destacada en la siguiente captura:

Si la protección rápida está habilitada y se produce el problema mencionado, bastará con deshabilitar esa opción de manera temporal.

Analizando la información

Una vez que hemos conseguido el volcado del proceso, llega el momento de analizarlo para intentar localizar los puntos de ‘conflicto’

Es necesario destacar que este proceso no es una ‘ciencia exacta’ por lo que tal vez no obtengamos información útil, pero al menos es una posibilidad muy a tener en cuenta.

El análisis de los volcados lo realizaremos con la herramienta “WinDbg”, pero antes tenemos que realizar una pequeña configuración:

1. Abrimos la carpeta del ‘Framework’ donde está la dll “SOS.dll” especificada en la tabla del punto 5.

2. Copiamos esa dll a la carpeta de instalación de “WinDbg”. Esta librería es necesaria porque proporciona información sobre el entorno interno del CLR.

3. En una carpeta del equipo donde realizaremos el análisis, creamos una carpeta “symcache” (será utilizada por el depurador para desargar los símbolos de los archivos PDB’s) en este documento se asume que la carpeta existe en la ruta c:\symcache

Para analizar el volcado, seguimos los siguientes pasos:

1. Arrancamos la herramienta WinDgb

2. Cargamos el archivo de volcado, mediante el menú “File”, “Open Crash Dump”

3. Una vez cargado el archivo, ejecutamos los siguientes comandos:

a. .symfix c:\symcache

b. .reload

c. .load sos

4. Obtenemos todos los procesos recogidos en el volcado con el comando !runaway, que nos dará un resultado como este:

En esta lista, ordenada por tiempo de CPU, podemos observar qué procesos están haciendo un mayor uso de la CPU. En la captura anterior, vemos que son los procesos con ids 27 y 23

5. Comprobamos que los hilos ‘sospechosos’ pertenecen a procesos de .Net, con el comando !threads:

La imagen se ve pequeñita, pero se confirma que uno de los hilos ‘sospechosos’ es un hilo ‘manejado’ por el CLR.
Además, podemos ver que uno de los hilos que aparecen está en un estado de “excepción”. Un vistazo de los dos hilos implicados, releva el estado de la ejecución:

a. Hilo 27: System.Threading.ThreadAbortException

b. Hilo 25: System.CannotUnloadAppDomainException

6. A continuación, ‘navegamos’ a los hilos con el comando ~27s y ~25s (el formato es ~[#hilo]s

7. En cada uno de ellos, obtenemos la pila de llamadas con el comando !clrstack. Con esta pila podemos intentar averiguar qué está pasando en la aplicación.

Como complemento al documento, se añaden las capturas de los hilos y la conclusión que nos han permitido obtener.

Detalle del hilo “27”

Detalle del hilo “25”

Conclusiones

Con la información que hemos obtenido, podemos determinar que la aplicación en cuestión ha intentado descargarse de memoria (System.AppDomain.Unload en el hilo 25) pero que existe un hilo (el 27) que está ocupando mucho tiempo de CPU al hacer:

Oracle.DataAccess.ClientOracleTuningAgent.DoScan().

En esta ocasión, podemos interpretar que existe algún problema con el Cliente Oracle. Una búsqueda en google nos da el siguiente enlace, que avala nuestra teoría [acceso].

Extracto de la página:

“This has been resolved. The fix is released in Oracle 11.2.0.1.2, which is available through the oracle.com website”