Come eseguire il debug/analizzare pause di GC estremamente lunghe in Node.js/V8

Question

Sto cercando di analizzare un problema di memoria/GC in un'app server Node.js relativamente complessa. Anche sotto carico molto moderato, sta diventando insensibile per periodi notevoli e queste pause si allungano nel tempo. L'esecuzione con il parametro --trace-gc dimostra che i tempi di raccolta dei rifiuti estremamente lunghi sono la causa più probabile:

[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 piena (--trace-gc-verbose) uscita può essere trovato here.

Questi registri sono il risultato di esecuzione il server con i seguenti parametri:

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

Quanto più a lungo si corre, più a lungo le pause diventano (spesso diversi minuti), fino a che alla fine si blocca completamente dopo un paio di ore. La memoria disponibile non si esaurisce mai e l'RSS non si avvicina nemmeno al limite di spazio vecchio di 1000mb, quindi non sembra essere una perdita. Mi sembra che ci potrebbe essere qualcosa di piuttosto insolito all'interno del codice, che rende molto "difficile" per il GC fare il suo lavoro in tempi accettabili.

La mia domanda è: come posso analizzare ulteriormente questo problema e restringere le possibili cause? Qualche strumento raccomandabile per aiutare con problemi come questo? Sono essenzialmente alla ricerca di un approccio più efficiente rispetto alla disattivazione ingenua e su parti del codice, che sono estremamente macchinose e richiedono molto tempo.

Per inciso, gradirei molto i collegamenti a qualsiasi documentazione che spieghi i termini/messaggi utilizzati nell'output di debug GC (come "limite di promozione raggiunto") e i numeri elencati qui. Ho una comprensione molto basilare di come funziona il V8 GC (this ha aiutato molto), ma la maggior parte di quell'uscita è ancora oltre me.

Nel caso sia importante: è in esecuzione su Node.js v0.10.33 su Ubuntu 14.04 Server.

EDIT: Qualche tempo fa siamo passati a io.js, dove questo problema semplicemente non si verifica più (presumibilmente a causa della recente versione molto più V8). Non ho mai trovato la causa di questo problema con Nodo v0.10, per non parlare di una soluzione.

Answer 1

Sei in grado di riprodurre il problema su un singolo nodo? Penso che se ero nella situazione avrei probabilmente fare un mix delle seguenti operazioni:

• Scrivi un caricatore che mi permetta di replicare in un'istanza locale
• In caso contrario, metto un caso in pungolo che riceverà un sottoinsieme di traffico e modificarlo per eseguire il seguente
• Aggiungi node-heapdump all'origine, chiamarlo a intervalli e esportare i risultati in un file JSON in N intervalli di minuti.
• Potenzialmente, se stai eseguendo localmente potresti anche essere in grado di sfruttare memwatch.
• Attendere il lento avvio del GC.
• Afferra un numero di discariche di heap in un momento in cui sai che il GC lento ha iniziato a verificarsi.
• caricarli su nel Chrome e analizzarli utilizzando il three snap shot technique (suppongo che si potrebbe chiamare questa la tecnica snapshot N nel nostro caso)

In sostanza, si caricare i cumuli e cominciare a guardare attraverso di loro per cercare di capisci che tipo di cosa si sta accumulando, che cosa lo trattiene e di conseguenza capirai perché GC impiega così tanto tempo.

La memoria disponibile non si esaurisce mai e l'RSS non si avvicina nemmeno al limite di spazio vecchio 1000mb, quindi non sembra essere una perdita. Mi sembra che ci potrebbe essere qualcosa di piuttosto insolito all'interno del codice, che rende molto "difficile" per il GC fare il suo lavoro in tempi accettabili.

Qui puoi cercare alberi di mantenimento lunghi e circolari. Ma alla fine della giornata anche questo è il caso dovresti essere in grado di identificare qual è la radice di quell'albero, cosa contiene e sperimentare i modi per ridurre la rimozione.

Sono anche d'accordo con @dandavis e sospetti chiusure.

Answer 2

Questa risposta potrebbe non essere specifica come vorresti, ma ti suggerisco di guardare lo good package che fa parte del framework hapi.js di Walmart. Fa un grande lavoro di estendere la registrazione oltre --trace-gc. Si tratta di un monitor di processo che ascolta per uno o più dei seguenti eventi:

• ops - Sistema e prestazioni dei processi - CPU, memoria, disco e altre metriche.
• response - Informazioni sulle richieste in entrata e sulla risposta. Questo programma si riferisce all'evento "response" o "tail" emesso dai server hapi.
• log - informazioni di registrazione non associate a una richiesta specifica come errori di sistema, elaborazione in background, errori di configurazione, ecc. Mappe per l'evento "log" emesso dai server hapi.
• error - richiede le risposte che hanno un codice di stato di 500. Questo programma all'evento hapi "richiesta-errore".
• request - Richiesta informazioni di registrazione. Questo programma si riferisce all'evento 'request' di hapi che viene emesso tramite request.log().

Si dovrebbe inserire la libreria Hapi affinché funzioni, ma potrebbe valerne la pena temporaneamente ai fini del debug. In generale consiglio vivamente Hapi di ridimensionare le app Node.js, i ragazzi di Walmart hanno fatto cose sorprendenti con esso nell'ultimo anno.