“Explorer gasta 700 ms para abrir el menú contextual de la barra de tareas. El 75% de este tiempo, realiza 114.801 operaciones de lectura desde un archivo, la cantidad promedio de datos leídos es de 68 bytes.
¿Debería escribir una publicación sobre esto, o un tweet bastante sarcástico?Trabajo rápidamente en una computadora y, por lo tanto, me molesta cuando tengo que esperar la finalización de una operación, que debe realizarse al instante. Un obstáculo constante en mi computadora portátil doméstica de servicio pesado fue el lento cierre de las ventanas en la barra de tareas. Hago clic con el botón derecho en el icono, espero a que se abra el menú y luego selecciono "Cerrar ventana". Lo más lento en este proceso deberían ser los movimientos del mouse, pero resulta que el componente más largo es el retraso antes de que aparezca el menú.
Esto me molestó durante mucho tiempo, pero mostré un autocontrol poco característico y evité la irritación. Eso fue hasta hoy, cuando finalmente me rompí y agarré el rastreador
ETW .
Esta publicación está escrita como un control para la velocidad de los blogs. Aproximadamente 90 minutos pasaron desde el momento en que se encontró el problema y el tweet sarcástico al respecto hasta que se publicó la publicación.
El trazador ETW solucionó cómo hago clic derecho en la barra de tareas y cierro las dos ventanas del Explorador. Utilicé la función
UIforETW Tracing to file con las opciones predeterminadas, lo que resultó en un
registro de diagnóstico de 20,9 MB .
A veces, la parte más difícil en el análisis de un rastro es encontrar la ubicación del problema, pero en este caso esta parte del análisis es trivial. Hubo tres señales inequívocas que indicaban el lugar correcto y el culpable dolorosamente obvio del crimen.
La primera señal fue eventos de entrada. UIforETW contiene un
registrador de entrada integrado (lo suficientemente anónimo como para no robar accidentalmente contraseñas o información personal), por lo que solo tuve que estudiar los
eventos MouseUp y
Button Type en detalle con un valor de 2 correspondiente al botón derecho del mouse. Al mismo tiempo, las marcas en la línea de tiempo de
WPA aparecen cuando ocurren estos eventos; vea las líneas verticales en la captura de pantalla:
Esto me dejó claro que cuando suelto el botón derecho del mouse, después de 600 ms, el foco de la ventana cambia, lo que, en mi opinión, corresponde al momento en que se muestra el menú. Además, RuntimeBroker.exe tiene un bloque claro de actividad de la CPU entre los eventos de soltar el botón del mouse y cambiar el foco de la ventana.
No se ha demostrado que el cambio en el enfoque de la ventana y la actividad de la CPU estén relacionados, pero al tomar medidas con la aplicación de grabación de pantalla, vi que se necesitan unos 660 ms para mostrar el menú, por lo que tiendo a confiar en esto.
El siguiente paso es aprender qué está haciendo RuntimeBroker.exe. Aunque
el uso de la CPU (preciso) hace un gran trabajo al ver cuánto tiempo de CPU usa el proceso y por qué está inactivo, la
tabla de uso de la
CPU (muestra) es una buena herramienta para descubrir qué tiempo de CPU está
desperdiciando . ¡Lo estudié cuidadosamente y rápidamente descubrí que 264 muestras eran de
KernelBase.dll! ReadFile :
Después de buscar un poco más, encontré otras pilas de llamadas que también afectaron esta función, así que hice clic derecho y seleccioné
Ver llamadas-> Por función . El modo que se activó (con pilas invertidas) mostró que de 899 muestras de este proceso, 628 muestras, o 70%, de diferentes pilas de llamadas pasaron por esta función:
271 muestras en esta secuencia no pasaron por la función, y las muestras restantes (no mostradas) estaban en otras secuencias.
Observe que 899 muestras en una secuencia de 10 252 representan dos clics del mouse, es decir, aproximadamente 450 muestras o 450 ms (a una frecuencia de muestreo estándar de 1 kHz) por clic del mouse.
A veces, la E / S de archivo es tiempo de CPU
El uso de la CPU (muestra) muestra el tiempo de la
CPU , por lo que la E / S del disco generalmente no se muestra aquí, porque en estos momentos el flujo se queda dormido y espera el disco. El hecho de que las operaciones de E / S se muestren como tiempo de CPU significa que todas las lecturas cayeron en la memoria caché del sistema y el tiempo de CPU fue un recurso adicional del núcleo (consulte
ntoskrnl.exe en la primera pila de llamadas muestreadas) gastado en obtener datos de la memoria caché.
Ahora que
la E / S de archivo ha sido sospechosa, tenemos que ir a
Graph Explorer-> Storage-> File I / O. Después de ajustar ligeramente la apariencia de las columnas, obtuvimos el siguiente resultado impresionante:
, 10 252
RuntimeBroker.exe 229 604
ReadFile, 15 686 586 . 68 .
.
, — . ,
RuntimeBroker.exe . 4 027 904 , , , 1,9 .
, . , ( ):
%appdata%\Microsoft\Windows\Recent\AutomaticDestinations\f01b4d95cf55d32a.automaticDestinations-msWPA. — , . :
« „“, ( ) ( ) „“/ . , ».
, !
, . , , , .
- ReadFile, 68 . , , . , 4 , .
- , - , — .
- , - , . , ETW !
- https://aka.ms/AA60dfg
- , UIforETW ,
- , ( , ), shift+ . , .
- Hacker news
- Reddit
- Twitter