- In einer 10 Jahre alten Rails-Produktions-App stieg der Speicher des
web-Dynos während eines Deployments stark an; da der Service dauerhaft 400–500 req/s und in Spitzen mehrere tausend req/s verarbeitete, war eine schnelle Eindämmung nötig.
- Auf Heroku wurden Dynos neu gestartet, die nahe an die Speichergrenze kamen, und Änderungen an Code und Metriken der letzten drei Tage zurückgenommen, doch das Speicherleck blieb bestehen.
- Während Sidekiq und Delayed::Job unauffällig waren, zeigte sich das Muster, dass nur einige Puma-Worker anwuchsen, was auf einen Zusammenhang mit einer bestimmten Art von Traffic hindeutete.
- Das Nachverfolgen des Heaps mit
rbtrace, ObjectSpace, heapy, sheap und reap zeigte, dass ein Puma-Request-Handling-Thread über das @children-Array von ActiveSupport::Notifications::Event 32.067 Objekte und 1,9 GiB Speicher festhielt.
- Manipulierte Query-Parameter lösten im URL-Bereinigungsprozess von Bugsnag einen
URI::InvalidURIError aus; die kurzfristige Maßnahme war ein Bugsnag-Upgrade, die langfristige ein Rails-Upgrade.
In einer laufenden Rails-App begann ein Leak
- Betroffen war eine Rails-App, die seit 10 Jahren existierte und ein produktiver Service mit realem Umsatz war.
- Die normale Dauerlast lag bei 400–500 req/s, Spitzen gingen bis auf mehrere tausend Requests pro Sekunde.
- Während eines gewöhnlichen Deployment-Ablaufs begann ein Speichersprung, und der Pager löste Alarm aus.
- Da die App auf Heroku lief, wurde der Zustand anhand der Speichernutzung pro Dyno beurteilt.
Die Störungsbegrenzung begann mit Dyno-Neustarts
- Das Verhalten sah nicht nach einfacher Speicheraufblähung (bloat), sondern nach einem Leak aus; die temporäre Lösung war ein Prozessneustart.
- Zwar starteten die täglichen mehrfachen Deployments die
web-Instanzen ohnehin regelmäßig neu, aber Dynos nahe am Speicherlimit wurden zusätzlich manuell neu gestartet.
Auch nach dem Zurücknehmen verdächtiger Änderungen blieb das Leak
- Ausgehend vom Zeitpunkt kurz vor dem ersten großen Spike wurden drei Tage Codeänderungen geprüft.
- Drei Änderungen erschienen möglicherweise relevant:
- eine Änderung, die im Modus
development wegen Rails-Code-Reloading ein Speicherleck verursachte
- eine Änderung, durch die bei bestimmtem Request-Filtering mehr Redis-Aufrufe als beabsichtigt entstanden
- eine N+1-artige Änderung, die mehr Datenbankaufrufe und das Laden von
ActiveRecord-Instanzen verursachte
- Die ersten beiden Änderungen wurden korrigiert, die dritte zurückgerollt und dann einzeln ausgerollt, doch das Leak blieb bestehen.
- Auch Änderungen an Tools zur Erfassung von Ruby-Sprachmetriken und Puma-Pool-Nutzungsmetriken wurden zurückgenommen, doch der Speicheranstieg stoppte nicht.
Das Leak-Muster deutete auf bestimmten Traffic hin
- Das Leak trat nur auf
web-Dynos auf; Sidekiq- und Delayed::Job-Dynos wirkten unauffällig.
- Nicht alle
web-Dynos leckten jederzeit.
- Teilweise zeigten sie über Stunden eine relativ flache Speichernutzung wie langlebige Webprozesse.
- Dann begannen irgendwann ein, einige oder alle Dynos zu lecken.
- Puma lief im Cluster-Modus und nutzte pro Dyno bei 8 vCPUs 12 Worker-Prozesse.
- Selbst innerhalb eines Dynos kam es vor, dass nur einige der 12 Worker fast den gesamten Speicher verbrauchten.
- OpenTelemetry Traces waren so stark gesampelt, dass sich eine bestimmte Request-Art nur schwer mit einem bestimmten Dyno verbinden ließ; auch die Korrelation mit nicht gesampelten Logs war mit den vorhandenen Tools nicht einfach.
Vorgehen zum Sammeln von Heap-Dumps
- Um sich an einen laufenden Ruby-Prozess anzuhängen, wurde
rbtrace verwendet.
- Da
rbtrace im Prozess geladen sein muss, wurde es in die Gemfile aufgenommen und das Laden über eine Umgebungsvariable gesteuert.
gem "rbtrace", require: String(ENV.fetch("FEATURE_ENABLE_MEMORY_DUMPS", false)) == "true"
- Auf Heroku wurde mit
heroku ps:exec ein SSH-Tunnel zu einem leckenden Dyno geöffnet und mit ps die Ruby-Prozesse nach RSS sortiert.
ps -eo pid,ppid,comm,rss,vsz --sort -rss | grep ruby
- Bei
web-Dynos sind Prozesse mit derselben PPID Puma-Worker; als Ziel wurde die PID des Workers mit dem höchsten Speicherverbrauch gewählt.
- Das Tracking von Speicherallokationen wurde mit
ObjectSpace.trace_object_allocations_start aktiviert, was Performance, Speicher und CPU beeinflussen kann.
DUMP_PID=<pid>
rbtrace --pid="${DUMP_PID}" --eval="Thread.new{require 'objspace';ObjectSpace.trace_object_allocations_start}.join"
- Heap-Dumps wurden mit
ObjectSpace.dump_all in /tmp erzeugt; bei einem über Stunden laufenden Leak-Prozess wuchs die JSON-Datei auf 5–6 GiB an.
rbtrace --pid="${DUMP_PID}" --eval="Thread.new{require 'objspace'; GC.start(); io=File.open('/tmp/heap-${DUMP_PID}.json', 'w'); ObjectSpace.dump_all(output: io); io.close}.join" --timeout=600
gzip "/tmp/heap-${DUMP_PID}.json"
- Auf Heroku wurde der Dump mit
heroku ps:copy lokal heruntergeladen; um mit heapy retained memory zu betrachten, wurden mindestens etwa drei Dumps gesammelt.
- Nach den Arbeiten wurde das Allocation-Tracking deaktiviert und die Dumps gelöscht oder der Dyno neu gestartet.
Die Heap-Analyse zeigte einen Thread, der 1,9 GiB festhielt
- Allein mit dem retained-memory-Report von
heapy und dem Diff von sheap ließ sich der Ausgangspunkt schwer finden.
- Mit
reap, das den Referenzgraphen von Ruby-Heap-Dumps analysiert und visualisiert, wurde ein Flamegraph erzeugt.
- Der Flamegraph zeigt Referenzen von den Wurzeln aus Sicht des Ruby-GC zu tieferliegenden Objekten; Objekte, die mehr Speicher festhalten, werden mit breiteren Zellen dargestellt.
- Im dritten Heap-Dump hielt ein
Thread 1,9 GiB Speicher fest.
- Tatsächlich war es das darunterliegende
Array, das 32.067 Objekte referenzierte und damit 1,9 GiB festhielt.
Verfolgen des Referenzpfads mit sheap
- Mit dem aktuellen
main-Branch von sheap wurden der zweite und dritte Dump verglichen.
- Da die Dumps fast 6 GiB groß waren, dauerte das Parsen entsprechend lange.
- Das Ergebnis von
find_path zeigte, dass der problematische Thread kein Hintergrund-Thread eines Telemetrie- oder Metrik-Tools war, sondern ein Puma-Thread, der Requests bearbeitete.
ActiveSupport::SubscriberQueueRegistry fungiert in Rails 6.1 als threadbezogene Hash, die Listen von ActiveSupport::Subscriber nach Event-Namen speichert.- Diese Registry referenzierte eine
Hash, und eines der darin enthaltenen Arrays hielt ActiveSupport::Notifications::Event fest.
- Dieses
Event referenzierte wiederum über sein @children-Array mehr als 32.067 Child-Event-Objekte.
- Der Name des ersten Child-
Event war redirect_to.action_controller, und darin befand sich ein ActionDispatch::Request-Objekt.
Eine ungewöhnliche Request lieferte den Reproduktionshinweis
- Das
ActionDispatch::Request im Heap enthielt eine reale Route und eine gültige öffentliche Ressourcen-ID, aber die Query-Parameter waren manipuliert.
- Im Request-Pfad war
password=[FILTERED] enthalten, was zeigte, dass ein Prozess zur Bereinigung sensibler Daten beteiligt war.
- Wurde dieselbe Route mit denselben Parametern im Inkognito-Browser gegen die Produktions-App geschickt, trat ein 500 server error auf.
- In den Logs stand
URI::InvalidURIError, und auch der Dyno, der den Request erhalten hatte, ließ sich identifizieren.
- Dieser Dyno zeigte zu dem Zeitpunkt noch normale Speichernutzung, aber nachdem Deployments kurz pausiert und weiter beobachtet wurde, zeichnete sich ein Leak-Trend ab.
- Lokal wurde die Situation samt Backtrace reproduziert, indem im
activesupport-Gem binding.pry und puts-Debugging eingefügt wurden.
Die eigentliche Ursache war eine Kombination aus Rails- und Bugsnag-Änderungen
- Der Error-Backtrace zeigte auf das
uri-Gem der Ruby-Standardbibliothek, das in Bugsnag.cleaner.clean_url verwendet wurde.
- Dieser Code lief innerhalb eines
ActiveSupport::Notifications.subscribe-Blocks bei der Bereinigung der Rails-Breadcrumb-URL.
- Das Problem war die Kombination aus zwei Faktoren:
ActiveSupport::Subscriber in Rails 6.1 verfolgt Events über Event#children und ein gemeinsam genutztes Array.- Eine Bugsnag-Änderung nutzte
URI für die Bereinigung der Rails-Breadcrumb-URL, wobei bei ungültigen URIs eine Exception auftreten konnte.
- Wenn
URI bei einer ungültigen URI einen Fehler auslöste, verursachte der Subscribe-Block von Bugsnag während der Verarbeitung von ActiveSupport::Notifications::Event eine Exception.
- Durch diese Exception wurde das Parent-
Event nicht aus Subscriber#event_stack entfernt; das Parent-Event blieb erhalten und verursachte das Speicherleck.
- Das Parent-
Event referenzierte über das #children-Array weiterhin Child-Events und hielt so immer mehr Speicher fest.
- Der Rails-7.1-Fix von John Hawthorn entfernt sowohl das Konzept von
Event#children als auch das gemeinsam genutzte Array zum Event-Tracking und beseitigt damit beide Ursachen des Leaks.
Die Lösung waren ein Bugsnag-Upgrade und ein Rails-Upgrade
- In aktuellen Rails-Versionen tritt dieses Problem dank John Hawthorns Fix nicht mehr auf.
- Die App lief damals auf Rails 6.1 und konnte deshalb nicht sofort von dem Rails-Fix profitieren.
- Bugsnag hatte bereits einen Fix eingebaut, damit
Bugsnag.cleaner.clean_url bei ungültigen URIs keine Exception mehr auslöst.
- Die kurzfristige Lösung war daher ein Upgrade auf die Bugsnag-Gem-Version, die diesen Fix enthielt.
- Die langfristige Lösung war ein Upgrade der Rails-Version.
- Die Änderung, die zeitlich mit dem ersten Speicher-Spike zusammenfiel, war das Upgrade von Bugsnag
v6.26.0 auf v6.26.1; der Zweck war eigentlich, eine Deprecation-Warnung einer anderen Abhängigkeit zu beheben.
1 Kommentare
Meinungen auf Hacker News
Ich verstehe nicht, warum manuelle Speicherverwaltung so gefürchtet ist. Mit RAII und klaren Ownership-Regeln ist Speicherverwaltung eine einfache Engineering-Aufgabe.
Frameworks, die Reference Counting oder Shared Pointer erzwingen, wirken auf mich eher schwieriger, weil dadurch die Ownership verschwimmt.
Wenn man etwas selbst erstellt hat, gibt man es selbst wieder frei; wenn man es weitergegeben hat, kümmert man sich nicht mehr darum. OS-Ressourcen wie Handles und Sockets verwalten wir auch manuell ohne automatischen Ressourcenmanager. Ich sehe keinen Grund, das Design durch automatische Speicherverwaltung unnötig zu verkomplizieren.
Nach vielen Jahren Entwicklung bin ich zu der Ansicht gekommen, dass die meisten Entwickler nicht genug freie Kapazität im Arbeitsgedächtnis haben, um gleichzeitig auch noch Speicherverwaltung mitzudenken. Selbst wenn man das Vorgehen mechanisch kennt, lässt man Dinge fallen, wenn man im Kopf zu viel jongliert.
Umgekehrt gibt es eine Minderheit, die manuelle Speicherverwaltung fast mühelos jedes Mal richtig hinbekommt. Für sie ist es tatsächlich leicht, weshalb sie kaum nachvollziehen können, warum andere damit Schwierigkeiten haben. Für solche Leute können die Vorteile automatischer Speicherverwaltung unklar wirken, während die Nachteile groß erscheinen.
Grob gesagt wurden solche Fehler nicht durch andere Fehler ersetzt, sondern sind einfach verschwunden. Sie verlangen Programmierern auch nicht mehr Arbeit ab, sondern nehmen ihnen im Vergleich zur manuellen Speicherverwaltung eher Arbeit ab.
Natürlich gewinnt Garbage Collection nicht immer, und sie hat reale Nachteile. Aber für die meisten Programme sind moderne Garbage Collectors gut genug, sodass diese Nachteile kaum ins Gewicht fallen.
Logikfehler haben ein ähnliches Problem, und selbst in Sprachen wie Java sind Speicherlecks selten möglich, aber speichersichere Sprachen sind eine Verbesserung. Das ist ähnlich wie TypeScript gegenüber JavaScript. Wenn es Automatisierung gibt, die Speicherfehler von 1 % auf 0,01 % senken kann, verstehe ich nicht, warum die Vermeidung von Leaks und undefiniertem Verhalten weiter eine manuelle Sorge bleiben sollte.
Man kann eine Garbage-Collection-Sprache wie Java verwenden, die einfach ist, aber Overhead hat, oder eine Sprache mit erzwungener Ownership wie Rust, die eine Lernkurve hat, aber keinen Overhead. Logikfehler sind ebenfalls lästig, doch Speicherfehler sind besonders berüchtigt, weil sie oft keine klare Fehlermeldung liefern oder das Programm selbst beim Auftreten nicht anhalten.
Nebenbei: Auch formale Verifikation ist eine Methode, eine ganze Fehlerklasse praktisch zu eliminieren. Derzeit sieht man sie vor allem in Systemen, bei denen Korrektheit am wichtigsten ist, weil ihre Nachteile – anders als bei Speicherverwaltung – zu groß sind. Der Code wird extrem ausführlich und schwierig und erzwingt bestimmte Strukturen. Wenn formale Verifikation aber besser wird, wird auch sie meiner Meinung nach stärker in den Mainstream rücken.
„Ich bin kein echter Programmierer. Ich klebe Dinge so zusammen, dass sie funktionieren, und mache weiter. Echte Programmierer würden sagen: ‚Es funktioniert, aber überall leckt Speicher. Sollten wir das nicht beheben?‘ Ich starte einfach Apache nach jeweils 10 Requests neu.“ — Rasmus Lerdorf, PHP Non-Designer
https://en.wikiquote.org/wiki/Rasmus_Lerdorf
Mein früherer Arbeitgeber hätte den Preis für die dümmste Art verdient, durch ein Speicherleck 5 Millionen Dollar zu verlieren.
In den 90ern hatte der Druckertreiber von Solaris ein Speicherleck[1]. Ich arbeitete damals als Auftragnehmer für eine große Bank, und zu jener Zeit war der rechtliche Status von Faxen bei Vertragsbestätigungen vor Gericht noch nicht ausreichend erprobt, daher protokollierten Banken Geschäfte per Fax. Das System, das das Fax verschickte, sendete das Dokument auch an einen bestimmten Drucker, um eine Handelsbestätigung auszudrucken. Jemand nahm diese Bestätigung dann, las sie der Gegenpartei am Telefon vor, sodass sie in der Gesprächsaufzeichnung[2] landete und rechtlich bestätigt wurde.
Eines Tages starb wegen des Speicherlecks der Druckertreiber, eine Bestätigung wurde nicht ausgedruckt, und die zuständige Person konnte sie nicht telefonisch vorlesen. Der Markt bewegte sich stark, und die Gegenpartei behandelte den Trade als DK[3]. So sehr die Bankvorstände auch tobten, es half nichts; nachdem der Verlust von 5 Millionen Dollar verbucht war, wurde eine Richtlinie eingeführt, mit dieser Bank nie wieder zu handeln[4]. Der Fax-Drucker-Job wurde auf Windows NT verlagert.
[1] Dem hervorragenden Buch „Expert C Programming“ zufolge wurde dieses Problem letztlich behoben, weil Scott McNealy, damals CEO von Sun Microsystems, trotz seiner Rolle als CEO eine leistungsschwache Workstation bekam, das Problem häufig erlebte und sich lange genug beschwerte, bis die Entwickler es schließlich reparierten. https://progforperf.github.io/Expert_C_Programming.pdf
[2] Telefonate in den Wertpapierabteilungen von Banken werden aus Rechts- und Compliance-Gründen fast immer aufgezeichnet.
[3] DK steht für „Don’t know“. Wenn die Gegenpartei sagt, sie „kenne“ den Trade nicht, bestreitet sie, dass ein Vertrag zustande gekommen ist.
[4] Da die Gegenpartei einfach anderswo handeln und einer anderen Bank Gebühren zahlen konnte, war es vermutlich für uns der größere Schaden.
Citi wurde ebenfalls verklagt, weil es einen Kredit zu früh zurückgezahlt hatte. In der Finanzbranche wird, wenn es einem nützt, wohl jeder einen schriftlichen Vertrag mit Nachdruck durchsetzen.
In C ist das Finden von Leaks dank Valgrind sehr einfach
Das Beheben ist schwieriger, aber wenn das Design stimmt, ist es meist einfach. Normalerweise wird innerhalb derselben Funktion allokiert und freigegeben, sofern es sich nicht um eine Funktion handelt, die für den Aufrufer allokiert. Wenn eine Funktion für den Aufrufer allokiert, betrachtet man diesen Aufruf selbst als Allokation auf Seite des Aufrufers
Bei statischer Analyse der Codebasis waren Fehlerbehandlungspfade die häufigste Ursache des Problems
So wie es Block-Scope, Funktions-Scope, Datei-Scope und globalen Scope gibt, gibt es auch in Modellen, die eine Abstraktion des Problemraums oder der Lösung darstellen, mehrere Scope-Ebenen. Ich habe allerdings noch nie gesehen, dass das so gelehrt wird
Wenn irgendein Scope in
$SCOPE::foo()eine Ressource erwirbt und sie in$SCOPE::cleanup()nicht freigibt, lässt sich das mit dem Auge recht leicht finden. Die Fähigkeit, den Problemraum und die vorgeschlagene Lösung zu modellieren, bevor man sich ins Coden stürzt, ist nützlichMir fällt eine Geschichte ein, die ich über Yahoo gehört habe. Der Ad-Server hatte ein Memory Leak und lief nach ungefähr 10000 Requests in Speichermangel
Die Lösung bestand darin, den Server nach 8000 Requests neu zu starten. Das funktionierte ein bis zwei Jahre, danach trat der Speichermangel auch schon nach 8000 Requests auf
Die nächste Lösung bestand darin, den Server nach 6000 Requests neu zu starten
Damit dieser Ansatz funktioniert, muss der Neustart extrem schnell sein
Als Rails-Entwickler galt es bei solchen Problemen als akzeptabler Produktivitäts-Trade-off, einfach mehr Hardware draufzuwerfen. Die Stimmung war: Wenn einen solche Probleme kümmern, soll man eben strengere Werkzeuge verwenden
Persönlich fällt es mir wegen meines Perfektionismus schwer, diesen Ansatz zu akzeptieren, aber es ist schwer zu leugnen, dass er in der Praxis funktioniert
Ich habe sowohl Sprachen mit Garbage Collection als auch solche ohne verwendet. Meist ist manuelles Management schwieriger zu schreiben, automatisches Management dagegen schwieriger zu debuggen
Ich würde gern eine Sprache verwenden, die beides kann. Beim Schreiben explorativen Codes ist automatische Speicherverwaltung praktisch, für manche Arten von Code ist manuelle Speicherverwaltung vorteilhaft
Es frustriert mich, dass man keinen Mittelweg zwischen Verbot und Zwang findet
@[manualfree]leicht pro Funktion oder Modul abschalten und mitv -gc noneauch für das gesamte Projekthttps://vlang.io
„Über Tools zum Profiling von Leaks, das Verstehen von Heap-Dumps und häufige Ursachen von Leaks ist viel geschrieben worden“
Uff, Leaks und Heap-Dumps. Jemand scheint eine gesündere Ernährung zu brauchen