Fehlerbehebung bei hohem Speicherverbrauch von NodeJs, tatsächlicher Kampfrekord

Vorwort

Dies ist eine Untersuchung, die durch die Erweiterung eines Online-Containers verursacht wurde. Obwohl sich schließlich herausstellte, dass es nicht durch das echte OOM verursacht wurde, habe ich den Untersuchungsprozess dennoch zusammengefasst und aufgezeichnet. Der gesamte Prozess war wie das Lösen eines Falls, bei dem Schritt für Schritt nach Hinweisen gesucht und die Ergebnisse Schritt für Schritt überprüft wurden.

Ich persönlich denke, dass die Bedeutung und Notwendigkeit dieses Vorgehens aus mehreren Gründen gegeben ist:

1. Aus Sicht des Programmierers: Streben Sie nach Code-Perfektion, lassen Sie Probleme nicht los und sorgen Sie für die Stabilität des Geschäfts
2. Aus Ressourcensicht: Es geht darum, den sinnlosen Ressourcenverbrauch zu reduzieren
3. Aus Unternehmenssicht: Reduzierung der Serverkosten und Kosteneinsparung für das Unternehmen
   

Umgebung: NodeJs-Dienst, der auf der Tencent Taf-Plattform läuft.

Ursache des Problems

Zunächst lag es daran, dass nach dem Start einer Timing-Funktion der Online-Container automatisch erweitert wurde. Da der NodeJs-Dienst selbst nur einige Schnittstellenabfragen und socket.io-Funktionen hat und weder großer Datenverkehr noch hohe Parallelität herrscht, muss ein Dienst tatsächlich auf 8 Container erweitert werden (einem Container werden 2 GB Speicher zugewiesen). Als ich daran dachte, vermutete ich einen Speicherverlust. Gleichzeitig wird im Protokoll gelegentlich ein Speichermangel angezeigt.

Gründe für die Erweiterung

Nach Rücksprache mit dem Betriebs- und Wartungspersonal fand ich heraus, dass die Erweiterung dadurch verursacht wurde, dass die Speichernutzung den kritischen Wert erreichte.

Lastbedingungen

Zunächst müssen wir die Möglichkeit ausschließen, dass der erhöhte Speicherverbrauch durch übermäßigen Servicedruck verursacht wird. Dies kann ein normales Geschäftsphänomen sein.

Durch die Überwachung haben wir festgestellt, dass der Datenverkehr und die CPU-Auslastung nicht sehr hoch sind und sogar als sehr niedrig bezeichnet werden können. Daher ist eine so hohe Speicherauslastung ein abnormales Phänomen.

Da es durch Speicherprobleme verursacht wird und das Phänomen einer allmählichen und kontinuierlichen Zunahme auftritt, denken wir an einen Speicherverlust. Die gängige Vorgehensweise besteht darin, einen „Heap-Snapshot“ oder eine Heapsnapshot-Datei zu drucken.

Geben Sie den Container ein:

Gehen Sie zum Knotennamen

Geben Sie den NodeJs-Projektordner ein

/usr/local/app/taf/service_name/bin/src

Erstellen Sie einen Snapshot:

const heapdump = erfordern('heapdump');
heapdump.writeSnapshot('./' + neues Date().getTime() + '.heapsnapshot', Funktion(err, Dateiname) {
    console.log('Dump geschrieben in', Dateiname);
});

Aufgrund der langsamen Geschwindigkeit beim direkten Übertragen von Dateien im Container mit dem Befehl lrzsz ist es erforderlich, sie mit dem Befehl scp auf einen statischen Ressourcenserver zu übertragen, der über den Browser heruntergeladen werden kann.

scp 1620374489828.heapsnapshot Benutzername@IP:/data/static/snapshot

Heapsnapshot vergleichen

Nachdem der Dienst gestartet wurde und eine Zeit lang ausgeführt wurde, werden zwei Snapshots generiert. Nach dem Vergleich sind nur Schlüsselwörter wie Websocket Socket grob zu sehen.

Ob eine bestimmte Funktion die Ursache ist, lässt sich bei weiterer Vergrößerung nicht feststellen.

Im Snapshot scheint es keine Hinweise zu geben. Da der Geschäftscode des gesamten Projekts nicht sehr groß ist, haben wir ihn Zeile für Zeile überprüft, aber es scheint keine abnormale Schreibweise zu geben, die OOM verursachen würde. Tatsächlich ist es in Ordnung, wenn der Geschäftscode klein ist. Wenn es sich um ein großes Projekt handelt, ist dieser Ansatz nicht kosteneffizient und es ist immer noch erforderlich, einige Diagnosemethoden zur Überprüfung zu verwenden, anstatt direkt zur Codeüberprüfung überzugehen.

Nachdem ich die Snapshots mehrmalig ausgedruckt und mehrmalig gelesen hatte, sah ich immer noch die Worte „WebSocket“, daher fragte ich mich, ob das Problem dadurch verursacht wurde, dass die Socket-Verbindung nicht freigegeben wurde?

Ich habe bei Google nach WebSocket-Speicherlecks gesucht und es gibt sie wirklich. Die Lösung besteht darin, perMessageDeflate hinzuzufügen und die Komprimierung zu deaktivieren. Derzeit ist die niedrigere Version von Socket-IO standardmäßig aktiviert. Ich habe sie also hinzugefügt und den Speicherverbrauch eine Weile beobachtet. Es gab keinen offensichtlichen Rückgang. Nach der Veröffentlichung war der Speicherverbrauch immer noch sehr hoch.

Konfigurationssyntax:

erfordern('socket.io').listen(server, {perMessageDeflate: false});

Die vom Client gesendete Anfrage enthält dieses Feld:

Zunächst wird dieser Parameter zum Komprimieren von Daten verwendet. Er ist standardmäßig auf der Clientseite aktiviert und auf der Serverseite deaktiviert. Aus bestimmten Gründen führt die Aktivierung zu Speicher- und Leistungsverbrauch. Die offizielle Empfehlung lautet, dies zu berücksichtigen, bevor Sie entscheiden, ob Sie es aktivieren. Allerdings sind die niedrigeren Versionen von Socket-IO aktiviert, z. B. Version ^2.3.0 (es scheint sich um einen Fehler zu handeln, und nachfolgende Versionen wurden so geändert, dass sie standardmäßig geschlossen sind).

Die Erweiterung ist auf dem Server standardmäßig deaktiviert und auf dem Client standardmäßig aktiviert. Sie verursacht einen erheblichen Mehraufwand in Bezug auf Leistung und Speicherverbrauch. Wir empfehlen daher, sie nur zu aktivieren, wenn sie wirklich benötigt wird.

https://github.com/socketio/socket.io/issues/3477#issuecomment-610265035

Nach dem Einschalten bleibt der Speicherverbrauch hoch.

console.log

Ein weiteres Phänomen ist, dass der vorhandene Node-Dienst einige Protokolle druckt. Ich habe im Internet einige Artikel über NodeJs-Speicherlecks durchgesehen und Lecks gefunden, die durch die Ausgabe von Konsolenprotokollen verursacht wurden. Also habe ich die Konsole auskommentiert und die Speichernutzung weiter beobachtet. Das Ergebnis war immer noch eine hohe Speichernutzung.

Hier scheinen die Hinweise zu enden, und es gibt keinen Hinweis mehr.

Protokoll

Einen Tag später habe ich mir versehentlich die Protokolldatei angesehen. Da beim Starten des Dienstes einige Startprotokolle gedruckt werden, stellte ich fest, dass es wiederholte Ausgaben gibt:

Dies deutet darauf hin, dass das System wiederholt ausgeführt wird. Um diese Hypothese zu überprüfen, verwenden Sie den Befehl top, um die Ergebnisse anzuzeigen.

TOP-Befehl

Gleichzeitig möchte ich auch die spezifische Speichernutzung sehen. Ich habe festgestellt, dass es so viele Arbeitsprozesse gibt. Sollten angesichts der tatsächlichen Nutzung im aktuellen Geschäft nicht nur 2 bis 4 ausreichen? Warum müssen wir so viele untergeordnete Prozesse öffnen?

PID USER PR NI VIRT RES SHR S %CPU %MEM ZEIT+ BEFEHL                                                                                                                       
 90359 Benutzername 20 0 736 m 38 m 14 m S 0,0 0,0 0:07.30 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90346 Benutzername 20 0 864 m 38 m 14 m S 0,3 0,0 0:07.08 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90381 Benutzername 20 0 730 m 38 m 14 m S 0,3 0,0 0:08,75 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90366 Benutzername 20 0 804 m 37 m 14 m S 0,0 0,0 0:06.94 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90618 Benutzername 20 0 730 m 37 m 14 m S 0,0 0,0 0:08.42 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90326 Benutzername 20 0 736 m 37 m 14 m S 0,0 0,0 0:08.46 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90542 Benutzername 20 0 736 m 37 m 14 m S 0,0 0,0 0:08,85 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90332 Benutzername 20 0 799 m 37 m 14 m S 0,0 0,0 0:07.32 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90580 Benutzername 20 0 732 m 37 m 14 m S 0,3 0,0 0:08.94 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90602 Benutzername 20 0 731 m 37 m 14 m S 0,3 0,0 0:08.33 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90587 Benutzername 20 0 735 m 37 m 14 m S 0,0 0,0 0:08,83 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90568 Benutzername 20 0 731 m 37 m 14 m S 0,0 0,0 0:08.83 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90544 Benutzername 20 0 729 m 37 m 14 m S 0,0 0,0 0:09.07 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90556 Benutzername 20 0 729 m 37 m 14 m S 0,0 0,0 0:08.82 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90431 Benutzername 20 0 735 m 37 m 14 m S 0,0 0,0 0:08.29 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90486 Benutzername 20 0 729 m 37 m 14 m S 0,0 0,0 0:09.06 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90516 Benutzername 20 0 735 m 37 m 14 m S 0,0 0,0 0:08,95 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90465 Benutzername 20 0 729 m 37 m 14 m S 0,0 0,0 0:09.06 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90527 Benutzername 20 0 735 m 37 m 14 m S 0,0 0,0 0:08.46 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90487 Benutzername 20 0 732 m 37 m 14 m S 0,3 0,0 0:08.48 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90371 Benutzername 20 0 731 m 37 m 14 m S 0,3 0,0 0:08,75 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90423 Benutzername 20 0 729 m 36 m 14 m S 0,3 0,0 0:08.09 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90402 Benutzername 20 0 729 m 36 m 14 m S 0,3 0,0 0:08,96 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90500 Benutzername 20 0 729 m 36 m 14 m S 0,0 0,0 0:08.70 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90353 Benutzername 20 0 729 m 36 m 14 m S 0,3 0,0 0:08,95 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90636 Benutzername 20 0 729 m 36 m 14 m S 0,0 0,0 0:08.84 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90425 Benutzername 20 0 732 m 36 m 14 m S 0,0 0,0 0:08.78 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90506 Benutzername 20 0 729 m 36 m 14 m S 0,0 0,0 0:08.84 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90589 Benutzername 20 0 729 m 36 m 14 m S 0,3 0,0 0:09.05 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90595 Benutzername 20 0 729 m 36 m 14 m S 0,0 0,0 0:09.03 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90450 Benutzername 20 0 729 m 36 m 14 m S 0,3 0,0 0:08,97 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90531 Benutzername 20 0 729 m 36 m 14 m S 0,0 0,0 0:08,99 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90509 Benutzername 20 0 735 m 36 m 14 m S 0,0 0,0 0:08,67 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90612 Benutzername 20 0 730 m 36 m 14 m S 0,3 0,0 0:08.84 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90479 Benutzername 20 0 729 m 36 m 14 m S 0,0 0,0 0:08.58 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90609 Benutzername 20 0 731 m 36 m 14 m S 0,3 0,0 0:09.23 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90404 Benutzername 20 0 734 m 36 m 14 m S 0,3 0,0 0:08.78 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90395 Benutzername 20 0 736 m 36 m 14 m S 0,0 0,0 0:08.57 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90444 Benutzername 20 0 729 m 36 m 14 m S 0,0 0,0 0:09.04 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90438 Benutzername 20 0 729 m 36 m 14 m S 0,3 0,0 0:07,78 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90340 Benutzername 20 0 736 m 36 m 14 m S 0,3 0,0 0:07.37 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90333 Benutzername 20 0 729 m 36 m 14 m S 0,0 0,0 0:07.60 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90563 Benutzername 20 0 735 m 36 m 14 m S 0,3 0,0 0:08,93 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90565 Benutzername 20 0 734 m 36 m 14 m S 0,3 0,0 0:08.77 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90457 Benutzername 20 0 735 m 36 m 14 m S 0,0 0,0 0:08.31 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90387 Benutzername 20 0 740 m 36 m 14 m S 0,0 0,0 0:07.59 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90573 Benutzername 20 0 728 m 35 m 14 m S 0,0 0,0 0:09.06 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90472 Benutzername 20 0 728 m 35 m 14 m S 0,0 0,0 0:08.94 /usr/local/app/service_name/bin/src/index.js: Arbeitsprozess                                                      
 90313 Benutzername 20 0 588 m 27 m 13 m S 0,0 0,0 0:00.46 /usr/local/app/service_name/bin/src/index.js: Masterprozess

Da der Wert in der Spalte %MEM nicht die spezifische Speichernutzung innerhalb des Containers anzeigt und immer als 0,0 angezeigt wird, müssen Sie die Werte VIRT, RES und SHR überprüfen. Ihre Bedeutung finden Sie hier: https://www.orchome.com/298

Uns interessiert eher RES. RES bezeichnet die Größe des Teils des virtuellen Speicherbereichs des Prozesses, der dem physischen Speicherbereich zugeordnet wurde. Daher können wir feststellen, dass ein Worker-Prozess eine Speichergröße zwischen 35 und 38 MB belegt. Es gibt 48 Worker-Prozesse und einen Master-Prozess.

Wie sind die 48 Arbeitsprozesse entstanden? Durch Abfragen der logischen Anzahl der CPUs können wir feststellen, dass es tatsächlich 48 sind.

# Gesamtzahl der Kerne = Anzahl der physischen CPUs x Anzahl der Kerne pro physischer CPU # Gesamtzahl der logischen CPUs = Anzahl der physischen CPUs x Anzahl der Kerne pro physischer CPU x Anzahl der Hyperthreads # Anzahl der physischen CPUs anzeigen cat /proc/cpuinfo | grep "physical id" | sort | uniq | wc -l

# Zeigen Sie die Anzahl der Kerne in jeder physischen CPU an (d. h. die Anzahl der Kerne)
cat /proc/cpuinfo| grep "CPU-Kerne"| uniq

# Anzahl der logischen CPUs anzeigen cat /proc/cpuinfo | grep "processor" | wc -l

Kontrollieren Sie die Anzahl der Prozesse

Da ich mit der Taf-Plattform nicht sehr vertraut bin, habe ich erfahren, dass zum Ausführen von NodeJS auf Taf das entsprechende Paket erforderlich ist: @tars/node-agent. Ich habe die Nutzungsdokumentation auf der offiziellen Website überprüft: https://tarscloud.github.io/TarsDocs/dev/tars.js/tars-node-agent.html

Es gibt eine -i-Konfiguration, die für Instanzen steht

-i, --instances

Node-Agent verwendet das native Cluster-Modul von Node.js, um einen Lastenausgleich zu erreichen.

Sie können die Anzahl der vom Node-Agent gestarteten Unterprozesse (Geschäftsprozesse) hier konfigurieren:

Wenn nicht konfiguriert (oder auf „auto“ oder „0“ konfiguriert), entspricht die Anzahl der gestarteten untergeordneten Prozesse der Anzahl der physischen CPU-Kerne.

Bei der Konfiguration als „max“ entspricht die Anzahl der gestarteten untergeordneten Prozesse der Anzahl der CPUs (aller Kerne).

Wenn der Node-Agent von Tarsnode gestartet wird, wird der Konfigurationsabschnitt tars.application.client.asyncthread in der TARS-Konfigurationsdatei automatisch gelesen.

Sie können es auch über die TARS-Plattform anpassen -> Dienst bearbeiten -> Anzahl asynchroner Threads.

https://tarscloud.github.io/TarsDocs/dev/tars.js/tars-node-agent.html
Verwenden Sie dieses Paket, um den NodeJs-Dienst auf Taf zu starten und die Lastausgleichsfunktion zu aktivieren. Da die spezifische Anzahl der untergeordneten Prozesse (Geschäftsprozesse) nicht konfiguriert ist, wird standardmäßig die Anzahl der physischen CPU-Kerne verwendet. Da 2 CPUs vorhanden sind, multiplizieren Sie diese mit 2, und es werden insgesamt 48 Arbeitsprozesse generiert. Jeder Arbeitsprozess belegt Speicher, sodass die Speichernutzung hoch bleibt.

Sie können die Konfiguration im „Private Template“ ändern:

Starten Sie anschließend den Dienst neu und überprüfen Sie die Speichernutzung:

Es ist ersichtlich, dass die Anzahl der Arbeitsprozesse die Speichernutzung beeinflusst. Das ursprüngliche Trenddiagramm der Speichernutzung wird weiter wachsen (deshalb vermutete ich am Anfang Speicherlecks). Dieses Problem trat nach der Reduzierung der Anzahl der Arbeitsprozesse nicht mehr auf. Ignorieren Sie es vorerst und beobachten Sie es später weiter.

Um die Beziehung zwischen der doppelten Konsole und dem Arbeitsprozess zu überprüfen, haben wir zwei Arbeitsprozesse gestartet und die Protokolle überprüft. Dabei stellte sich heraus, dass die Protokolle tatsächlich zweimal gedruckt wurden.

Zusammenfassen

Lassen Sie uns dieses Problem noch einmal durchgehen:

Warum wurde es nicht rechtzeitig entdeckt?

Dies kann mit der Rolle der Front-End-Entwickler zusammenhängen, die für manche Funktionen der Back-End-Dienste nicht besonders sensibel sind. Ich habe nicht darauf geachtet oder ich kenne bzw. verstehe es nicht.

Kann es im Voraus vermieden werden?

Es kann einen ähnlichen Alarmmechanismus geben, der darauf hinweist, dass der Speicher des Node-Dienstes einen Aufwärtstrend aufweist. Ich bin mit den Funktionen der Taf-Plattform noch nicht vertraut und werde sie später erkunden.

Dies ist das Ende dieses Artikels zur Fehlerbehebung bei hohem Speicherverbrauch in NodeJs. Weitere Informationen zum hohen Speicherverbrauch in NodeJs finden Sie in früheren Artikeln auf 123WORDPRESS.COM oder in den folgenden verwandten Artikeln. Ich hoffe, Sie werden 123WORDPRESS.COM auch in Zukunft unterstützen!