.Rendimiento de NET

Diagnóstico de rendimiento de aplicaciones .NET mediante ETW

Subramanian Ramaswamy

Descargar el ejemplo de código

Escribe una aplicación administrada y lo pone a prueba... y es lenta. Su aplicación, funcionalmente, es correcta, pero su rendimiento deja mucho que desear. Desearía diagnosticar los problemas de rendimiento y resolverlos, pero su aplicación está ejecutándose en un entorno de producción, de manera que no puede instalar generadores de perfiles ni interrumpirla. O quizás su aplicación no es usada tan ampliamente como para que se justifique la compra de Visual Studio Profiler para creación de perfiles de CPU.

Por suerte, el Seguimiento de eventos para Windows (ETW) puede mitigar estos problemas. Esta poderosa tecnología de registro está integrada en muchas partes de la infraestructura de Windows y saca provecho de Microsoft .NET Framework 4 CLR para simplificar como nunca antes la creación de perfiles de sus aplicaciones administradas. ETW recopila datos de sistema amplio y genera perfiles para todos los recursos (CPU, disco, red y memoria), lo cual lo vuelve extraordinariamente útil para obtener una vista integral. Lo que es más, el ecosistema de ETW se puede ajustar de manera que sea de baja sobrecarga, haciéndolo adecuado para diagnósticos de producción.

El objetivo de este artículo es darle una idea de las fortalezas obtenibles al usar ETW para crear perfiles de su aplicación administrada. No cubriré todo, existen varios eventos de SO y eventos ETW de CLR disponibles para diagnóstico a los cuales ni siquiera les daremos un vistazo. Pero, obtendrá una perspectiva de como mejorar el rendimiento y funcionalidad de sus aplicaciones administradas significativamente usando el ecosistema de ETW. Para empezar el diagnóstico basado en ETW de su código administrado, mostraré una investigación simple, usando PerfMonitor, una herramienta de ETW disponible de forma gratuita que se puede descargar desde bcl.codeplex.com/releases/view/49601.

PerfMonitor

PerfMonitor permite recopilar rápida y fácilmente datos de rendimiento de ETW y generar informes útiles. No pretende reemplazar a las herramientas de análisis profundo, como el generador de perfiles de Visual Studio, sino que presentar información general de las características de rendimiento de una aplicación y realizar análisis rápidos.

Existe otra herramienta para diagnóstico de ETW llamado XPerf, la cual está disponible de forma gratuita por medio del Kit de herramientas de rendimiento de Windows. Sin embargo, mientras XPerf es muy útil para creación de perfiles de código nativo de Windows, aún no cuenta con compatibilidad completa para creación de perfiles de código administrado. PerfMonitor, por otra parte, demuestra el alcance y las capacidades de la creación de perfiles de código administrado al usar ETW. PerfMonitor cuenta con la capacidad de reunir información simbólica asociada al código de ejecución de .NET Framework, haciéndolo valioso para investigaciones de rendimiento de .NET Framework, aunque no es compatible con el análisis en profundidad que XPerf puede proporcionar. 

PerfMonitor es una herramienta totalmente autónoma y es todo lo que necesita para empezar a crear perfiles y diagnosticar a su aplicación administrada. El único requisito adicional es que debe ejecutarse de Windows Vista o Windows Server 2008 en adelante. PerfMonitor es una herramienta de línea de comando, al escribir PerfMonitor.exe usersGuide desde su ubicación le mostrará una introducción. Si cuenta con un cliente cuyo programa desea diagnosticar bajo condiciones operativas; como, por ejemplo, para un servidor de producción; todo lo que necesita es copiar el archivo a esa máquina y estará listo para empezar la recopilación de perfiles. Los perfiles se pueden analizar sin conexión, de ser necesario.

Generalmente se examinan cuatro factores durante cualquier investigación de rendimiento: CPU, E/S de disco, memoria y escalabilidad. La mayor parte de las investigaciones comienzan desde la CPU, la cual afecta tanto el inicio como el tiempo de ejecución de la aplicación. Examinar la E/S del disco es sumamente útil al diagnosticar tiempos de inicio prolongados (la E/S del disco es un factor significativo para el tiempo de inicio en frío, es decir, el tiempo que toma en iniciarse una aplicación cuando no está presente en la memoria, como después de un reinicio), donde el consumo excesivo (o fuga) de memoria puede hacer que sus aplicaciones se pongan más lentas a medida que pasa el tiempo. La escalabilidad es importante si desea que su aplicación alcance una capacidad de proceso proporcional al número de procesadores.

PerfMonitor ayuda a obtener una visión general rápida de todos estos, salvo de escalabilidad, y también proporciona suficiente información para profundizar usando otras herramientas especializadas. Por ejemplo, para diagnosticar problemas del montón de la recolección de elementos no usados (CG) de CLR .NET, CLRProfiler es más útil. Sin embargo, PerfMonitor informa rápidamente si existe un problema y si es necesario profundizar usando otras herramientas. En algunos casos, PerfMonitor señala el problema por si mismo y contiene toda la información que necesita para enfrentar un error de rendimiento, como verá en breve. De un vistazo a la columna Todo sobre CLR “Auditoría de uso de memoria para aplicaciones .NET” (msdn.microsoft.com/magazine/dd882521), en donde se analiza la importancia de realizar una auditoría a los programas para uso y planificación de memoria para un buen rendimiento. Al extender esta filosofía, PerfMonitor permite auditar rápidamente muchos aspectos de rendimiento del programa administrado, no sólo memoria.

Un ejemplo de investigación: CsvToXml

El programa de ejemplo que diagnosticaré usando ETW convierte un archivo CSV a un XML. El código fuente, junto con el paquete de solución (y un archivo CSV de ejemplo de entrada, data.csv) está disponible en code.msdn.microsoft.com/mag201012ETW. Para ejecutar el programa, ejecute el comando CsvToXml.exe data.csv output.xml.

Como muchos programas, CsvToXml se armó apresuradamente y el desarrollador no anticipó que sería usado con archivos CSV grandes. Cuando empecé a usarlo en el mundo real, sentí que era muy lento. ¡Le tomó más de 15 segundos procesar un archivo de 750k! Sabía que existía un problema, pero sin una herramienta de creación de perfiles, terminaría tratando de adivinar la razón de esa lentitud (¿puede identificarla sólo mirando la fuente?). Por suerte, PerfMonitor puede ayudar a descubrirlo.

Generar y ver la traza de programa

El primer paso es hacer una auditoría rápida de la aplicación al ejecutar el siguiente comando en una ventana de símbolo de sistema de administrador (ETW recopila datos de toda la máquina, por lo tanto requiere privilegios de administrador):

PerfMonitor runAnalyze CsvToXml.exe data.csv out.xml

Esto iniciará el registro de ETW, iniciará CsvToXml.exe, esperará a que CsvToXml se complete, terminará el registro y, finalmente, abrirá una página web que muestra el análisis de CsvToXml. En un sencillo paso, se cuenta con una amplia gama de datos que ayudarán a descubrir los cuellos de botella de rendimiento en CsvToXml.

El resultado de este comando está capturado en la figura 1. La página contiene, entre otros datos, el identificador de proceso, la línea de comando usada y un desglose de alto nivel de datos de rendimiento, lo que incluye estadísticas de CPU, de GC y estadísticas just-in-time (JIT). PerfMonitor también proporciona un análisis de primer nivel sobre donde empezar el diagnóstico, con vínculos útiles a artículos informativos u otras herramientas.

Figura 1 Análisis de rendimiento de CsvToXml

El informe muestra que la conversión de formato tomó casi 14 segundos, de los cuales 13,6 ocurrieron en la CPU con una utilización promedio de 99 por ciento. Por lo tanto, el escenario está relacionado con la CPU.

El tiempo total en GC y los tiempos de pausa de GC son bajos, lo que es bueno. Sin embargo, la tasa de asignación máxima para GC es de 105,1 MB/seg, lo que es excesivo. Esto exige una investigación más profunda.

Análisis de CPU

El análisis detallado de CPU proporciona un desglose del tiempo de CPU, como se indica en la figura 2, y existen tres maneras de leer datos de perfil de CPU. La vista ascendente indica rápidamente los métodos que están consumiendo la mayor parte del tiempo de CPU, que deben ser los primeros en ser diagnosticados. La vista descendente es útil para descubrir si el código exige cambios estructurales o de arquitectura y ayuda a entender el rendimiento general del programa. La vista autor-destinatario indica la relación entre métodos; por ejemplo, cual método llama a cual. 

Figura 2 Análisis ascendente de CsvToXml.exe

Tal como otros creadores de perfiles de CPU, las vistas de PerfMonitor proporcionan el tiempo inclusivo (el tiempo invertido en un método específico, lo que incluye el tiempo invertido en los destinatarios) y el tiempo exclusivo (el tiempo invertido en un método específico, lo que excluye destinatarios). Cuando los tiempos inclusivos y exclusivos son iguales, ese método en específico está listo. PerfMonitor también proporciona un gráfico de utilización de CPU que desglosa el uso de CPU a lo largo del tiempo por un método específico. Al mantener el mouse sobre los encabezados de columna del informe se proporcionan más detalles acerca de su significado.

La mayor parte de las investigaciones de rendimiento comienzan con una vista ascendente, la cual es una lista de métodos según su tiempo exclusivo (esta vista se puede ver en la figura 2). Una vez seleccionada la vista ascendente, se puede ver que el método mscorlib System.IO.File.OpenText es el que consume la mayor parte de la CPU. Al hacer clic en este vínculo aparece la vista de autor-destinatario del método OpenText, la cual revela que el método CsvToXml.CsvFile.get_ColumnNames está invocando a OpenText desde el programa y que get_ColumnNames está consumiendo casi 10 segundos de tiempo de CPU (figura 3). Lo que es más, este método es llamado desde CsvToXml.CsvFile.XmlElementForRow desde un bucle (el mismo XmlElementForRow es llamado desde el método Main).

Figura 3 Vista autor/destinatario de get_ColumnNames

Por lo tanto, algo parece estar funcionando mal en estos métodos. Extraer el código de estos métodos conduce al problema, el cual está destacado en la figura 4: ¡el archivo se abre y analiza varias veces, generando un bucle!

Figura 4 El método XmlElementForRow invoca al método ColumnNames

public string[] ColumnNames
{
  get
  {
    using (var reader = File.OpenText(Filename))
      return Parse(reader.ReadLine());
  }
}

public string XmlElementForRow(string elementName, string[] row)
{
  string ret = "<" + elementName;
  for (int i = 0; i < row.Length; i++)
    ret += " " + ToValidXmlName(ColumnNames[i]) + "=\"" + EscapeXml(row[i]) + "\"";
  ret += "/>";
  return ret;
}

Esta clase de escenarios ocurren más frecuentemente de lo que cree. Cuando se escribió el método, puede que el desarrollador haya supuesto que se invocaría en escasas ocasiones (como ocurre con ColumnNames), por lo que no le haya prestado mucha atención al rendimiento. Sin embargo, frecuentemente ocurre que situaciones posteriores terminan llamando al método y estableciendo un bucle, lo que tiene impacto en el rendimiento de la aplicación.

En un archivo CSV, todas las filas tienen el mismo formato, de manera que no hay razón para hacer esto en cada ocasión. Se puede elevar la funcionalidad de ColumnNames en el constructor, como se puede apreciar en la figura 5, y dejar que la propiedad proporcione los nombres de columna en la memoria caché. Esto asegura que el archivo sea de sólo lectura.

Figura 5 Almacenamiento en memoria caché de los nombres de columna para un mejor rendimiento

public CsvFile(string csvFileName)
{
  Filename = csvFileName;

    using (var reader = File.OpenText(Filename))
      ColumnNames = Parse(reader.ReadLine());
        
}

public string Filename { get; private set; }

public string[] ColumnNames { get; private set;}

Después de la reconstrucción, al ejecutar el comando anterior nuevamente descubriremos que la aplicación es mucho más ágil, con una duración de sólo 2,5 segundos.

Sin embargo, al revisar los datos ajustados, notará que el más largo sigue siendo el tiempo de CPU. Al revisar nuevamente el tiempo de CPU y al mirar el análisis ascendente, notará que Regex.Replace es ahora el método con mayor consumo, el cual es llamado por EscapeXml y ToValidXmlName. Dado que EscapeXml es el método de mayor consumo (330 ms de tiempo exclusivo, revisemos su código fuente:

private static string EscapeXml(string str)
{
  str = Regex.Replace(str, "\"", "&quote;");
  str = Regex.Replace(str, "<", "&lt;");
  str = Regex.Replace(str, ">", "&gt;");
  str = Regex.Replace(str, "&", "&amp;");
  return str;
}

También se llama a EscapeXml desde un bucle en XmlElementForRow, lo que lo hace propenso a ser un cuello de botella. Las expresiones regulares son más bien excesivas para estos reemplazos, sería más eficaz usar un método Replace de cadena. Por lo tanto, reemplace EscapeXml con lo siguiente:

private static string EscapeXml(string str)
{
  str = str.Replace("\"", "&quote;");
  str = str.Replace("<", "&lt;");
  str = str.Replace(">", "&gt;");
  str = str.Replace("&", "&amp;");
  return str;
}

Con esta transformación, habrá reducido el tiempo general a aproximadamente dos segundos, manteniendo la predominancia del tiempo de CPU. Éste es un rendimiento aceptable. Se ha hecho casi siete veces mejor el tiempo de ejecución.

Como un ejercicio para el lector, dejé unos cuantos errores adicionales en el programa de muestra, de manera que pueda identificarlos usando los eventos de ETW.

Explorar las estadísticas de CG

Las estadísticas GC de PerfMonitor proporcionan una visión general rápida del perfil de memoria. Como recordará, recomiendo encarecidamente auditar el uso de memoria, además, la información proporcionada por los eventos ETW de GC entrega una instantánea rápida de cualquier problema en el montón de GC .NET. El resumen rápido indica el tamaño de montón de GC agregado, las tasas de asignación y los tiempos de pausa de GC. Al seleccionar el vínculo Análisis de tiempo de GC de la ficha de resultados de PerfMonitor se mostrarán los detalles de los GC, cuándo ocurrieron, cuánto tiempo consumieron, etc.

La información permite determinar si es necesario profundizar en algún problema de memoria usando CLRProfiler u otros creadores de perfiles de memoria. El artículo “Perfilar montones del recolector de elementos no usados de .NET” (msdn.microsoft.com/magazine/ee309515) profundiza en la depuración de montones de GC .NET usando CLRProfiler.

Para este programa en específico, ninguna de las estadísticas de GC parece ser preocupantes. La tasa de asignación es alta. Una buena norma general es mantener la tasa de asignación por debajo de los 10 MB/s. Sin embargo, los tiempos de pausa son muy breves. Las tasas de asignación altas están comprendidas por el tiempo de CPU, lo que significa principalmente que se puede mejorar la capacidad de CPU, como ya ha descubierto. Sin embargo, después de los ajustes, las tasas de asignación siguen siendo altas, lo que significa que están ocurriendo muchas asignaciones (¿puede usted arreglar esto?). El tiempo de pausa de GC de unos cuantos milisegundos es evidencia de la eficiencia y capacidades de autoajuste del GC proporcionado por el tiempo de ejecución de .NET Framework. Por lo tanto, la GC de .NET se hace cargo automáticamente de la administración de memoria.

Explorar las estadísticas de JIT

Para mejorar el tiempo de inicio, uno de los primeros elementos a revisar es el tiempo necesario para la compilación JIT de métodos. Si el tiempo que se toma es significativo (por ejemplo, la mayor parte del tiempo usado en el inicio de la aplicación es consumido por la compilación JIT), la aplicación puede verse beneficiada por generación de imágenes nativas (NGen), la cual elimina tiempo de compilación de JIT al compilar previamente el ensamblado y al guardarlo en el disco. Es decir, el ensamblado pasa por compilación JIT y se guarda en el disco, lo que elimina la necesidad de compilaciones JIT para próximas ejecuciones. Antes de continuar por la ruta NGen, puede querer considerar aplazar algunos de los métodos que pasan por compilación JIT posteriormente en el programa, de manera que la compilación JIT no afecte el inicio. Para obtener más información, consulte el artículo “Los beneficios de rendimiento de NGen” (msdn.microsoft.com/magazine/cc163610).

La aplicación de ejemplo CsvToXml.exe no tiene un costo de inicio significativo y permitir una compilación JIT de todos los métodos en cada ocasión está bien. Las estadísticas de compilación JIT también indican que el número de métodos que pasaron por compilación JIT fueron 17 (lo que sugiere que se hizo compilación JIT de todos los métodos) y que el tiempo total de compilación JIT fue de 23 ms. Ninguno de estos es un problema de rendimiento para la aplicación, pero para aplicaciones mayores, donde el tiempo de compilación JIT es un factor a considerar, usar NGen debiera eliminar cualquier problema. Por lo general, el tiempo de compilación JIT se vuelve un factor a considerar cuando una aplicación empieza a realizar compilación JIT a cientos o miles de métodos. En esos casos, NGen es la solución para eliminar costos de compilación JIT.

Hay más orientación para mejorar el inicio disponible en otros artículos de MSDN Magazine, y los eventos ETW pueden ayudar a identificar y resolver cuellos de botella. Muchos otros eventos JIT también están disponibles, lo que incluye eventos en línea que pueden proporcionar perspectivas acerca de las razones por las que un método no está en línea.

Eventos ETW de CLR en .NET Framework 4

El equipo de CLR escribió una publicación de blog sobre el seguimiento de cargas de DLL y sobre como determinar si un DLL específico se debe cargar durante el inicio. El proceso de determinar si debe hacerse una carga de DLL durante el inicio se facilita con los eventos de ETW. Al usar los eventos de carga de módulo de ETW disponibles en .NET Framework 4, se puede determinar cuales módulos están cargados y por qué. También hay eventos para descarga de módulos, etc.

Hay varios otros eventos en .NET Framework 4 que hacen más fácil que nunca el diagnóstico de aplicaciones administradas. La figura 6 resume estos eventos. Todos los eventos activados durante la ejecución pueden descargarse con el comando PerfMonitor runPrint. El equipo de CLR también ha revisado eventos que permiten adjuntar y separar la creación de perfiles de ETW y el equipo planea agregar más eventos de ETW para facilitar el proceso de depuración de aplicaciones administradas en futuros lanzamientos.

Figura 6 Eventos de ETW en .NET Framework 4

Nombre de categoría de evento	Descripción
Evento ETW de información de tiempo de ejecución	Captura información acerca de tiempo de ejecución, lo que incluye la SKU, número de versión, la manera de activar el tiempo de ejecución, los parámetros de línea de comando con los que se inició, el GUID (si está disponible) y otra información relevante.
Evento ETW de excepción	Captura información de excepciones.
Eventos ETW de contención	Captura información acerca de contención para bloqueos de monitor o nativos que use el tiempo de ejecución.
Evento ETW de grupo de subprocesos	Captura información acerca de fuentes de subprocesos de trabajo y de E/S.
Eventos de ETW de cargador	Captura información acerca de carga y descarga de dominios, ensamblados y módulos de aplicación.
Eventos de ETW de método	Captura información acerca de métodos CLR para resolución de símbolo.
Eventos de ETW de GC	Captura información pertinente a GC.
ETW de eventos de seguimiento JIT	Captura información acerca de inclusión en línea JIT y llamados de cola.
Eventos de ETW de interoperabilidad	Captura información sobre generación de código auxiliar y almacenamiento en memoria caché del lenguaje intermedio de Microsoft (MSIL).
Eventos de ETW de supervisión de recursos de dominio de aplicaciones (ARM)	Captura información diagnóstica detallada sobre el estado de un dominio de aplicación.
Eventos de ETW de seguridad	Captura información sobre verificación de nombres seguros y Authenticode.
Evento de ETW de pila	Captura información usada en otros eventos para generar seguimiento de pilas después que se generó un evento.

Encontrará dos archivos con el sufijo PerfMonitorOutput en el directorio de ejecución, estos son los archivos de registro de ETW. También verá archivos con el kernel sufijo, lo que implica que contienen los eventos del SO. Los datos recopilados por PerfMonitor son los mismos datos usados por XPerf, de manera que puede usar PerfMonitor para simplificar la recolección de datos y realizar informes simples, mientras usa XPerf para análisis más avanzados sobre los mismos datos. El comando merge de PerfMonitor convierte los archivos ETW a un formato compatible con XPerf.

Conclusión

La investigación de rendimiento por medio de ETW es simple, pero efectiva. Existen muchas herramientas basadas en ETW gratuitas y de baja sobrecarga disponibles que permiten la depuración de código administrado de forma efectiva. Sólo hice una mirada superficial de los eventos ETW disponibles en el tiempo de ejecución de .NET Framework. Mi objetivo era la introducción a la depuración de una aplicación administrada usando eventos y herramientas de ETW. Al descargar PerfMonitor y usar la documentación de MSDN sobre eventos ETW en CLR, en conjunto con el blog CLR Perf Blog, potenciará sus investigaciones de rendimiento sobre aplicaciones administradas.

Agradecimientos especiales a Vance Morrison, socio arquitecto de CLR Performance, por su orientación y asistencia en la creación de este artículo.

Subramanian Ramaswamy es el administrador de programas de CLR Performance en Microsoft. Él posee el grado académico de Ph.D. en Ingeniería eléctrica e informática del Georgia Institute of Technology.