Identificar qué es «lento» con PerfView y dotnet-trace — introducción práctica a la investigación de rendimiento en .NET

En el artículo anterior, «Introducción a los registros de eventos de Windows y ETW», tratamos qué es ETW y cómo definir eventos propios con EventSource, dejando el análisis con PerfView «fuera de alcance». Este artículo continúa desde ahí. Trata el procedimiento para llegar, con PerfView y dotnet-trace, hasta la función causante cuando una aplicación de negocio «va lenta», «mantiene la CPU al máximo» o «se congela de vez en cuando».

Este artículo se centra en la investigación de CPU y tiempo de respuesta. La discriminación de problemas de memoria que crece continuamente se trata en «Cómo distinguir la espera del GC de una fuga de memoria en .NET», y los problemas de bloqueo (crash) en «Leer volcados de memoria con WinDbg + SOS».

1. Antes que nada, la conclusión

• Existen dos tipos de «lentitud»: la que agota la CPU (CPU bound) y la que espera bloqueada con la CPU ociosa. La primera requiere muestreo de CPU y la segunda, recolección de ThreadTime (cambios de contexto); ni siquiera la recolección de CPU por defecto muestra la causa de la segunda.¹
• En caso de duda, empiece por dotnet-trace. Es una herramienta multiplataforma basada en EventPipe que puede recolectar sin privilegios de administrador siempre que sea el mismo usuario que inició el proceso objetivo.² El .nettrace recolectado se puede abrir con PerfView o Visual Studio.³
• PerfView es necesario cuando hay que ver toda la máquina, código nativo o tiempo bloqueado. Al estar basado en ETW, también puede manejar eventos del kernel y pilas de código nativo. A cambio, iniciar una sesión ETW requiere privilegios de administrador.³
• El muestreo de CPU es, por defecto, cada 1 milisegundo (por procesador). Léalo como que 1 muestra equivale a aproximadamente 1 ms de tiempo de CPU, y como referencia, juzgue una vez reunidas 1.000 muestras o más (idealmente unas 5.000). Con pocas muestras, las funciones que aparecen arriba pueden deberse al azar.¹
• La interpretación de los números parte siempre de distinguir inclusive (uno mismo + los destinos llamados) de exclusive (uno mismo). Una función con exclusive alto es «el lugar que realmente consume CPU»; una función con inclusive alto es «un lugar donde algo por debajo es pesado».
• Antes de medir, fije en qué operación concreta consiste esa «lentitud». Recolectar mientras todo va «pesado en general» no se puede leer. Recolecte después de fijar la operación y el tiempo, como en «esta salida de informe tarda 40 segundos». Para la idea de medición comparativa antes/después de una mejora, también sirve de referencia «Cómo comparar correctamente la velocidad entre versiones de un programa en Windows».

Resumimos en una tabla de referencia por dónde empezar según el síntoma.

2. Ordenar la relación entre las herramientas — ETW y EventPipe

Aunque parecen aparecer muchas herramientas, la base es solo dos.

• ETW (Event Tracing for Windows): infraestructura de trazado que atraviesa todo el sistema operativo. Permite registrar desde el kernel hasta la aplicación en el mismo eje temporal, pero iniciar y detener una sesión requiere privilegios de administrador, y es exclusivo de Windows.³
• EventPipe: mecanismo de trazado integrado en el runtime de .NET. No requiere privilegios de administrador y funciona igual en todos los sistemas operativos, pero a cambio solo ve código administrado y el runtime; no obtiene eventos del kernel ni pilas nativas.²

Con esta correspondencia clara en mente, resulta natural decidir el reparto: «primero recolectar ligero con dotnet-trace; si no basta, recolectar con ETW mediante PerfView».

3. Antes de recolectar — observe la tendencia 10 minutos con dotnet-counters

En lugar de recolectar una traza de inmediato, muchas veces es más rápido observar primero las métricas principales del runtime con dotnet-counters.⁴

dotnet tool install --global dotnet-counters
dotnet-counters ps
dotnet-counters monitor --process-id <PID> --counters System.Runtime

Aquí se observan el uso de CPU, el tamaño del montón de GC y el número de GC, la longitud de cola y el número de hilos de ThreadPool, y el número de excepciones. Si en este punto aparecen tendencias como «el GC se ejecuta varias veces por segundo» o «la cola de ThreadPool sigue creciendo», se puede acotar qué tipo de traza recolectar a continuación (asignaciones o bloqueo).

Aun así, quien mide por primera vez no sabe si «ese número es anómalo». El criterio más fiable es el valor obtenido ejecutando el mismo comando con su propia aplicación en condiciones normales. Como referencia para quien todavía no dispone de ese valor, resumimos la interpretación que usamos en la práctica.⁵

Lo importante no es el umbral en sí, sino cómo se comporta el valor con el tiempo. Un valor que sube y baja con la carga y se estabiliza es sano; un valor que no vuelve a bajar aunque se detenga la carga es el que hay que investigar. La forma de leer las tendencias de memoria se explica en detalle en el artículo sobre cómo distinguir la espera del GC de una fuga de memoria.

4. Recolectar una traza con dotnet-trace

dotnet-trace es una herramienta de recolección basada en EventPipe.⁶ La instalación y la recolección básica son las siguientes.

dotnet tool install --global dotnet-trace
dotnet-trace ps
dotnet-trace collect --process-id <PID> --duration 00:00:00:30

Si no se especifica ninguna opción, se recolecta con la configuración de perfil por defecto, que incluye los eventos principales del runtime y el muestreo de hilos. El perfil que antes existía con el nombre cpu-sampling se ha retirado, y actualmente la combinación por defecto es dotnet-common y dotnet-sampled-thread-time.⁶ Según el uso, también se puede elegir --profile gc-verbose (muestreo de GC y asignaciones de objetos) o --profile gc-collect (registra solo la ocurrencia de GC, con poca carga).

Para recolectar junto con el proveedor propio de EventSource creado en el artículo anterior, añada --providers.

dotnet-trace collect --process-id <PID> --providers KomuraSoft-OrderService

El resultado de la recolección es un archivo .nettrace. Hay tres formas de abrirlo: con Visual Studio, con PerfView, o convirtiéndolo a formato speedscope para verlo en el navegador.⁶

dotnet-trace convert trace.nettrace --format Speedscope

El formato speedscope es una vista de gráfico de llamas ligera que se abre en speedscope.app, adecuada para observar de forma intuitiva «bajo qué función se gastó el tiempo».

Decidir con cuál abrirlo resulta sencillo si se piensa a quién se le va a mostrar el resultado.

Es decir, PerfView es para investigar y speedscope para compartir. El análisis detallado hasta identificar el nombre de la función es más potente con el visor de pilas de PerfView, así que pasamos al siguiente capítulo.

5. Investigar la CPU con PerfView — cómo leer el visor de pilas

PerfView es una herramienta de investigación de rendimiento publicada gratuitamente por Microsoft; funciona con solo descargar el ejecutable PerfView.exe desde la página de versiones de GitHub (no requiere instalación).⁷

5.1 Recolectar

El flujo para recolectar con la GUI, detallando incluso qué tocar en la pantalla, es el siguiente.

1. Ejecute PerfView.exe como administrador (iniciar una sesión ETW requiere privilegios de administrador³)
2. Elija Collect > Collect en el menú (el atajo es Alt+C). Se abre el cuadro de diálogo de recolección, que pide el nombre del archivo de datos a crear¹
3. Decida qué recolectar con el grupo de casillas del cuadro de diálogo. Con la configuración por defecto se recolectan muestras de CPU y los eventos principales del CLR. Si también quiere investigar el tiempo de espera, active aquí la casilla Thread Time (capítulo 6)¹
4. Pulse el botón Start Collection
5. Reproduzca la operación que quiere investigar (esto es lo que se está midiendo, así que no intercale operaciones innecesarias)
6. Pulse el botón Stop Collection. Tras detener la recolección se ejecutan la fusión de datos y la resolución de símbolos, y se crea el archivo .etl.zip con el nombre indicado en el paso 2

Hacer lo mismo por línea de comandos toma esta forma (también hay que ejecutarlo como administrador³).

PerfView collect /nogui /acceptEULA /maxCollectSec:30

La recolección por defecto incluye muestras de CPU cada 1 milisegundo en todos los procesadores (con pila de llamadas) y los eventos principales del CLR.¹ La sobrecarga durante la recolección con la configuración por defecto se sitúa en general en torno a unos pocos puntos porcentuales.⁸

5.2 Leer CPU Stacks

Al abrir el resultado de la recolección (.etl.zip) y elegir el proceso objetivo en «CPU Stacks», se abre el visor de pilas.

A primera vista hay muchos elementos en pantalla, así que primero conviene tener claro qué hay dónde. El visor de pilas se divide, a grandes rasgos, en «los campos de filtro de la parte superior» y «la cuadrícula con pestañas de la parte inferior».

Lo primero que hay que mirar son dos columnas de la pestaña ByName.

• Exc (exclusive): número de muestras en las que esa función misma estaba en ejecución. Es el lugar que realmente consume CPU.
• Inc (inclusive): suma del número de muestras de esa función y de todo lo que llamó desde ella. Indica que algo por debajo de ese punto es pesado.

El patrón de lectura consiste en mirar desde arriba en Exc y clasificar «si es código propio o del runtime/biblioteca». Si el código propio aparece arriba en Exc, el algoritmo o el bucle de esa función es el objetivo directo. Si lo que aparece arriba en Exc es de la familia System.String o un serializador JSON, hay que recorrerlo por Inc en la pestaña Callers para averiguar desde qué parte del código propio se está llamando en gran volumen.

Otro punto importante es confirmar el propio número de muestras. Como el muestreo de CPU es una estadística con intervalo de 1 ms, con pocas muestras el resultado depende del azar. Como referencia, juzgue una vez reunido un total de 1.000 muestras o más, idealmente unas 5.000, y si no son suficientes, repita la operación objetivo para alargar el tiempo de recolección.¹

Además, si los nombres de función de sus propios módulos aparecen como direcciones, es que los símbolos (PDB) no se han podido resolver. Tener a mano los PDB de los artefactos de compilación es, en sí mismo, lo que hace posible investigar. Este tema se explica en detalle en «Qué es un PDB (base de datos de programa)».

6. «La CPU está ociosa pero va lenta» — ver el tiempo bloqueado con ThreadTime

Más de la mitad de la «lentitud» en la práctica no es CPU, sino espera: espera de bloqueo, espera de respuesta de BD o HTTP, E/S de archivos, espera casi de interbloqueo por Task.Result. Este tipo de problema no aparece en las muestras de CPU, porque es «tiempo en el que directamente no se usa CPU», así que la recolección por defecto no muestra la causa.

En PerfView, si al recolectar se activa la opción Thread Time, se registran además los eventos de cambio de contexto, y se puede seguir, para cada hilo, tanto el «tiempo que usó CPU» como el «tiempo que estuvo bloqueado».¹

Hay dos formas de activarlo, por GUI y por línea de comandos, y el resultado es el mismo en ambos casos.

• Con la GUI: al abrir el cuadro de diálogo de Collect > Collect (Alt+C) del paso 2 de 5.1, active la casilla Thread Time antes de pulsar Start Collection. La guía oficial también indica claramente que «si quiere investigar el tiempo de reloj de pared, hay que configurar la casilla Thread Time del cuadro de diálogo de recolección».¹ Pasar esto por alto y recolectar con la configuración por defecto, para luego preguntarse «por qué no aparece el tiempo bloqueado», es el primer tropiezo habitual.
• Por línea de comandos: añada el interruptor /threadTime.

PerfView collect /nogui /acceptEULA /threadTime /maxCollectSec:30

En el análisis se abre la vista «Thread Time Stacks». Es el mismo visor de pilas que CPU Stacks, pero la diferencia es que las muestras incluyen, además del tiempo de CPU, BLOCKED_TIME (tiempo que estuvo bloqueado). Si se acota al rango de tiempo de la operación lenta y se observa en qué pila (qué espera) se acumula el BLOCKED_TIME del hilo que llevaba el procesamiento, se obtiene un desglose del tipo «de los 40 segundos totales, 35 fueron esperando esta llamada HTTP».

Los síntomas del tipo «la interfaz se congela» (al operar, no responde durante varios segundos) son, casi siempre, en realidad un bloqueo del hilo de interfaz. Tras identificar con ThreadTime dónde se bloquea el hilo de interfaz, como medida permanente hay que llevar el diseño hacia hacer asíncrona la espera síncrona. Para ordenar este aspecto del diseño, consulte «Async y el subproceso de interfaz en WPF/WinForms explicados en una sola página».

Como aviso, la recolección de ThreadTime registra un evento por cada cambio de contexto, por lo que el volumen de datos aumenta claramente respecto a la recolección por defecto. Limite el tiempo de recolección y evite recolecciones largas en producción.

7. Combinarlo con EventSource — acotar «qué tramo es lento» con el vocabulario del negocio

Tanto CPU Stacks como Thread Time son agregados de todo el proceso. Cuando se quiere acotar por unidad de proceso de negocio, como «qué parte dentro de un pedido concreto es lenta», entran en juego los eventos Start/Stop de EventSource tratados en el artículo anterior.

Para que este capítulo se pueda probar por sí solo, aunque no haya leído el artículo anterior, dejamos aquí un código mínimo para crear usted mismo el proveedor a seguir. El --providers KomuraSoft-OrderService del capítulo 4 se refiere a este Name.

using System.Diagnostics.Tracing;

// El [EventSource(Name = ...)] es el nombre de proveedor visible desde ETW/EventPipe
[EventSource(Name = "KomuraSoft-OrderService")]
public sealed class OrderServiceEventSource : EventSource
{
    public static readonly OrderServiceEventSource Log = new OrderServiceEventSource();

    [Event(1, Level = EventLevel.Informational)]
    public void OrderProcessingStart(string orderId) => WriteEvent(1, orderId);

    [Event(2, Level = EventLevel.Informational)]
    public void OrderProcessingStop(string orderId) => WriteEvent(2, orderId);
}

En el lado que llama, basta con envolver el tramo que se quiere medir.

OrderServiceEventSource.Log.OrderProcessingStart(orderId);
try
{
    ProcessOrder(orderId); // El proceso de negocio que se quiere medir
}
finally
{
    OrderServiceEventSource.Log.OrderProcessingStop(orderId);
}

Si alinea los nombres de método como ~Start / ~Stop y numera los ID de evento de forma consecutiva, resulta más fácil leerlos como un par de tramos en la vista Events de PerfView. Emitir siempre el Stop en finally es para que una ejecución que salió por una excepción no quede como un «tramo que nunca termina». Los detalles de cómo definir eventos (restricciones de tipo de los argumentos, cómo distinguir EventLevel y Keywords) se explican en el artículo anterior.

Dando por hecha esta instrumentación, la investigación avanza en el siguiente orden.

• Instrumentar en la aplicación eventos como OrderProcessingStart / OrderProcessingStop (el código anterior)
• Confirmar en la vista «Events» de PerfView la hora de ese evento y acotar el rango de tiempo del visor de pilas (filtros Start/End) a ese tramo
• Leer el desglose de CPU o tiempo bloqueado dentro del rango acotado

De este modo se puede analizar solo «esa vez concreta que fue lenta», sin que quede sepultado bajo el ruido de las condiciones normales. Los eventos propios también se pueden recolectar de la misma manera con dotnet-trace, así que, una vez añadida la instrumentación, el mismo método de investigación sirve tanto en la máquina de desarrollo como en producción. En la práctica, la dificultad de una investigación de rendimiento depende menos de la pericia con las herramientas que de si «existen puntos de observación en el lado de la aplicación».

Resumen

• El punto de partida es separar la «lentitud» entre CPU bound y bloqueo. La primera solo se ve con muestreo de CPU (1 muestra ≈ 1 ms); la segunda, solo con la recolección de ThreadTime.
• La base es usar primero dotnet-trace, que no requiere privilegios de administrador, y recurrir a PerfView cuando hace falta ver toda la máquina, código nativo o tiempo bloqueado. También es habitual combinar ambos: recolectar .nettrace y leerlo con PerfView.
• En el visor de pilas, el núcleo de la lectura es distinguir exclusive de inclusive, comprobando siempre si el número de muestras es suficiente.
• Preparar eventos propios de EventSource que acoten el tramo del proceso de negocio eleva un nivel la precisión de la investigación.

En KomuraSoft LLC atendemos la investigación de problemas de rendimiento en aplicaciones de negocio de Windows —«va lenta», «se congela», «la CPU se satura»— y la consulta sobre instrumentación y diseño para facilitar la medición. Si dispone del procedimiento de reproducción y del archivo de traza, también es posible encargar solo el análisis a partir de ahí.

Artículos relacionados

• Introducción a los registros de eventos de Windows y ETW — cómo llevar los registros de una aplicación de negocio al mecanismo estándar del sistema operativo
• Cómo distinguir la espera del GC de una fuga de memoria en .NET — procedimiento práctico para observar, comparar y demostrar el crecimiento de memoria
• Leer volcados de memoria con WinDbg + SOS — introducción práctica al análisis después de la recolección
• Introducción a la recolección de volcados de memoria en Windows: WER/ProcDump/WinDbg
• Qué es un PDB (base de datos de programa) — comprender la información de depuración, los símbolos y Source Link
• Cómo comparar correctamente la velocidad entre versiones de un programa en Windows
• Async y el subproceso de interfaz en WPF/WinForms explicados en una sola página

Áreas de consultoría relacionadas

• Investigación de fallos y análisis de causas
• Desarrollo de aplicaciones Windows
• Consultoría técnica y revisión de diseño
• Contacto

Referencias

Artículos relacionados

Artículos recientes con las mismas etiquetas para profundizar en temas cercanos.

Temas relacionados

Estas páginas sitúan el tema en un contexto más amplio de servicios y decisiones.

Servicios relacionados con este tema

El artículo está directamente relacionado con los siguientes servicios.

Preguntas frecuentes

Preguntas habituales en las consultas sobre el tema del artículo.

¿Debo usar PerfView o dotnet-trace?

Recomendamos probar primero dotnet-trace. Puede usarse sin privilegios de administrador, recoger datos solo del proceso objetivo y la operación se resuelve en una línea de comando. En cambio, si necesita ver pilas de código nativo, la situación de toda la máquina —influencia de otros procesos o del kernel— o seguir el tiempo bloqueado por cambio de contexto, hace falta PerfView basado en ETW. También es habitual recoger un archivo .nettrace y abrirlo después con PerfView para analizarlo.

¿Cómo se relaciona con el generador de perfiles de Visual Studio?

Si el problema se reproduce en una máquina de desarrollo, las herramientas de uso de CPU y memoria de Visual Studio son más sencillas y normalmente bastan para empezar. PerfView y dotnet-trace son útiles al recoger datos en equipos de prueba o producción donde no se puede instalar Visual Studio, al separar recogida y análisis en equipos distintos o al necesitar eventos ETW, incluidos EventSource propios y eventos del kernel. Visual Studio también puede abrir los archivos .nettrace producidos por dotnet-trace.

¿Es seguro ejecutarlo en un servidor de producción?

Ambas herramientas están pensadas para recogidas breves en producción, pero no sin condiciones. Limite la duración a decenas de segundos o unos minutos, pruebe primero el mismo comando en un entorno de validación para comprobar la sobrecarga y el tamaño del archivo, y confirme el espacio libre en disco. En especial, la recogida ThreadTime —cambios de contexto— y las trazas de asignación producen muchos eventos y el archivo crece rápido. Además, una traza puede contener información como argumentos de línea de comandos, por lo que hay que manejar los archivos recogidos con cuidado.

¿Cómo se reparten con WPR/WPA?

WPR (Windows Performance Recorder) y WPA (Windows Performance Analyzer) son herramientas de investigación más orientadas al sistema operativo y basadas en el mismo ETW. Para análisis detallado de toda la máquina, como E/S de disco, energía o tiempo de arranque, WPR/WPA es fuerte; para investigar CPU, GC y tiempo bloqueado de una aplicación .NET, PerfView suele ser más legible porque su presentación está optimizada para código administrado. Si el objetivo es una aplicación de negocio, PerfView y dotnet-trace cubren la mayor parte de los casos.

Perfil del autor

Página de presentación del autor del artículo.

Go Komura

Representante de KomuraSoft LLC

Especializado en desarrollo de software para Windows, consultoría técnica e investigación de fallos, sobre todo en proyectos con sistemas existentes y errores difíciles de reproducir.