javascript - que - Cómo depurar/analizar pausas de GC extremadamente largas en Node.js/V8

node js tutorial

Question

Estoy tratando de analizar un problema de memoria / GC en una aplicación de servidor Node.js relativamente compleja. Incluso bajo una carga muy moderada, deja de responder por períodos perceptibles, y estas pausas crecen con el tiempo. La ejecución con el parámetro --trace-gc muestra que los tiempos de recolección de basura extremadamente largos son la causa probable:

[4805]      537 ms: Mark-sweep 17.6 (46.4) -> 10.3 (47.4) MB, 20 ms [allocation failure] [GC in old space requested].
[4805]     1338 ms: Mark-sweep 31.3 (58.4) -> 19.2 (57.2) MB, 40 ms [allocation failure] [promotion limit reached].
[4805]     2662 ms: Mark-sweep 58.0 (79.2) -> 43.9 (85.2) MB, 109 ms [Runtime::PerformGC] [promotion limit reached].
[4805]     4014 ms: Mark-sweep 90.1 (111.5) -> 70.6 (113.9) MB, 114 ms [allocation failure] [promotion limit reached].
[4805]     7283 ms: Mark-sweep 129.7 (153.9) -> 112.0 (158.9) MB, 511 ms [allocation failure] [promotion limit reached].
[4805]    10979 ms: Mark-sweep 184.6 (210.9) -> 160.3 (212.9) MB, 422 ms [Runtime::PerformGC] [promotion limit reached].
[4805]  1146869 ms: Mark-sweep 243.8 (271.4) -> 191.6 (267.9) MB, 1856 ms [allocation failure] [promotion limit reached].
[4805]  1731440 ms: Mark-sweep 282.1 (307.4) -> 197.5 (298.9) MB, 1 / 11230 ms [allocation failure] [promotion limit reached].
[4805]  2024385 ms: Mark-sweep 291.0 (320.8) -> 197.3 (306.9) MB, 9076 ms [Runtime::PerformGC] [promotion limit reached].
[4805]  2623396 ms: Mark-sweep 290.9 (317.1) -> 196.9 (311.9) MB, 1 / 15401 ms [allocation failure] [promotion limit reached].
[4805]  3223769 ms: Mark-sweep 291.4 (323.6) -> 187.8 (318.9) MB, 1 / 13385 ms [allocation failure] [promotion limit reached].
[4805]  4225777 ms: Mark-sweep 280.1 (324.2) -> 190.6 (315.9) MB, 1 / 13266 ms [allocation failure] [promotion limit reached].
[4805]  4705442 ms: Mark-sweep 286.2 (321.4) -> 195.2 (314.9) MB, 1 / 17256 ms [Runtime::PerformGC] [promotion limit reached].
[4805]  5225595 ms: Mark-sweep 288.3 (324.0) -> 201.7 (316.9) MB, 1 / 22266 ms [Runtime::PerformGC] [promotion limit reached].
[4805]  6127372 ms: Mark-sweep 296.5 (324.6) -> 200.5 (316.9) MB, 1 / 28325 ms [allocation failure] [promotion limit reached].
[4805]  6523938 ms: Mark-sweep 297.8 (328.9) -> 198.8 (323.9) MB, 1 / 27213 ms [allocation failure] [promotion limit reached].
[4805]  7355394 ms: Mark-sweep 292.1 (330.7) -> 223.9 (322.9) MB, 60202 ms [allocation failure] [promotion limit reached].

La --trace-gc-verbose completa ( --trace-gc-verbose ) se puede encontrar here .

Estos registros son el resultado de ejecutar el servidor con los siguientes parámetros:

--expose-gc --trace-gc --trace-gc-verbose --trace-gc-ignore-scavenger --max-old-space-size=1000

Cuanto más se prolonga, más largas son las pausas (a menudo, varios minutos), hasta que finalmente se bloquea completamente después de un par de horas. La memoria disponible nunca se agota, y el RSS ni siquiera se acerca al límite de espacio de 1000 mb, por lo que no parece haber una fuga. Me parece que podría haber algo bastante inusual dentro del código, lo que hace que sea muy difícil que el GC haga su trabajo en marcos de tiempo aceptables.

Mi pregunta es: ¿Cómo hago para analizar más a fondo este problema y para reducir las posibles causas? ¿Alguna herramienta recomendable para ayudar con problemas como este? Básicamente, estoy buscando un enfoque más eficiente que apagar y encender ingenuamente partes del código, lo cual es extremadamente engorroso y requiere mucho tiempo.

Como nota aparte, agradecería enormemente los enlaces a cualquier documentación que explique los términos / mensajes utilizados en la salida de depuración del GC (como "límite de promoción alcanzado") y los números que figuran allí. Tengo una comprensión muy básica de cómo funciona el V8 GC ( this ayudó mucho), pero la mayor parte de esa salida aún está fuera de mi alcance.

En caso de que importe: Esto se ejecuta en Node.js v0.10.33 en Ubuntu 14.04 Server.

EDITAR: Hace un tiempo pasamos a io.js, donde este problema simplemente ya no ocurre (probablemente debido a la versión V8 mucho más reciente). Aunque nunca encontré la causa de este problema con Node v0.10, y mucho menos una solución.

Answer 1

¿Puede reproducir el problema en un solo nodo? Creo que si estuviera en la situación, probablemente haría una mezcla de lo siguiente:

• Escribe un cargador que me permita replicar en una instancia local
• Si no, coloque una instancia en prod que recibirá un subconjunto de tráfico y modifíquelo para hacer lo siguiente
• Agregue node-heapdump a su fuente, node-heapdump en un intervalo y exporte los resultados a un archivo json en intervalos de N minutos.
• Potencialmente, si está ejecutando localmente, también puede aprovechar el memwatch .
• Espere a que el GC lento comience.
• Agarre una serie de volcados de almacenamiento dinámico en un momento en el que sabe que comenzó a producirse una GC lenta.
• Cárguelos en cromo y analícelos utilizando la técnica de tres instantáneas (supongo que podría llamar a esto la técnica de instantáneas N en nuestro caso)

Básicamente, cargarás los montones y comenzarás a mirarlos para tratar de entender qué tipo de cosas se están acumulando, qué están conteniendo y, como resultado, comprenderás por qué GC tarda tanto.

La memoria disponible nunca se agota, y el RSS ni siquiera se acerca al límite de espacio de 1000 mb, por lo que no parece haber una fuga. Me parece que podría haber algo bastante inusual dentro del código, lo que hace que sea muy difícil que el GC haga su trabajo en marcos de tiempo aceptables.

Aquí usted puede estar buscando árboles de retención largos y circulares. Pero al final del día, incluso en ese caso, debería poder identificar cuál es la raíz de ese árbol, qué hay en él y experimentar con formas de reducir la eliminación.

También estoy de acuerdo con @dandavis y sospechosos de cierres.

Answer 2

Es posible que esta respuesta no sea tan específica como le gustaría, pero sugeriría ver el buen paquete que forma parte del marco de trabajo de Walmart hapi.js. Hace un gran trabajo extendiendo el registro más allá de --trace-gc . Es un monitor de proceso que escucha uno o más de los siguientes eventos:

• ops : rendimiento del sistema y del proceso: CPU, memoria, disco y otras métricas.
• response - Información sobre las solicitudes entrantes y la respuesta. Esto se asigna al evento de "respuesta" o "cola" emitido por los servidores hapi.
• log : la información de registro no está vinculada a una solicitud específica, como errores del sistema, procesamiento en segundo plano, errores de configuración, etc. Se asigna al evento "registro" emitido desde los servidores de Hapi.
• error : solicite respuestas que tengan un código de estado de 500. Esto se asigna al evento hapi "error de solicitud".
• request - Solicite información de registro. Esto se asigna al evento hapi ''request'' que se emite a través de request.log() .

Tendría que Hapi biblioteca de Hapi para que esto funcione, pero puede valer la pena temporalmente para fines de depuración. En general, recomiendo Hapi para escalar las aplicaciones de Node.js, los chicos de Walmart han estado haciendo cosas increíbles con él durante el último año.