Visual Studio 2010 Profiling Tools–Solucionando problemas de rendimiento– Parte 4

Por: Nestor Guadarrama – Revisado por: Ivanov Cepeda

En el artículo anterior (Visual Studio 2010 Profiling Tools - Solucionando problemas de rendimiento - Parte 3), establecimos las principales características de perfilamiento asociadas al método de recolección de datos Concurrency y como este método permite además, realizar análisis de contención de recursos, incluyendo datos de uso del procesador (CPU Utilization), hilos de ejecución de procesamiento (Threads) y utilización individual de cada núcleo disponible del procesador para identificar potenciales problemas por cambios de contexto (Context Switches) realizados por la aplicación perfilada.

En esta última entrega, estaremos profundizando en el analizador de concurrencia, específicamente en el uso de Visual Studio Concurrency Visualizer SDK, para perfilar un proceso, incluyendo datos de traza sobre el perfilador, para que el perfil de la aplicación provea más contexto. Además, mostraremos como utilizar las utilidades VSPerfCmd y VSPerfASPNetCmd para realizar colección de datos en ambientes web de producción.

VISUAL STUDIO CONCURRENCY VISUALIZER SDK

Lo primero que debo dejar claro a los lectores es que el Visual Studio Concurrency Visualizer SDK, solamente está disponible en las versiones Premium y Ultimate de Visual Studio 2012. Utilizando el Visual Studio Concurrency Visualizer SDK, se puede instrumentar el código fuente de la aplicación para mostrar información adicional basada en la ejecución de rendimiento planificada con el método Concurrency. Se puede asociar información de contexto con fases y/o eventos dentro del código. Estas visualizaciones adicionales son denominadas markers. El SDK expone tres tipos de visualizaciones primitivas:

• Span
• Flag
• Message

Un span , representa un intervalo de tiempo en la aplicación, como por ejemplo una fase o ciclo. Un flag, representa un único punto en el tiempo (por ejemplo, cuando una variable u objeto alcanza cierto límite o cuando la aplicación arroja una excepción no controlada). Un message, también representa un punto único en el tiempo, pero este punto es una analogía visual (mensaje visual) a la técnica utilizada por un proceso de tipo traza de eventos (event-style-tracing).

Iniciamos el proceso de instalación del SDK desde el menú Analyze de Visual Studio 2012:

Figura 1. Agregando el Concurrency Visualizer SDK al proyecto de Visual Studio 2012 HRWeb.

En este instante, el SDK solicitará indicar a cual proyecto se desea agregar las referencias necesarias para poder instrumentar el código:

Figura 2. Selección del proyecto al cual se agregara el Concurrency Visualizer SDK

Una vez agregado el SDK al proyecto, podemos confirmar en las referencias del mismo que se incluyó la librería Microsoft.ConcurrencyVisualizer.Markers:

Figura 3. Librería Microsoft.ConcurrencyVisualizer.Markers, agregada como referencia en el proyecto HRWeb

Para iniciar el proceso de instrumentación del código, debemos agregar una referencia al namespace de la librería del SDK. Utilizare para tal fin la página Benefits.aspx.cs:

Figura 4. Referencia al namespace Microsoft.ConcurrencyVisualizer.Instrumentation

Como ya hemos identificado en los artículos anteriores, el método BuildParagraph() de la clase Benefits.aspx.cs, incluye una mala práctica en la concatenación de cadenas que eleva el consumo de procesamiento por parte del CPU y de la memoria del equipo:

Figura 5. Método BuildParagraph()

Originalmente cuando ejecuto este código y visualizo el resultado en el perfilador de concurrencia, puedo observar que efectivamente los threads asociados a la ejecución del proceso de concatenación están realizando un trabajo, pero no puedo identificar con claridad exactamente en qué fase o momento específico los threads ejecutan alguna sección en particular de código:

Figura 6. Threads de ejecución en concurrencia para la página Benefits.aspx.cs

Para demostrar el uso de los markers de tipo span, agregare las siguientes entradas al código, de forma tal de identificar en que sección específica, el thread toma el control de procesamiento en este método:

Figura 7. Inclusión de las sentencias Using(Markers.EnterSpan()) para identificar las entradas de la ejecución del proceso de perfilamiento

Al realizar la ejecución del proceso de perfilamiento, se puede observar en la vista Threads, la incorporación de información contextual sobre el hilo de ejecución que comentamos con el elemento span:

Figura 8. Se identifica en la vista Threads como el proceso Foreach() asociado a la concatenación, toma al menos 6 segundos en procesar todas las cadenas.

Al seleccionar la opción Markers, de la sección Visible Timeline Profile, se puede apreciar, para cada marcador, el tipo de marker, la importancia (prioridad) y el tiempo de duración de su ejecución:

Figura 9. Opción Markers, mostrando el tiempo de duración y la prioridad de cada sección instrumentada en el código.

Ahora, utilizaremos el marker de tipo flag. Siguiendo la misma lógica de instrumentación dentro del código, podemos demarcar específicamente un momento del tiempo. Esto es muy útil, por ejemplo, si la aplicación presenta un fallo, pero el tiempo de ejecución antes del fallo es muy corto, como para poder identificarlo. En nuestro código, insertaremos dos (2) flags para identificar el momento exacto en el que inicia la operación de Foreach() y el momento exacto en el que inicia el proceso de visualización de la página:

Figura 10. Adición de los markers de tipo flag al código para identificación de momentos de ejecución específicos

Se destaca en el código que he utilizado uno de los métodos alternativos que provee el objeto markers. Se trata del método WriteFlag() ,utilizando como primer parámetro un enumerador de tipo Importance de forma tal de destacar el nivel de importancia del marcador para efectos de visualización. El ejecutar el mecanismo de perfilamiento, se puede destacar los puntos de entrada de los marcadores flag en el hilo de ejecución:

Figura 11. Identificación del marker flag en la visualización de los threads de ejecución

Al seleccionar nuevamente la opción Markers, el visualizador mostrará todas las entradas, incluyendo las entradas de tipo flag y su importancia:

Figura 12. Visualización de los nuevos markers flag

Finalmente, utilizaremos el marker der tipo Message. Típicamente, en las aplicaciones que desarrollamos incorporamos alguna técnica de manejo de logging para identificar, en resultados posteriores a la ejecución. El marker de tipo Message, actúa como una especie de mensaje de log dentro de las aplicaciones, para permitirnos guardar algún mensaje en particular, dentro de la ejecución del código, que pueda ser perfilado cuando dicha sección sea procesada por el hilo de ejecución.

En nuestro ejemplo, uno de los aspectos que más nos ha llamado la atención durante el perfilamiento ha sido la cantidad de tiempo que toma el ciclo Foreach() en el proceso de concatenación, pero no conocemos cuanto tiempo toma cada iteración dentro del ciclo. Para conocer esta información, incluiremos una llamada a la función Stopwatch() , para determinar el intervalo de tiempo (en milisegundos) que cada iteración toma en procesarse:

Figura 13. Uso del método WriteMessage() del objeto Markers para agregar un mensaje al perfilador

Al procesar el perfilador, la opción Markers nos muestra la traza realizada por cada iteración del ciclo Foreach() :

Figura 14. Entradas del mensaje incluido dentro del ciclo Foreach() , para cada concatenación

Uno de los aspectos interesantes a resaltar, es que a medida que el ciclo Foreach() , itera en la concatenación, los tiempos de ejecución se incrementan de manera significativa (en algunos puntos hasta 100 veces):

Figura 15. Tiempos de ejecución e incremento por iteración dentro del ciclo Foreach()

Como introducción, esta etapa básica de perfilamiento con el método Concurrency puede ser de gran utilidad para brindarles asistencia en la comprensión de problemas de rendimiento en las aplicaciones. Los invito a que le den una mirada al blog del equipo de desarrollo paralelo de Visual Studio, para mayor información sobre este tema.

UTILIDAD VsPerfCmd PARA COLECTAR INFORMACION DE PERFILAMIENTO

Para colectar la información relacionada con los hilos de ejecución e información del uso del procesador por parte de la aplicación, utilizaremos la utilidad VSPerfCmd. Esta utilidad es usada para iniciar y detener la ejecución de colección de información en la perfilación de un proceso. La utilidad VSPerfCmd es una característica sumamente poderosa, dado que permite obtener datos adicionales del proceso de perfilamiento, en ambientes donde, normalmente, no se instalaría Visual Studio para realizar este tipo de procesos (por ejemplo, ambientes de Producción).

En ambientes ASP.NET, típicamente se podría utilizar la utilidad VSPerfASPNetCmd (de la cual hablaremos más adelante). Esta utilidad, a diferencia de VSPerfCmd, no requiere crear variables de sesión o reinicio del servidor. Sin embargo, VSPerfASPNetCmd no provee mecanismos (método de inicio) para colectar data utilizando el mecanismo de concurrencia descrito en este artículo.

Una vez realizada la instalación y configuración Stand-Alone en el servidor web donde se desea perfilar la aplicación, procedemos a realizar el procedimiento de inicio del perfilador, a través de una ventana de comando (abrir la ventana de comando con permisos de administración) como se indica a continuación:

Visual Studio 2010

VSPerfCmd/start:concurrency,resourceonly /output:OutputFile [Options]

donde:

• /start inicializa el perfilador para colectar la data de contención de recursos.
• /output:OutputFile es requerido cuando se utiliza la opción /start. Especifica el nombre y localización de la data de perfilamiento (archivo .vsp)
• [Options] Indica las diferentes opciones que pueden utilizarse para especificar acciones adicionales (colección adicional de datos) a través del perfilador:
  • /user:[Domain\]UserName Especifica el dominio y el usuario de la cuenta que puede ser utilizada para poder iniciar el perfilador (permisos de acceso)
  • /crosssession Habilita el perfilador para colectar data utilizando otras sesiones de usuario.
  • /wincounter:WinCounterPath Especifica contadores de rendimiento de Windows (Performance Counters) que pueden ser colectados durante la sesión de perfilamiento.
  • /automark:Interval Solo puede ser utilizado si se indica la opción /wincounter. Se utiliza para indicar la frecuencia (en milisegundos) entre cada colección de información de los contadores indicados. Por defecto es 500 milisegundos.
  • /events:Config Especifica los eventos de tracing de Windows (Event Tracing for Windows o ETW) que serán colectados durante el perfilamiento. Esta data es colectada en un archivo adicional (extensión .etl).

Como comente al inicio de este artículo, Visual Studio 2010 posee una limitante relacionada con la captura de información sobre hilos de ejecución dentro del proceso o información sobre el uso del procesador por parte de la aplicación. Esta condición se evidencia en el comando anteriormente descrito, dado que al inicializar el perfilador, la única opción posible para colocar en el inicio del mecanismo es resourceonly. En Visual Studio 2012, dicha limitación no existe:

Visual Studio 2012

VSPerfCmd/start:concurrency /output:OutputFile [Options]

Para el objetivo de esta sección, utilizare la versión Visual Studio 2012, dado que es la que refleja fielmente la información de procesamiento de hilos de ejecución y consumo de procesamiento. Observe que estoy ejecutando la versión de 64 bits de la utilidad VSPerfCmd. Además, utilizare la opción /crosssession, dado que el proceso W3WP.exe al cual adheriremos el perfilador, se ejecuta con la identidad del application pool creado para la aplicación:

Figura 16. Ventana de comando con la ejecución de la utilidad VSPerfCmd

Seguidamente, iniciamos la aplicación, instalada en este caso en un servidor IIS 7.5. El Administrador de Tareas (Task Manager), nos mostrara un nuevo proceso W3WP.exe, asociado al application pool que creamos para dicha aplicación:

Figura 17. Proceso W3WP.exe asociado a la aplicación HRWeb

Ahora, adherimos al proceso W3WP.exe (en nuestro caso el proceso con el identificador 17388) nuestro perfilador, utilizando el siguiente comando:

VSPerfCmd/attach:PID [/target:Version]

donde:

• /attach:PID indica el número de identificación del proceso que se perfilara.
• /target:Version indica la versión del .NET Framework que se utilizara para el proceso de perfilamiento

Figura 18. Adhesión del perfilador al proceso 17388 satisfactorio

Seguidamente, se inicia el proceso de colección de datos por parte del perfilador, indicando que se inicie la colección del proceso y de las variables asociadas al mismo. Para esto, utilizaremos los comandos vsperfcmd /globalon y vsperfcmd /processon:PID (en nuestro caso, 17388). Se realizan las pruebas para la reproducción del escenario de error o rendimiento que se intenta validar. Una vez terminado el proceso reproducción del error se procederá a realizar el cierre de la sesión de perfilamiento.

Figura 19. Comandos de inicio de colección de variables

Para culminar la sesión de perfilamiento, el perfilador no debe estar colectando información. Puede detener la colección de datos cuando se reinicia el proceso W3WP.exe asociado al application pool de la aplicación (un proceso de reciclado), o invocando al comando vsperfcmd /detach:

Figura 20. Liberación del perfilador del proceso 17388

Finalmente, se descarga el perfilador de memoria utilizando el comando vsperfcmd /shutdown,y se inicia el proceso de análisis:

Figura 21. Cierre de la sesión de perfilamiento exitoso

Validamos que se haya creado efectivamente el archivo de perfilamiento en la ruta indicada:

Figura 22. Archivo de perfilamiento creado.

Ahora, desde la interfaz de Visual Studio, abrimos el archivo hrweb.vsp para analizar la data de perfilamiento colectada por la utilidad VsPerfCmd:

Figura 23. Muestra sumaria del archivo hrweb.vsp con la data colectada por la utilidad VsPerfCmd

Efectivamente, la utilidad colectó de manera eficiente la información relacionada con el perfilamiento de la aplicación para realizar el análisis correspondiente:

Figura 24. Muestra de datos colectados por la utilidad VsPerfCmd

UTILIDAD VSPerfASPNetCmd PARA COLECTAR INFORMACION DE PERFILAMIENTO

La utilidad VSPerfASPNetCmd, es una utilidad de características reducidas (si la comparamos con VsPerfCmd), dado que no permite colectar datos de perfilamiento de concurrencia. Solo permite colectar muestras de tipo Sampling, Trace, Memory y TIP (Tier Interaction Profile). No obstante la utilidad VSPerfASPNetCmd es la más recomendada cuando se utiliza el Stand-Alone Profiler en ambientes de producción dado que es la menos intrusiva de ambas. La sintaxis a utilizar por la utilidad se muestra a continuación:

Visual Studio 2010 / 2012

Vsperfaspnetcmd [/Options] Website

donde [/Options] indica las diferentes opciones que pueden utilizarse para especificar acciones adicionales (colección adicional de datos) a través del perfilador:

• /Sample o /s: Perfila un website usando el método Sampling. Es el método por defecto. No puede ser utilizado en combinación con /Trace.
• /Trace o /t: Perfila un website usando el método Instrumentation. No puede ser utilizado en combinación con /Sample.
• /Memory[:type] o /m[:{a|l}]: Perfila las cargas de datos en memoria (allocations) y opcionalmente perfila el tiempo de vida de los objetos (garbage collection). Type puede ser alguno de los siguientes valores:
  • Allocation o a, colecta información de la data cargada en memoria
  • Lifetime o l, colecta información del tiempo de vida de los objetos cargados en memoria
• /Tip o /t: Agrega información detallada de los requerimientos ASP.NET y ADO.NET a la colección realizada por el perfilador.
• /Output:file o /o:file: Especifica la ruta y el nombre del archivo de perfilamiento (.vsp).
• /NoWait o /n: Retorna a la ventana de comando inmediatamente, así la ventana de comando puede ser utilizada nuevamente para nuevos comandos. Si se utiliza esta opción, en una nueva ventana de comando deberá utilizarse la opción VSPerfASPNETCmd /Shutdown para inhabilitar el perfilador.
• /PackSymbols[:{on|off}] o /p[:{on|off}]: Incluye símbolos de depuración y perfilamiento específicos para la traza a colectar (funciones, nombres de parámetros, etc.) en el archivo de perfilamiento (.vsp)
• /Shutdown:website o /d:website: El url del website a ser analizado.

Para el ejemplo de esta sección, utilizaremos la opción /Memory. Inicialmente, abrimos una ventana de comandos con permisos de Administrator y ejecutamos la instrucción vsperfaspnetcmd /memory websiteUrl:

Figura 25. Ejecución de la utilidad VSPerfASPNETCmd

Al terminar de realizar las pruebas y reproducción del inconveniente, la ventana de comandos ofrece la opción de pulsar la tecla “Enter” para detener el proceso de perfilamiento. Al realizar este paso, la utilidad iniciará la carga de símbolos de depuración y la generación de los reportes asociados a las opciones que se indicaron en la línea de comando:

Figura 26. Proceso de carga de símbolos y generación de reportes

Una de las principales diferencias que notaran en la generación del archivo, es el tamaño del mismo. En comparación con la utilidad VsPerfCmd, el tamaño generado por la utilidad VsPerfASPNETCmd es mucho más grande, dado que contiene toda la información incluida de los símbolos y contadores asociados. Una vez abierto el archivo .vsp desde Visual Studio, obtenemos información, en nuestro caso, relacionada con el consumo y utilización de la memoria por parte de la aplicación:

Figura 27. Resumen de las colocaciones de datos en memoria por parte de los objetos de tipo System.String en la aplicación.

Un punto de interés en la vista de análisis de memoria realizado, es la sección Allocation. Esta vista muestra que tamaño real de memoria utiliza específicamente que objeto definido por el CLR y las funciones donde dichos objetos son creados y utilizados:

Figura 28. Detalle del consumo de memoria por objeto de la vista Allocation

Como pueden deducir en este punto, la utilidad VsPerfASPNETCmd ofrece prácticamente la misma información de perfilamiento que las demás técnicas mostradas durante los artículos de esta serie. Sin embargo, lo que hace atractiva a esta utilidad, es su capacidad de poder ser instalada en ambientes de producción de manera stand-alone y lo poco intrusiva que se presenta, en comparación con la utilidad VsPerfCmd.

Con esto terminamos esta seria de cuatro (4) artículos sobre las bondades que Visual Studio ofrece para el perfilamiento de aplicaciones web. Sin embargo, esto solo es el comienzo, en próximas entregas, analizaremos otras técnicas de colección y perfilamiento de aplicaciones en ambientes de producción, asi como técnicas de depuración y resolución de problemas.

Estamos en contacto!