Ejemplo 15: medición del tiempo de DPC/ISR
Puede medir la cantidad de tiempo que dedica un controlador en llamadas a procedimientos diferidos (DPC) e interrumpir rutinas de servicio (ISR) mediante el seguimiento de estos eventos en el kernel de Windows. Esta información le ayudará a minimizar el tiempo que el controlador pasa en IRQL más altos, lo que hace que el controlador y el sistema sean más eficientes.
Microsoft recomienda que las DPC no se ejecuten durante más de 100 microsegundos y las ISR no deben ejecutarse durante más de 25 microsegundos. Para conocer los requisitos más recientes, consulte Kit de laboratorio de hardware.
El procedimiento que se describe en esta sección incluye los pasos siguientes:
Iniciar el seguimiento del kernel de eventos DPC/ISR.
Supervisar la sesión de seguimiento de los eventos perdidos y, si es necesario, aumentar el tamaño de los búferes de seguimiento.
Utilizar el controlador de prueba.
Detener la sesión de seguimiento.
Usar Tracerpt para generar un informe que resuma la actividad de DPC/ISR.
Analizar los informes
Paso 1: Iniciar una sesión de seguimiento.
El comando siguiente inicia una sesión de seguimiento del registrador de kernel NT:
tracelog -start -f test01.etl -dpcisr -UsePerfCounter -b 64
El comando tracelog -start inicia la sesión de seguimiento. Dado que "NT Kernel Logger" es el nombre de sesión predeterminado, no es necesario especificarlo y no puede usar el parámetro -guid para especificar un archivo de proveedor. El comando usa el parámetro -f para indicar una sesión de registro y dirigir los mensajes de seguimiento al archivo de registro de seguimiento de eventos test01.etl.
El comando incluye el parámetro -dpcisr para habilitar el seguimiento de DPC, ISR, modificadores de contexto y carga de imágenes.
Al realizar el seguimiento de DPC e ISR, agregue siempre el parámetro -UsePerfCounter al comando. La resolución del temporizador del sistema es demasiado baja para medir el tiempo invertido en estas actividades. Además, Tracerpt, la herramienta que da formato a los eventos DPC/ISR, requiere los valores del reloj del contador de rendimiento para sus informes. (Tracerpt se incluye en Windows XP y versiones posteriores de Windows).
Por último, el comando usa el parámetro -b para aumentar el tamaño de los búferes de seguimiento a 64 KB. Dado que el seguimiento de DPC/ISR genera un gran volumen de mensajes de seguimiento a una velocidad rápida, es importante aumentar el tamaño de los búferes de seguimiento para que no pierda eventos.
En respuesta a este comando, Tracelog inicia la sesión del registrador de kernel NT y muestra sus propiedades.
Logger Started...
Operation Status: 0L The operation completed successfully.
Logger Name: NT Kernel Logger
Logger Id: ffff
Logger Thread Id: 00000C18
Buffer Size: 64 Kb
Maximum Buffers: 25
Minimum Buffers: 3
Number of Buffers: 5
Free Buffers: 4
Buffers Written: 14
Events Lost: 0
Log Buffers Lost: 0
Real Time Buffers Lost: 0
AgeLimit: 15
Log File Mode: Sequential
Enabled tracing: Process Thread Disk File ImageLoad
Log Filename: c:\Tracelog\test01.etl
Tenga en cuenta que los eventos de DPC, ISR y modificador de contexto no aparecen en el campo Seguimiento habilitado de la pantalla. Dado que estos eventos se supervisan mediante instrumentación interna, no aparecen en esta lista incluso cuando están habilitados. Sin embargo, los eventos de carga de imágenes, que también están habilitados por el parámetro -dpcisr, sí aparecen.
Paso 2: Comprobar si hay eventos perdidos.
Use un comando tracelog -q (consulta) periódicamente para comprobar si hay eventos perdidos. Si los hay, use un comando tracelog -update para agregar más búferes a la sesión de seguimiento.
tracelog -q
El comando tracelog -q toma un nombre de sesión, pero no es necesario proporcionar uno en este caso porque "NT Kernel Logger" es el valor predeterminado.
En respuesta a este comando, Tracelog muestra las propiedades de la sesión.
Operation Status: 0L The operation completed successfully.
Logger Name: NT Kernel Logger
Logger Id: ffff
Logger Thread Id: 00000BC4
Buffer Size: 64 Kb
Maximum Buffers: 25
Minimum Buffers: 3
Number of Buffers: 25
Free Buffers: 23
Buffers Written: 571
Events Lost: 544
Log Buffers Lost: 0
Real Time Buffers Lost: 0
AgeLimit: 15
Log File Mode: Sequential
Enabled tracing: Process Thread Disk File ImageLoad
Log Filename: c:\Tracelog\test.etl
En este caso, 544 eventos que se generaron no se guardaron en un búfer. Para evitar que esto sea recurrente, use un comando tracelog -update para aumentar el tamaño de cada búfer (-b) o para aumentar el número máximo de búferes (-max), por ejemplo:
tracelog -update -b 128 -max 40
Paso 3: Utilizar el controlador.
Use las rutinas de prueba para que el controlador realice sus funciones. Considere la posibilidad de ejecutar dos pruebas, una para funciones básicas y otra para funciones más avanzadas.
Paso 4: Detener la sesión de seguimiento.
Utilice el comando siguiente para detener la sesión de seguimiento:
tracelog -stop
Normalmente, un comando tracelog -stop requiere un nombre de sesión, pero dado que "NT Kernel Logger" es el valor predeterminado, el nombre de la sesión no es necesario.
Paso 5: Crear un informe de DPC/ISR.
Para resumir los mensajes de DPC/ISR en el registro de seguimiento de eventos, use la versión de Tracerpt incluida en Windows XP con SP2 y versiones posteriores de Windows.
El siguiente comando Tracerpt da formato a los mensajes en el archivo Test01.etl y crea un informe con formato de texto de la actividad en Windows XP con SP2.
tracerpt test01.etl -report dpcisr.txt -df
En este comando, el parámetro -report especifica el método de análisis y el nombre del archivo de salida. El parámetro -df es necesario para dar formato a los mensajes correctamente solo en Windows XP con SP2.
Al crear este informe en Windows Server 2003 con SP1 y versiones posteriores de Windows, puede crear un informe con formato HTML mediante el comando siguiente.
tracerpt test01.etl -report dpcisr.html -f HTML
En este comando, el parámetro -report especifica el nombre del archivo de salida y el parámetro -f especifica el formato del informe.
Paso 6: Analizar el informe.
El "Informe de sesión de seguimiento de eventos de Windows" tiene las secciones siguientes:
Estadísticas de imagen. Muestra datos sobre los procesos que se ejecutan en el equipo durante el seguimiento.
Totales de disco. Muestra datos sobre E/S de disco para cada proceso que se ejecuta durante el seguimiento.
Uso del procesador de DPC para todo el seguimiento: muestra el porcentaje de tiempo de procesador dedicado a mantener las rutinas de DPC para cada controlador.
Distribución de todos los tiempos de ejecución de DPC para todo el seguimiento. Una tabla de intervalos de tiempo en unidades de microsegundos. En la tabla se muestra el porcentaje de rutinas de DPC que se encuentran en cada intervalo de tiempo.
Distribución de los tiempos de ejecución de DPC de DriverName ( DPCRoutineAddress ) para todo el seguimiento. Una tabla de intervalos de tiempo en unidades de microsegundos. En la tabla se muestra el porcentaje de instancias de esta rutina de DPC que se encuentran en cada intervalo de tiempo. Aparece una sección como esta para cada rutina de DPC del seguimiento.
Uso del procesador de ISR para todo el seguimiento. Muestra el porcentaje de tiempo de procesador dedicado a las rutinas de servicio de interrupción de mantenimiento para cada controlador del seguimiento.
Distribución de todos los tiempos de ejecución de ISR para todo el seguimiento. Una tabla de intervalos de tiempo en unidades de microsegundos. En la tabla se muestra el porcentaje de rutinas de ISR que se encuentran en cada intervalo de tiempo.
Distribución de los tiempos de ejecución de ISR de DriverName ( ISRAddress ) para todo el seguimiento. Una tabla de intervalos de tiempo en unidades de microsegundos. En la tabla se muestra el porcentaje de instancias de la ISR que se encuentran en cada intervalo de tiempo. Aparece una sección como esta para cada ISR del seguimiento.
Distribución del uso del procesador de DPC e ISR para TracingPeriodInMs, ventanas de tiempo de dos microsegundos. Muestra el uso combinado del procesador por parte de las DPC e ISR durante el seguimiento.
Distribución de latencias de DPC de ISR de DriverName ( ISRAddress ) a DriverName ( DPCRoutineAddress ) para todo el seguimiento. Muestra la distribución de intervalos de retraso entre el final de una ISR y el principio de la DPC asociada.
En el siguiente extracto de un informe de ejemplo se muestra la distribución de los tiempos de ejecución de DPC para Ipsec.sys. En general, no se recomienda que las rutinas DPC duren más de 100 microsegundos. El informe muestra que más de la mitad de las rutinas DPC para este controlador superan el umbral.
+------------------------------------------------------------------------------+
| Distribution of ipsec.sys (F7AA7449) DPC execution times for the whole trace |
+------------------------------------------------------------------------------+
| Lower Bound Upper Bound Count Percent |
+------------------------------------------------------------------------------+
| 0 1 0 0.00% |
| 1 2 0 0.00% |
| 2 3 8 42.11% |
| 3 4 1 5.26% |
| 4 5 0 0.00% |
| 5 10 0 0.00% |
| 10 25 0 0.00% |
| 25 50 0 0.00% |
| 50 100 0 0.00% |
| 100 250 10 52.63% |
+------------------------------------------------------------------------------+
| 19 100.00% |
+------------------------------------------------------------------------------+