🤶🏿 💣 🦅 Investigación: ¿qué es más alto que las prioridades de subprocesos en Windows? 🍺 👶🏻 🛡️

Esta investigación, como muchas otras, comenzó con el hecho de que estaba haciendo mi propio negocio, no tratando de buscar problemas por mí mismo. Esta vez, todo lo que hice fue abrir la tapa de la computadora portátil e intenté iniciar sesión en el sistema.

Por las primeras veces, cuando esto resultó en un retraso de veinte segundos, ignoré el problema, esperando que se resolviera por sí solo. Las siguientes veces pensé en la investigación, pero los problemas de rendimiento que surgen incluso antes de iniciar sesión son más difíciles de resolver, y fui flojo.

Cuando me di cuenta de que estaba evitando cerrar la computadora portátil porque tenía miedo de estos retrasos demasiado frecuentes, me di cuenta de que era hora de hacerlo en serio.

Afortunadamente, recientemente arreglé la traza del búfer de anillo UIforETWhaciéndolo confiable, así que lo comencé y comencé a esperar el próximo evento de retraso. No tuve que esperar mucho.

Me tomó varias veces lograr que el ETW me siguiera completamente bien . Y dado que este territorio no me era familiar, me llevó un tiempo descubrir qué estaba sucediendo. Todavía no entendía completamente el problema, pero el 90% entendía las razones de su aparición. Logré aprender mucho, incluidos algunos detalles nuevos sobre el planificador de Windows, y también encontré una solución absolutamente efectiva.

El rastro ideal que finalmente grabé al cargar en Microsoft Windows Performance Analyzer (WPA) se ve así:

Eventos estándar, ventanas en foco y uso de CPU

Esta tabla y dos gráficos contienen una tonelada de información. La tabla superior ( Eventos genéricos ) muestra las pulsaciones de teclas registradas para UIforETW. Traté de presionar una tecla (código de clave virtual 162) una vez por segundo hasta que aparezca un campo de ingreso de contraseña. Dado que estas 17 pulsaciones de teclas están seleccionadas, en el gráfico a continuación se muestran con líneas azules verticales para una visualización simplificada del tiempo de ejecución de eventos críticos. El eje x representa el tiempo en segundos.

Las barras horizontales en el gráfico superior ( Ventana en foco ) muestran qué proceso tiene foco durante este tiempo. Hay seis procesos diferentes en total. El período de seguimiento es el corto tiempo durante el cual se cerró la computadora portátil.

El gráfico inferior muestra el uso de la CPU . La información se obtiene de los datos de cambio de contexto, por lo tanto, debe ser completamente precisa y completa. En este seguimiento, un valor del 100% indica el momento en que se utilizaron los ocho procesadores lógicos de mi computadora portátil de cuatro hilos y ocho núcleos.

Después de recibir los datos de seguimiento, tuve que averiguar qué hace mi computadora portátil en secreto cuando se cierra la cubierta y hasta el momento en que vuelvo al sistema.

Tormenta antes de la calma

Como podemos ver, la computadora portátil al comienzo de la traza de la computadora portátil es relativamente simple, como debería ser. Entonces cerré su tapa. Esto parece haber causado un aumento en la actividad de la CPU y un cambio en el enfoque de las ventanas. Window in Focus cambió de UIforETW a Idle, luego a csrss, de nuevo a Idle, a LogonUI y luego a Idle. ¿Quien lo hubiera pensado?

Durante este intervalo, la computadora portátil realizó aproximadamente 17 segundos de procesamiento de CPU de varios tipos. Parte de esto es el trabajo necesario para apagar. Parte: estos son programas (incluidas las herramientas internas de Google) que están registrados en el Programador de tareas para la ejecución de "Cuando un usuario bloquea una estación de trabajo", tiene sentido. Incluso me di cuenta de que se está trabajando para crear elementos de la interfaz de usuario para iniciar sesión cuando el usuario continúa trabajando; debe estar preparado con anticipación, ¿verdad?

17 segundos de CPU: un tiempo bastante largo para que la computadora portátil se vaya a dormir. Incluso en mi computadora portátil con cuatro núcleos y ocho hilos, el proceso lleva más de cuatro segundos. En la computadora portátil de mi casa, lleva más de 13 segundos de tiempo de CPU para conciliar el sueño, y casi todos pasan al código de Windows. ¿El servicio de políticas de diagnóstico realmente necesita ejecutar un par de SruDbTableSearches antes de que la computadora portátil pueda descansar?

Creo que este trabajo excesivo al ir a dormir también es un problema, pero este no es el problema que estoy buscando. Así que decidí darle la espalda.

Y solo mucho más tarde me di cuenta de que fue durante este tiempo cuando se arrojaron los granos de destrucción de mi insecto ...

Dormir

Después de bloquear la computadora portátil, no hay actividad de la CPU. En esta prueba en particular, la computadora portátil se bloqueó durante unos 16 segundos.

Despertar convulsivo

La actividad de la CPU durante la transición al sueño es incomparable con cuando comenzó a despertar. Durante este tiempo, mi computadora portátil sobrecargada tomó aproximadamente 172 segundos de tiempo de CPU (!!!) durante 22.6 segundos. Esto es un montón de trabajo.

Uno de los misterios de este proceso es la caída del uso de la CPU a casi cero aproximadamente un segundo después del estallido inicial de actividad. Este breve período de inactividad parece bastante anormal, dado el caos que lo rodea. Pero creo que esta característica no está relacionada con el problema, por lo que no le presté atención.

Otro misterio es por qué tantosLos programas cobran vida después de esta breve pausa. Es curioso que el intruso más serio responsable de 31.6 de 172 segundos de la CPU fue Windows Performance Analyzer (WPA), el mismo programa que utilizo para analizar los rastros. Las tres copias que dejé ejecutándose están trabajando duro para representar mi interfaz de usuario, a pesar de que aún no es visible.

Además, se producen patrones oscuros cuando se intenta inicializar dispositivos portátiles. KeStallExecutionProcessor es un ciclo de espera, y fue extraño ver que esta es la función más ejecutable de todo el sistema. ¿Es un segundo ciclo de espera impar la única forma de iniciar el equipo? ¿Es realmente necesario pasar 700 ms de tiempo de CPU inicializando el mouse y el teclado ? ¿Deberían Microsoft e Intel ignorar la recomendación de Microsoft sobreun máximo de 50 microsegundos ?

Conductores de un ciclo de espera. i8042prt.sys está escrito por Microsoft. Los siguientes dos son creados por Intel.

En última instancia, muchos programas se ejecutan activamente durante este tiempo . La mayoría de ellos parecen estar enfrentando el mismo problema que WPA: están desesperados por dibujar píxeles en una pantalla oculta, y esto alude a un error de Windows. Pero incluso sin este error explorer.exe y otros programas buscan activamente algo que hacer. Pero al final, aunque este uso excesivo de la CPU es una parte necesaria del problema, no es el problema en sí . Así que de nuevo dejé de prestarle atención.

Atención

Al analizar los rastros, es importante saber cuándo ocurren acciones importantes. La evidencia principal fueron los eventos de entrada, porque dejé de hacer clic en el control después de que apareció el formulario de entrada de contraseña. Aquí están las últimas tres pulsaciones de teclas de la tecla de control en forma aproximada en el cuadro Ventana en foco :

Parece que los eventos críticos están recibiendo el foco de LockApp.exe, después de lo cual el foco obtiene LogonUI.exe casi instantáneamente. Presumiblemente, ingresé la contraseña en LogonUI.exe (es conveniente que la traza no intercepte los eventos del teclado), después de lo cual el foco cambió brevemente al explorador y luego a UIforETW, desde donde comencé.

También parece que LogonUI.exe no puede enfocarse antes de LockApp.exe: este patrón se repite en todos los rastros que estudié.

Entonces, después de más de mil palabras dedicadas a resolver este enigma, finalmente tenemos una pregunta clara que podemos investigar: ¿por qué LockApp.exe se enfoca después de salir del tiempo de inactividad, lleva veinte segundos?

Tenemos una pregunta? Genial, respondamos

Utilizando los datos de Uso de CPU (Preciso) obtenidos del cambio de contenido, rápidamente descubrí que dentro de veinte segundos después de despertar, LockApp.exe recibió menos de un milisegundo de tiempo de CPU, y durante más de 14 segundos (de 35.158 sa 49.827 s) no funcionó generalmente:

LockApp no funciona en absoluto durante mucho tiempo

La documentación sobre el significado de las columnas en las tablas de Uso de CPU (Preciso) está aquí .

Si un proceso o subproceso no se ha estado ejecutando durante algún tiempo y desea averiguar por qué, generalmente se pueden encontrar pistas importantes en el primer cambio de contexto después de una larga pausa, es decir, cambiar a 49.827 segundos de rastreo. Reordené las columnas para mostrar más datos de este cambio de contexto:

LockApp está preparado pero no ejecutado. Extraño ...

Cuenta, igual a 1 significa que miramos los datos para un solo cambio de contexto.

Tiempo desde el último, igual a 38,2 millones de microsegundos, significa que este hilo no se ejecutará en 38,2 segundos. Esto en sí mismo no es ni bueno ni malo. Los flujos inactivos ahorran energía, y al final la computadora portátil estuvo en un sueño por algún tiempo.

El tiempo de conexión simplemente nos dice cuándo encaja exactamente el hilo en la CPU, cuando el contexto cambia a ese hilo.

Y ahora vamos a la columna Listo. Nos dice cuánto tiempo el hilo estuvo listo para ejecutarse, pero no se ejecutó. En otras palabras, este hilo estaba esperando algo (bloqueo, manejo) y esto es algofue liberado o iniciado, pero el hilo aún no se ejecutó durante 19.493 segundos.

Para comprender mejor la columna Listo (nosotros) , puede echar un vistazo a la columna Tiempo (s) listo (s) . Nos dice cuándo está preparada la corriente. Vemos que durante 30.333 segundos de rastreo, este hilo se preparó para la ejecución, pero no se ejecutó hasta 49.827 segundos. Esto parece ser importante.

Esta disposición de columnas nos muestra el mismo cambio de contexto:

New Thread Stack y Ready Thread Stack

Entonces, este hilo (que el New Thread Stack esperaba que fuera NtWaitForWorkViaWorkerFactory) recibió la orden de despertarse (el proceso del sistema llamó a KeSetEvent) poco después de que abrí la tapa del portátil, durante 30.333 segundos de rastreo. Pero comenzó no entonces (que sería "bueno"), sino después de 19.494 s, y esto es malo.

Por lo general, cuando llevo a cabo un análisis de expectativas de este tipo, paso mucho tiempo averiguando por qué la transmisión está esperando y qué hizo que no estuviera lista. Pero esta era la primera vez que hacía un análisis de expectativas, en el que no era importante, y la pregunta era por qué este hilo ya no se ejecuta.

Casos ...

La mayoría de las personas no pasan tanto tiempo estudiando los rastros de ETW, por lo que se necesita una explicación aquí. Esto es muy extraño Si el hilo está listo, generalmente se inicia instantáneamente o después de unos pocos milisegundos. La disponibilidad de la secuencia, como su nombre lo indica , significa que la secuencia está lista para ejecutarse y que casi nada puede interferir con ella. Pero descubramos qué puede evitar la ejecución de un hilo terminado.

Tarea prioritaria

Al principio sugerí que este es un caso simple de "hambre" de la CPU. Docenas de procesos requieren tiempo de CPU, y debido a esto, LockApp no obtiene el correcto hasta que la carga disminuye. Sin embargo, esta teoría no se corresponde con los síntomas, ya que el proceso LockApp podría tomar unos 18 segundos incluso sin obtener tiempo de CPU.

La teoría del hambre de la CPU es buena porque es verificable. Pude aumentar la prioridad del proceso LockApp usando el Administrador de tareas (durante uno de los breves períodos en que no fue suspendido por el sistema UWP), por lo tanto, en la traza final que utilicé para esta publicación, LockApp se ejecutó con alta prioridad. Un subproceso normal de Windows se ejecuta con una prioridad de aproximadamente 8-10. La prioridad más alta con la que se puede ejecutar un subproceso de Windows normal (no en tiempo real) es 15. Mis trazas de ETW mostraron que LockApp siempre funcionó con prioridad 13 o superior.

Aquí hay una línea de tiempo de la CPU para 19.494 segundos críticos, agrupados y coloreados por prioridad de hilo ( Nuevo en Pri, la prioridad actual que se asignó al subproceso). Vemos que los subprocesos con prioridades 4, 8, 9 y 10 consumen la gran mayoría del tiempo de CPU, especialmente al final:

Uso de CPU por prioridad

Aquí hay otra imagen con hilos ocultos con prioridades 0-12. Cada vez que el gráfico cae por debajo del 12.5% (lo que significa un procesador lógico del tiempo de CPU de mi laptop de ocho hilos), se debe iniciar LockApp , y se vuelve absolutamente increíble que la prioridad evite que se ejecute tan a menudo cuando muchos hilos con menor o igual prioridad obtener un montón de tiempo

Uso prioritario de la CPU, solo subprocesos de alta prioridad

Eliminar la inversión prioritaria

Se especula que los algoritmos de inversión de prioridad de Windows son tan propicios para otros subprocesos que LockApp.exe está bloqueado. Pero dado que los gráficos mostrados arriba demuestran que las prioridades verdaderas se usan en las decisiones de planificación, esta suposición (siempre poco convincente) tendrá que ser abandonada.

Descarga del núcleo de la pila

Cuando hablé sobre este rompecabezas en Twitter, uno de los comentaristas sugirió que la pila del núcleo del hilo estaba descargada . No estaba familiarizado con esta situación, pero después de las explicaciones de John Werth (él entiende en su campo) apagué el intercambio de la pila del kernel y reinicié la computadora. Nada ha cambiado. De hecho, no pensé que esto ayudaría, dado que tengo 32 GB de memoria, y el problema ocurre repetidamente y con frecuencia; pero era mejor estar seguro de esto.

Proceso de pausa

Dado que LockApp es una aplicación UWP moderna, está sujeta a restricciones similares a las de las aplicaciones para teléfonos inteligentes. Entre otras cosas, esto significa que se puede suspender cuando no está en primer plano y luego "descongelarse" cuando se devuelve al primer plano. James Forshaw propuso grabar ETW de Microsoft-Windows-Kernel-Process para obtener datos sobre esto.

Los eventos están diseñados para causar la máxima confusión. El nombre de la tarea Process Freeze se usa tanto para "descongelar" como para "congelar", y la versión del evento win: Stop significa que el proceso está comenzando (se detuvo la congelación) y la versión de win: Startsignifica que el proceso se detiene (comienza a congelarse). Todo esto es extremadamente lógico, pero muy confuso. Si los nombres de los eventos se dividieran en Congelar y Descongelar, entonces habría menos confusión.

No hay documentación para estos eventos, pero gracias al análisis, determiné que estos eventos siempre son creados por el Servicio de Infraestructura de Tareas de Fondo / Broker . El nombre y la ID del proceso correspondiente se indican en el campo FrozenProcessID.

Eventos de ProcessFreeze (también utilizado para descongelar) Fue

interesante investigar este proveedor, tiene muchos eventos prometedores, pero al final resultó que LockApp no se detuvo ni se descongeló durante el rastreo. Sin embargo, este proveedor parecía bastante útil, por lo que modifiqué UIforETW para que las versiones futuras siempre lo escribieran.

Ya hemos descartado todo

Ninguna de las teorías descritas anteriormente me pareció muy probable, y ahora todos las hemos excluido. Comencé a buscar ayuda y me pidió que me diera ideas de un amigo de Microsoft. Y en ese momento descubrí que la prioridad de flujo 0-31 tan conocida en Windows es en realidad solo cinco bits de baja prioridad de un sistema de prioridad completa .

Uso de cargo oficial

Resultó que mi ignorancia fue culpa mía. Si leyera atentamente las 108 páginas de la sección Hilos de Windows Internals, 7ma Edición, Parte 1 , entendería lo que estaba sucediendo. Si desea avanzar, este tema se revela en las páginas 287 a 295 .

Este campo de súper prioridad que no conocía se llama Rango . Aparece en WPA como una columna oculta predeterminada (para encontrarla, debe abrir el Editor de vistas) llamada NewThreadRank . Cuando se planifican hilos, el Rango de hilos tiene prioridad sobre la prioridad. Casi todas las transmisiones tienen Rango 0, y una transmisión con Rango 0 siempre tiene mayor prioridad que una transmisión con Rango 2. Al incluir una columnaNewThreadRank y mirando el lado izquierdo de la tabla, podemos ver inmediatamente el problema:

El rango es más importante que la prioridad

Las transmisiones LockApp.exe tienen Rango 2, lo que significa que, a pesar de la prioridad 14, tienen la prioridad más baja en el sistema.

Una explicación casi completa.

Dado que resultó que los subprocesos de LockApp.exe tienen Rango 2, solo se pueden ejecutar cuando ninguno de los subprocesos con Rango 0 "desea" ejecutarse. Dado que muchas aplicaciones (por razones desconocidas) representan activamente sus pantallas invisibles, luchan por cada migaja de tiempo de CPU, sin dejar nada para los rangos más altos. Una vez que LockApp.exe recibe una pequeña fracción del tiempo de CPU, rápidamente se mueve al Rango 0 (y la carga de la CPU cae), después de lo cual el proceso de inicio de sesión se realiza de la manera habitual.

Después de conocer esta información, comencé a estudiar cómo cambia el rango de LockApp con el tiempo. En los últimos segundos antes de irse a dormir, LockApp cambió repentinamente del rango 0 al 2. El rango está diseñado para evitar que la CPU tome demasiado tiempo, como cuando Windows Photos está demasiado interesado en el procesamiento de fondo no solicitado y hace la transición del rango 2 al 19:

Microsoft.Photos baja en el rango

De la documentación se puede entender que el objetivo principal del rango de flujo es compartir el tiempo de CPU entre sesiones en la máquina para que los procesos de un usuario no dañen a otros. Ambas opciones para usar el rango dejan en claro que el rango del subproceso solo debería aumentar si usa mucho tiempo de CPU, y cuando la computadora portátil se fue a dormir, LockApp.exe usó solo 79.3 ms de tiempo de CPU, y el resto del sistema - 17 del tiempo de CPU . Sin embargo, el sistema operativo por alguna razón decidió degradar LockApp a 2 en el proceso de ir a dormir.

El sistema operativo cambia el rango de la secuencia solo si pertenece al "grupo de planificación" ( KSCHEDULING_GROUP), y la mayoría de los subprocesos en una instalación típica de Windows no son miembros. En consecuencia, la mayoría de los subprocesos no están sujetos a un cambio en el rango, por lo que pueden pasar el tiempo de CPU de la manera que deseen.

Rompecabezas restantes

Desafortunadamente, todavía no está claro por qué LockApp.exe cae al rango 2 antes de activar el modo de suspensión. Supongo que LockApp está en el grupo de planificación y probablemente uno de los algoritmos se comporta incorrectamente. Pero no pude encontrar una API para investigar esto, y el tiempo se estaba acabando. Si conoce algún detalle, escriba los comentarios al artículo original. Me parece que el principio mismo de utilizar el rango como el componente más importante en las decisiones de planificación debería romperse inevitablemente si la mayoría de los procesos del sistema no están involucrados en él: los hilos en los grupos de planificación siempre corren el riesgo de quedarse sin los recursos necesarios. La planificación dinámica de asignación de recursos ( DFSS ) está condenada al fracaso si la mayoría de los subprocesos no están involucrados.

Además, no sé por qué tantas aplicaciones permanecen activas después de ir a dormir. Esto generalmente se explica por el hecho de que "muchos temporizadores terminan cuando la computadora portátil está en modo de suspensión durante varias horas", pero esta explicación no es adecuada si la computadora portátil estuvo en un sueño durante solo unos segundos, y el comportamiento de representación de WPA indica que algo sucede en el sistema de ventanas algo mal. Agregue a eso aplicaciones de mal comportamiento y controladores de ciclo de espera, y la CPU apilará todo con el tiempo.

El hecho de que las tormentas de la CPU se apaguen y LockApp se inicie al mismo tiempo conduce a una explicación obvia: LockApp solo puede funcionar cuando la demanda de la CPU cae. Pero hay una explicación igualmente convincente: tan pronto como LockApp obtiene la capacidad de ejecutarse (o, posiblemente, LogonUI lo consigue), la demanda de CPU cae. Ambas explicaciones funcionan, pero creo que la segunda es más plausible, porque de lo contrario no podemos explicar por qué la interpretación aparentemente interminable de WPA se detiene de repente.

Solución al problema

Tan pronto como me di cuenta de que LockApp.exe es una aplicación separada que tiene problemas con el inicio, y que aumentar su prioridad no ayuda, lo desactivé. El archivo DisableLockScreen.reg me ayudó con esto:

Windows Registry Editor Version 5.00
[HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\Personalization]
“NoLockScreen”=dword:00000001

Al apagar la pantalla de bloqueo, la computadora portátil se despierta inmediatamente después de abrir la cubierta. No noté ni el frenado ni las tormentas de la CPU, y ahora se necesita un paso menos para ingresar.

La primera publicación de Twitter que publiqué cuando encontré el problema por primera vez contiene una línea de tiempo para una investigación que puede ser útil para alguien. Además, muchas personas inteligentes de Twitter vinieron a la publicación, gracias a ellos.

Cuando volví al artículo, descubrí que después de volver a encender la pantalla de bloqueo, el problema desapareció. Un simple reinicio no lo solucionó: en febrero reinicié muchas veces, pero probablemente no sabremos por qué se perdió.

Investigación: ¿qué es más alto que las prioridades de subprocesos en Windows?