Cómo el tiempo lineal se convierte en Windows en O (n²)

Recientemente me encontré con retrasos de varios minutos en mi estación de trabajo. Después de la investigación, resultó que la causa del problema era un bloqueo, que podía durar cinco minutos, durante los cuales la fuente del bloqueo básicamente giraba en un ciclo de nueve instrucciones.

Es muy importante para mí seleccionar buenos encabezados para mis publicaciones, pero inmediatamente recordé que el nombre apropiado "48 núcleos están bloqueados por nueve instrucciones" ya fue tomado [ traducción en Habré] por una publicación escrita hace menos de un mes. La cantidad de procesadores bloqueados es diferente, y el ciclo es un poco más largo, pero de hecho, todo esto te hace experimentar un deja vu. Por lo tanto, mientras explico el nuevo problema encontrado, quería reflexionar sobre por qué sucede esto todo el tiempo .

¿Por qué está pasando esto?

Hablando en términos generales, tales problemas surgen como resultado de una observación que llamaré la Primera Ley de Computación de Dawson: O (n ² ) es un imán para algoritmos que no escalan bien : son lo suficientemente rápidos como para entrar en producción, pero lo suficientemente lentos como para estropear todo, cuando lleguen


O (n ² ) en acción: datos tomados de mi caso

Que esta pasando El desarrollador escribe el código y usa el algoritmo O (n ² ). Quizás no se da cuenta de esto, o el algoritmo se convierte en O (n ² ) debido a un error , o el desarrollador sabe que él es O (n ² ), pero cree que nunca será importante. En condiciones de laboratorio, la velocidad del código es aceptable, y es aceptable para la mayoría de los usuarios en el mundo real, pero luego alguien crea 7,000 procesos con App Verifier activado o crea un archivo binario con 180,000 elementos CFG , o recopila una DLL tan grande que es constantemente se escanea una lista enlazada , que toma todo el procesador. Al trabajar en el tiempo de inicio del motor Valve Source 2, encontré muchos algoritmos O (n ² ), cada uno de los cuales agregó aproximadamente 30 segundos al tiempo de inicio del motor, es decir, este problema ocurre con desarrolladores muy diferentes.

O (n ² ) es un imán para algoritmos que no escalan bien: son lo suficientemente rápidos como para entrar en producción, pero lo suficientemente lentos como para estropear todo cuando llegan allí.

Exactamente

Por ejemplo, la creación de los nombres de los archivos de registro del verificador de la aplicación se realiza en tiempo lineal para cada proceso en ejecución, y esto es normal hasta que se da cuenta de que esto conduce a O (n ² ) si se están ejecutando muchos procesos. A veces ni siquiera es obvio que hay bucles anidados, o que formalmente no es O (n ² ), o no es obvio que los bucles pueden funcionar durante tanto tiempo que puede afectar significativamente la velocidad ...

Por lo tanto, tenga en cuenta esta característica, piense en ello cuando escriba código, monitoree cómo se escala el rendimiento bajo cargas pesadas y examine partes sospechosas del código al perfilar esas cargas pesadas. O déjemelo a mí para que pueda buscarlos y escribir artículos en mi blog.

Volvamos a nuestras quejas habituales.

Como de costumbre, me dediqué a trabajar en mi estación de trabajo desactualizada pero poderosa con 48 procesadores lógicos y 96 GB de RAM. Introduje ninja chrome para construir Chromium, pero ... no pasó nada. Miré y esperé veinte segundos, pero la asamblea nunca comenzó. Entonces, por supuesto, cambié a UIforETW para grabar el rastro ETW . Más precisamente, traté de hacerlo. Al intentar iniciar la grabación de seguimiento, UIforETW se congela . ¡Por primera vez en mi práctica, un error utilizó medidas de protección para evitar que lo explorara!

Después de uno o dos minutos, comenzó el ensamblaje de Chromium, y UIforETW comenzó la traza, pero comenzó demasiado tarde y no tenía la más mínima información sobre lo que sucedió.


Opciones de UIforETW con seguimiento de búfer circular seleccionado

Cuando sucedió lo mismo un par de días después, UIforETW nuevamente no pudo hacer nada. Esta vez, dejé el rastro para trabajar en memorias intermedias circulares, para estar preparados para el hecho de que el bloqueo se produciría por tercera vez. Sin embargo, esto redujo en gran medida la velocidad de mis herramientas de construcción, así que después de unas horas me di por vencido.

Entonces esta situación se repitió nuevamente . Esta vez ejecuté la herramienta de registro de rastreo ETW creada por Microsoft - wprui , y pude comenzar a grabar. ¡Aproximadamente 40 segundos después, el ensamblaje comenzó a funcionar y obtuve un rastro!

¿Puedo comenzar la investigación ahora?

Anteriormente, noté en el "Administrador de tareas" que WinMgmt.exe se estaba ejecutando durante estas congelaciones . Al observar los datos de Uso de CPU (Preciso) en WPA, me convencí de que después de más de cuarenta segundos, durante los cuales WinMgmt.exe fue casi el único proceso de trabajo, mi máquina cobró vida después de que WinMgmt.exe se apagara :


Esperamos el despertar de los procesos después de que se complete WinMgmt.exe

Todo esto es bastante sospechoso, pero mis sabios lectores saben que "después" no significa "debido a", y requerirán pruebas.

Como la última vez , aproximé el momento del desbloqueo en el gráfico, clasificando los cambios de contexto por Tiempo de cambio y buscando el primer cambio con un valor de Tiempo desde el último largo (que indica el período de tiempo durante el cual el hilo no se ejecutó). Habiendo perdido una docena de hilos que solo fueron cortos tiempos de inactividad, encontré el primero de muchos que esperó 41.57 segundos. El hilo dormido no despertó WinMgmt.exe , pero rápidamente descubrí que se despertó con el hilo que despertó WinMgmt.exe una fracción de milisegundo antes.

Para obtener una explicación de los gráficos de Uso de CPU (Preciso) y los conceptos de preparación de subprocesos / subprocesos nuevos, consulte este tutorial o esta documentación .

En la captura de pantalla con los datos de cambio de contenido, la línea 17 contiene la secuencia 72.748 (WinMgmt.exe) , que activa la secuencia 74.156 (svchost.exe). A continuación, en la línea 19, el subproceso 74,156 (svchost.exe) activa el subproceso 58,704 (svchost.exe) , que esperaba 41,57 segundos. Este es el primer hilo que se despierta después de un largo sueño y a partir de esto continúa la cadena de activación de los flujos. Los subprocesos que se acaban de activar se pueden ver en la columna Nuevo Id. De subproceso , y luego bajar unas líneas y verlos en la columna Id. De subproceso de preparación , activando otro subproceso. Los nombres y las ID de proceso lo ayudan a comprender el contexto. La línea 17 está asociada con las líneas 18 y 19, la línea 19 está asociada con 20, que está asociada con la línea 23, que está asociada con la línea 27, y así sucesivamente; cada hilo es activado por el hilo anterior en la cadena:


El monstruo despierta: los largos hilos inactivos cobran vida

41.57 es mucho tiempo para bloquear un hilo, pero en realidad se bloquearon cientos de hilos, y se bloquearon mucho más tiempo. La única razón por la que su valor Tiempo desde el último es aproximadamente 41.5 segundos es porque la longitud del rastreo antes de que se resuelva el bloqueo.

Parece que los resultados son consistentes con la teoría de que el problema está en WinMgmt.exe , pero no lo prueban. Mi confianza aumentó cuando miré svchost.exe (3024) en Seguimiento-> Configuración del sistema-> Servicios y descubrí que es un servicio Winmgmt , pero aún necesitaba más certeza.

Habiendo hurgado un poco más (avanzando y retrocediendo en el tiempo), decidí que las interacciones son demasiado complicadas para analizarlas en detalle, especialmente sin nombres de flujo que podrían indicarnos qué están haciendo 25 hilos diferentes en svchost.exe (3024) .

Prueba!

Entonces decidí acercarme a la prueba de culpabilidad WinMgmt.exe de manera diferente. Quizás valió la pena comenzar con esto, pero sería demasiado simple. Tomé la línea de comando WinMgmt.exe de la tabla Procesos en WPA y la inicié manualmente. El comando tiene la forma:

winmgmt.exe / verificadorepository

y tardó unos cinco minutos en completarse. Si bien funcionó (y tuve mucho tiempo), descubrí que no podía iniciar el seguimiento de ETW desde UIforETW . Tal evidencia era mejor que cualquier análisis complejo que pudiera hacer.


Configuración para mostrar solo subprocesos inactivos largos

Luego corrí repro nuevamente con el rastro ya corriendo; Después de analizar el rastro, descubrí más de cien procesos cuyos hilos fueron bloqueados durante más de cinco minutos.

Y de nuevo al grano ...

Por costumbre, volví a mirar los datos de Uso de la CPU (Muestreo) para ver en qué WinMgmt.exe estaba perdiendo el tiempo. Rápidamente descubrí que el 96.5% de las muestras estaban en repdrvfs.dll! CPageCache :: Read () , llamado en cuatro pilas diferentes:


Cuatro caminos que me llevaron a CPageCache :: Leer

Aquí se muestra un árbol de pilas completas para esta función, principalmente para las personas de Microsoft que desean investigar este problema:


Pilas completas que conducen a CPageCache :: Leer de tres maneras

Agregué una columna de dirección y descubrí que el 95.3% de las muestras estaban en un ciclo de nueve instrucciones (las muestras siempre cayeron en solo siete de nueve instrucciones (si desea saber por qué, vea aquí ), pero el depurador mostró el tamaño completo del ciclo) :


Muestras por dirección: siete direcciones muy "calientes"

Luego comencé winmgmt.exe / verifiedrepository manualmente, y al mismo tiempo recopilé datos del contador de la CPU sobre las instrucciones de rama que se estaban ejecutando . A partir de esto, podría calcular aproximadamente cuántas veces se ejecutó el ciclo. Esto probablemente no era necesario, pero quería asegurarme de que el bucle se ejecutara muchas veces y que no se ejecutara lentamente (por alguna razón). Pensé que era genial poder hacerlo simplemente, solo hacer un pequeño cambio en el archivo por lotes. Descubrí que WinMgmt.exe ejecutó aproximadamente una instrucción de ramificación por ciclo, es decir, el ciclo (que, como ya sabía, consumía la mayor parte del tiempo de la CPU) fue extremadamente rápido, y la desaceleración se debió al hecho de que corrió cientos de millones tiempos

Retardo Xperf

Solo por meticulosidad, decidí ver por qué UIforETW no podía comenzar a rastrear durante este incidente. Resultó que UIforETW estaba ejecutando xperf , pero xperf estuvo inactivo durante 41.5 segundos (en realidad más) en esta pila de llamadas:

xperf.exe! wmain
xperf.exe! CStopTrace :: Ejecutar
perfctrl.dll! LoggingSession :: EnumLoggers
perfctrl.dll! LoggingSession :: LoggingSession
perfctrl.dll! LoggingSession :: CreateProviderList
perfctrl.dll! GetProviderInfoCache
perfctrl.dll! CProviderInfoCache :: CProviderInfoCache
tdh.dll! TdhfEnumerateProviders
tdh.dll! TdhpWbemConnect
wbemprox.dll! CLocator :: ConnectServer
wbemprox.dll! CDCOMTrans :: DoActualConnection

En resumen, xperf es llamado por Wbem y, por lo tanto, está bloqueado por este problema. xperf intenta detener el rastreo antes de iniciarlo, porque agregué este comportamiento para que el inicio del rastreo sea más tolerante a fallas . Sospecho que aún se produciría un bloqueo, pero no estoy seguro.

Creamos gráficos de complejidad computacional.

Me di cuenta de que WinMgmt.exe escanea el directorio c: \ windows \ System32 \ wbem \ Repository , que tiene 1.9 GB en mi máquina, por lo que pedí en el trabajo y en Twitter que dijera cuánto tarda este directorio en obtener puntos de datos. También le pedí a la gente que arreglara el tiempo de ejecución de winmgmt.exe / verificadorepository y comencé a programar. Aunque estas pruebas se llevaron a cabo en máquinas completamente diferentes con diferentes velocidades de CPU, el gráfico resultó ser bastante claro:


La relación entre la raíz cuadrada del tiempo y el tamaño del repositorio

Este gráfico de la relación de sqrt (tiempo) al tamaño del repositorio es increíblemente ideal para los datos recibidos de seis máquinas diferentes y, sin embargo, es real. Obviamente, la función VerifyRepository tiene un rendimiento O (n ² ). Si n es el tamaño del directorio del repositorio en GB , entonces VerifyRepository demora aproximadamente 1.6 * n ² minutos. Esta es una buena estimación aproximada para todos los valores, desde una fracción de segundo hasta diez minutos.

Relevancia

O tengo suerte o solo estoy atento, porque durante un par de semanas ya nadie ha encontrado este problema; pensé que cosas extrañas estaban sucediendo con mi automóvil. Pero de repente comencé a escuchar quejas sospechosamente similares de colegas. Uno de ellos tenía un repositorio de 2.6 GB, que tardó diez minutos en verificar. El problema afectó a algunos de nuestros desarrolladores de CI y, en diferentes grados, a otras personas diferentes. Mis colegas generalmente saben que en caso de problemas con el rendimiento de las máquinas con Windows, tengo que decirme esto, sin embargo, probablemente hay muchos otros empleados de Google que trabajan con Windows que se ven impedidos por este error, pero no se dan cuenta de esto.

Afortunadamente, ya he comenzado a trabajar con nuestro departamento de TI. Encontré el script que lanzó WinMgmt y descubrí que se ejecuta cada hora. Esto significaba que mi máquina estaba ejecutando WinMgmt.exe / verificadorepository el 10% del tiempo, y algunos de mis colegas tenían más del 16% del tiempo. Hay una probabilidad bastante alta de obtener un retraso de diez minutos antes del montaje.

Para cuando comenzaron a llegar los informes, la solución ya estaba en camino a la producción. El script era opcional, y ciertamente no valía la pena por los problemas que causó, por lo que la solución fue desactivar su llamada.

Resumen

winmgmt.exe / verifiedrepository contiene un ciclo de nueve instrucciones, cuyo número de iteraciones de ejecución es proporcional al cuadrado del tamaño del repositorio wbem . Debido a esto, la ejecución del comando puede tomar hasta diez minutos, aunque en realidad debería ejecutarse en solo unos segundos. Esto es malo en sí mismo.

Pero aún peor, el equipo realiza un bloqueo WMI ( Instrumental de administración de Windows ) durante su operación, por lo que cualquier proceso que realice operaciones WMI se congelará.

Acertijos increíbles

El script que ejecutaba winmgmt.exe / verificadorepository cada hora hizo esto durante muchos años, pero el comportamiento problemático comenzó a aparecer hace solo uno o dos meses. Presumiblemente, esto significa que el repositorio wbem se ha vuelto mucho más grande recientemente. Los retrasos a 0.5 GB se pasan por alto fácilmente, pero a partir de 1.0 GB y más ya pueden forzar. Como se sugirió en Twitter, ejecuté strings.exe para el archivo objects.data . Muchas de las cadenas más comunes contienen polmkr en el nombre, pero no sé qué significa eso.

Publiqué un informe de error en Twitter , y al principio causó algunos movimientos del equipo de WMI , pero luego dejé de recibir respuestas, por lo que no sé cuál es la situación ahora.

Me gustaría ver una solución para el problema de rendimiento, y me gustaría que nuestro departamento de TI pueda encontrar y solucionar el problema que hace que nuestros repositorios wbem sean tan grandes. Pero por ahora, el departamento de TI ha prometido no ejecutar el comando / verifique el repositorio cada hora más, lo que debería ayudarnos a evitar los peores síntomas.

Referencias

• Una lista general de tutoriales, investigaciones y documentación de ETW está disponible aquí: https://tinyurl.com/etwcentral
• El tutorial sobre el uso de la CPU (muestreado) (para averiguar en qué se dedica el tiempo de la CPU) está aquí , y la documentación está aquí.
• El tutorial de Uso de CPU (Preciso) (para encontrar las razones por las que no se pueden ejecutar hilos) está aquí , y la documentación está aquí.
• Los enlaces a artículos individuales se encuentran en el cuerpo de la publicación, también puede encontrarlos en mi categoría Investigar informes
• Otras historias sobre algoritmos O (n ² ) se pueden leer en Accidentally Quadratic

Una discusión del artículo sobre Reddit está aquí , una discusión sobre noticias de hackers está aquí , un hilo en Twitter está aquí, y posiblemente aquí