Visual Studio 2010 Profiling Tools –Solucionando problemas de Rendimiento – Parte 3
Por Nestor Guadarrama
En los artículos anteriores (Visual Studio 2010 Profiling Tools - Solucionando problemas de rendimiento - Parte 1 y Visual Studio 2010 Profiling Tools - Solucionando problemas de rendimiento - Parte 2), mostramos distintas alternativas para configurar las herramientas de perfilamiento de Visual Studio y obtener información relacionada con el desempeño de las funciones, variables y tiempos de cada llamada realizada en una aplicación web.
En esta nueva entrega, mostraremos la información brindada por el método de recolección de datos Concurrency. Este método colecta información detallada sobre la pila de llamadas cada vez que hilos de ejecución (threads) que están compitiendo por ser atendidos son forzados a esperar para tener acceso a recursos compartidos. Además, las visualizaciones ofrecidas por el método Concurrency, colectan información general acerca de cómo las aplicaciones multi-hilos interactúan entre ellas, el hardware, el sistema operativo y con otros procesos dentro del computador huésped.
El método Concurrency colecta dos (2) tipos de información de concurrencia:
- Data sobre contención de recursos por cada evento de sincronización que cause que una función perfilada deba esperar por el recurso que desea acceder.
- Data sobre los hilos de ejecución de procesos (threads) que incluye uso del procesador, contención de hilos de ejecución, migración de hilos de ejecución, demoras en sincronización, áreas de solapamiento de I/O y otros eventos del sistema.
Con base en la descripción anterior, es importante hacer notar que, dada la naturaleza de la aplicación que se desarrolló para esta serie de artículos (aplicación web), de los dos tipos de información que el perfilador nos permite capturar, solamente en esta sesión podríamos colectar información sobre contención de recursos, dado que para las aplicaciones web, el perfilador no puede capturar información sobre multi-hilos de ejecución (en la versión 2012 de Visual Studio, esta limitante fue removida).
Lo primero que notaremos es que cuando intentamos acceder a Visual Studio 2010, la IDE nos mostrara el siguiente mensaje:
Figura 1. Mensaje de Visual Studio 2010, indicando que no puede perfilar aplicaciones ASP .NET para multi-hilos.
Esta condición, puede ser cambiada en la ventana de propiedades del reporte Concurrency, tal y como se muestra a continuación:
Figura 2. Al deshabilitar la opción Visualize the behavior of a multithreaded application, le indicamos al perfilador que no intente colectar información sobre el comportamiento de los hilos de ejecución de la aplicación web
Para este artículo, utilizaremos el asistente de rendimiento (Performance Wizard), ubicado en la ventana Performance Explorer:
Figura 3. Performance Explorer
Al iniciar el asistente de rendimiento, seleccionaremos la opción Concurrency. Esta sección contiene dos (2) opciones a seleccionar: a) Collect resource contention data y b) Visualize the behavior of a multithreaded application. Como describimos inicialmente, en esta etapa no seleccionaremos la segunda opción, dado que Visual Studio 2010 no permitirá avanzar con el análisis de rendimiento:
Figura 4. Ventana del Asistente de Rendimiento
Una vez completados los pasos del asistente, el perfilador iniciara automáticamente la aplicación a perfilar (en nuestro caso la aplicación web HRWeb). Al terminar de realizar las funciones de navegación, el motor de análisis mostrara los resultados del reporte de perfilamiento de contención para recursos:
Figura 5. Pantalla inicial del Concurrency Profiling Report
Lo primero que destaca de este reporte versus los reportes analizados de los otros mecanismos de perfilamiento es el hecho de que no presenta una sección de tipo HotPath. A cambio, el reporte presenta la sección Most Contended Threads. Esta sección presenta un resumen de los hilos de ejecución de procesos que han presentado mayor cantidad de escenarios de contención.
Por definición, contención ocurre cuando un hilo de ejecución (thread) trata de acceder a un área de memoria que es compartida por todos los hilos pertenecientes al mismo proceso. Para evitar problemas de concurrencia usualmente el hilo utilizará un mecanismo que bloqueará cualquier otro hilo de ejecución que requiera modificar dicha área. Si el área de memoria que se desea acceder, ya se encuentra bloqueada por otro hilo, se genera una contención ya que el hilo que está intentando acceder deberá esperar a que el bloqueo sea liberado, para adquirir o realizar un bloqueo al espacio de memoria que intenta acceder. [NG1] Así que, en resumen, mientras menos procesos de contención posean nuestra aplicación, mejor para el rendimiento.
Figura 6. Sección Most Contended Threads del reporte Concurrency Profiling Report
Un punto a discutir acerca de este reporte es que el mismo utiliza como criterio de selección la cantidad de transacciones de contención establecidas por un hilo de ejecución, no la longitud (en tiempo) de la contención. Así, si un thread ha estado bloqueando el acceso a un recurso por largo tiempo, pero solamente una vez, este reporte no mostrara dicho inconveniente. Solamente mostrara aquellos threads que han repetido la misma operación de contención de manera simétrica una cantidad “n” de veces.
Al examinar detenidamente el reporte, encontramos dos (2) aspectos interesantes:
- De los handlers que la aplicación crea para manejar los recursos, el handle 1, ejecuta la mayor cantidad de contenciones
- Dos (2) threads en particular están causando contención en el procesamiento de la aplicación.
Evaluemos que están haciendo dichos threads. Al seleccionar los números de threads (en nuestro caso 11232 y 8672 respectivamente), se navega hasta la sección Thread Details, donde se muestra el detalle de cada operación ejecutada por dicho thread:
Figura 7. Sección Thread Details con el detalle del thread 11232
Al seleccionar este segmento, en la sección inferior de la vista, Visual Studio mostrara la pila de llamada de la ejecución del trhead en dicho momento. Esta información es de suma utilidad, dado que desde esta vista, podemos navegar directamente a la sección de código que causa el síntoma de contención descrito por el perfilador. En nuestro caso, la llamada a la carga de datos incluida en el método LoadPersonal() , de la capa DAL (Entitty Framework):
Figura 8. Vista de código que causa contención en el proceso.
Esta llamada, ejecuta una invocación síncrona a la clase DALMethods.cs, ubicada en el proyecto de tipo Entity Framework HRDAL. En esta clase, el Entity Framework permite retornar una lista de un dato de tipo complejo (Complex Type) denominado uspEmployees, que recupera todos los registros de algunos campos para la tabla HumanResources.Employee:
Figura 9. Dato de tipo complejo uspEmployees, definido en la capa DAL.
CONCURRENCY PROFILER EN VISUAL STUDIO 2012
En el momento que inicie la escritura de esta serie de artículos, estaba próxima la salida al mercado de la más reciente versión de Visual Studio (2012). No quise dejar pasar la oportunidad de probar las herramientas de perfilamiento, desde la nueva interfaz y…un momento….la opción Concurrency había cambiado!!!. Así que pensé, “…este es un buen momento para escribir acerca de dichos cambios para que los lectores estén precavidos…”, así que aquí vamos.
Una de los modificaciones que detectaremos en la nueva interfaz de desarrollo Visual Studio 2012, es que el perfilamiento de las aplicaciones utilizando el método de recolección de datos Concurrency es que, si invocan al perfilamiento de la manera tradicional (Performance Wizard, Menu “Analyze” -> “Start Performance Analyze”), el reporte que generará la aplicación es muy similar al reporte creado por el método de colección CPU sampling). Esto es porque con la nueva versión, la forma correcta de invocar al método de colección es a través del menú “Analyze -> Concurrency Visualizer”:
Figura 10. Nueva opción Concurrency Visualizer en Visual Studio 2012
Como habíamos indicado al inicio de este artículo, en la versión anterior de Visual Studio (2010), el proceso de perfilamiento no permite realizar colección de datos de concurrencia en procesos web, dado que el visualizador de multi-hilos de ASP .NET no permite adjuntar un proceso único (como el caso del perfilador de concurrencia), a múltiples hilos hospedados por un solo proceso. Al intentar realizar esta operación en Visual Studio 2012, la interfaz indica que la operación no puede iniciar con un proyecto de este tipo (proyecto web). Sin embargo, la interfaz permite adjuntar el perfilador a un proceso externo:
Figura 11. Mensaje de advertencia de Visual Studio 2012 para indicar que debe adjuntarse el perfilador a un proceso existente
Para poder adjuntar el perfilador de concurrencia al proceso, se hace necesario instalar la aplicación en un entorno Internet Information Server, de manera tal que podamos perfilar el proceso W3WP.exe asociado al application pool que hospeda la aplicación. Una vez realizado este proceso, procedemos a ejecutar la aplicación (ya sea a través de Visual Studio, desde la consola de administración de Internet Information Server o desde el navegador web, accediendo a la página deseada). En nuestro caso, el servicio W3WP iniciado es:
Figura 12. Proceso W3Wp asociado al application pool HRWebAppPool
Una vez iniciado el proceso, indicamos a Visual Studio que deseamos adjuntar el perfilador de concurrencia a dicho proceso:
Figura 13. Adjuntando el perfilador de concurrencia al proceso
Figura 14. Seleccionando el proceso W3WP asociado al application pool HRWebAppPool
En este momento, se inicia el proceso de reproducción del inconveniente o navegación del sitio para identificar problemas de rendimiento. Una vez culminada la reproducción del inconveniente, se indica en la interfaz de Visual Studio 2012 la detención del perfilamiento. La interfaz no mostrará un reporte inicial como el siguiente:
Figura 15. Interfaz inicial del perfilador de concurrencia y contención en Visual Studio 2012
La primera visualización que nos otorga el pefilador es acerca de la utilización del procesador (CPU Utilization). En esta vista, podemos identificar algunos componentes claves sobre el tiempo de uso del proceso que estamos perfilando, así como el patrón de ejecución que el proceso perfilado posee en la ejecución dentro de los procesadores lógicos de la maquina donde realicemos las pruebas.
La segunda visualización se denomina Threads. Muestra toda la información colectada sobre la ejecución detallada de cada hilo de ejecución en el espacio del tiempo que la aplicación se ejecutó. Esta vista es sumamente poderosa y donde invertirán más tiempo analizando el comportamiento de la aplicación, dado que permite observar la pila de la llamada de cada ejecución dentro del proceso. Además, permite seleccionar (Zoom In / Zoom Out), sobre espacios de procesamiento, y seleccionar específicas secciones de ejecución de memoria para identificar potenciales problemas de contención en las llamadas realizadas (tiempo de ejecución de una llamada, recurso que se intenta acceder, mutex del sistema operativo, esperas (Wait) de un hilo por un recurso compartido, etc.):
Figura 16. Interfaz Threads, mostrando los diferentes hilos de ejecución y los stacks asociados a dicho threads en el tiempo
La tercera interfaz se denomina Cores e identifica como el proceso perfilado se comportó en su ejecución en los distintos procesadores de la maquina donde se realizan las pruebas. Unos de los aspectos importantes a resaltar en esta vista es que permite visualizar cuantos Context Switches, realizó cada hilo de ejecución. Uno de los aspectos de rendimiento a evaluar en una aplicación es cuantos switches realiza entre los núcleos lógicos de los procesadores del sistema, dado que este proceso garantizar el multi –procesamiento, pero es un proceso costoso que impacta el rendimiento:
Figura 17. Interfaz Cores, con la información del contexto para cada núcleo lógico y cada thread del proceso W3WP asociado al application pool HRWebAppPool
Retomando nuestro análisis de rendimiento, lo primero que observamos es que la aplicación consume bastas cantidades de uso del procesador por alguna acción en particular:
Figura 18. Evidencia de alto consumo de procesador
Para determinar que funciones pueden estar produciendo dicho comportamiento, se hace necesario acudir a la interfaz Threads e investigar que hilos de ejecución están tomando más tiempo en procesamiento. Al hacer el análisis de los threads, resulta interesante que más del 80% de uso del procesador se halla invertido en procesos de sincronización. Para hacer un análisis detallado de una sección específica de tiempo (digamos rangos de 8 ms cada bloque), se utiliza la sección de Zoom indicada en la parte superior de la interfaz. Al detallar esta sección y compararla con otras secciones del proceso (e incluso con otros hilos), se identifica que el patrón de comportamiento plantea que el código está llamando a procesos de copia y concatenación de cadenas cada vez:
Figura 19. Análisis de hilos de ejecución para el proceso W3WP.exe asociado al application pool HRWebAppPool
Incluso, uno de los aspectos de mayor importancia es el hecho de que cada ejecución de esta operación, está solicitando que el Garbage Collector relame más memoria para poder continuar la operación. Esta es la causa principal del alto consumo de procesador (High CPU) del proceso:
Figura 20. Indicación que el GC está reclamando más memoria para poder continuar la operación.
Al detallar el proceso, se identifica que la causa principal de este comportamiento, radica en la llamada a un método de concatenación de cadenas para crear una tabla HTML, que no sigue las prácticas adecuadas:
Figura 21. Sección del código que muestra la mala práctica en concatenación de cadenas.
Esto es todo por el momento. En la entrega final, utilizaremos el Visual Studio Concurrency SDK, para perfilar un proceso, incluyendo datos de traza sobre el perfilador, para que el perfil de la aplicación provea más contexto y demás, utilizaremos las utilidades VSPerfCmd y VSPerfASPNetCmd para realizar colección de datos en ambientes web de producción.