Wenn ein fehlender Index den Server lahmlegt

In letzter Zeit hatte ich bei meinem PC-Hardwareempfehler pc-kombo mit Performanceproblemen zu kämpfen. Auf meinem Rechner lief die Anwendung lokal gut. Aber wenn mehrere Besucher auf dem Server waren brach desöfteren die Performance ein. Und zwar aller Seiten, die irgendwie auf die SQLite-Datenbank zugriffen oder kompliziertere Berechnungen durchführten.

Bis hierhin hatte ich schon einige Stellen der Serveranwendung optimiert. Die Preisaktualisierung – für die große XML-Dateien geparst werden müssen, was die Serverperformance beeinträchtigen konnte – wurde auf einen zweiten Server ausgelagert, das war die größte Aktion. Geschickter und ebenfalls mit großem Effekt: Ein Cache verhindert das unnötige Neuberechnen des besten PCs für einen bestimmten Preispunkt, solange sich die Komponentenpreise nicht geändert haben. Übersetzungen werden nun genauso im Arbeitsspeicher zwischengespeichert, was die Customize-Funktion beschleunigt. Die Berechnung der Durchschnittsgröße eines Gehäuses wird nur noch durchgeführt, wenn die Detailseite eines Gehäuses mit dem Größenvisualisierer angezeigt wird, und so weiter. All das half, doch es war nicht die Ursache des Grundproblems. Dafür wurde das nun sichtbar.

Schuld an den Performanceeinbrüchen war wohl eine einzelne Datenbankabfrage.

Der Debugweg

Nach all den vorherigen Verbesserungen stach eine Seite als noch besonders langsam heraus: Die Detailansicht einer Komponente, z.B. die des Prozessors i7-8700K. Auf dem lokalen Rechner mit Testdaten war diese Seite allerdings schnell. Ich entschloss mich, trotzdem erstmal dort zu debuggen, da der langsamste Abschnitt auf meinem Rechner ja auf dem Server noch problematischer sein und die längere Verzögerung verursachen könnte.

Zum Performance-Debuggen benutze ich ruby-prof mit ruby-prof-flamegraph. Über die Gemseite finden sich gute Erklärungen. Bei mir sieht der gekürzte Code so aus:

get '/:country/product/:type/:ean' do |country, type, ean|
    if settings.development?
        require 'ruby-prof'
        require 'ruby-prof-flamegraph'
        begin
            RubyProf.start
        rescue RuntimeError => re
            RubyProf.stop
            RubyProf.start
        end
    end

    html = doStuff()

    if settings.development?
        result = RubyProf.stop
        printer = RubyProf::FlameGraphPrinter.new(result)
        File.open("profiling/profile_data", 'w+') { |file| printer.print(file) }
    end
    html
end

Die Datei profiling/profile_data kann ich dann mit flamegraph.pl visualisieren:

flamegraph.pl --countname=ms --width=1920 < profile_data > product.svg

Und das sah so aus:

Mit 73% ging der größte Teil der Rechenzeit also in Hardware#priceHistory verloren. Auf meinem Rechner war das weniger als eine Sekunde. Aber auf dem Server hatte das Laden der Seite vorher – unter Last – ~8 Sekunden gedauert. Dort würde diese Funktion wohl ebenfalls den größten Teil der Rechenzeit ausmachen, vermutete ich.

Was macht priceHistory? In Grunde führt es diesen SQL-Query aus:

SELECT * FROM pmdb.priceHistory WHERE ean = ? AND (vendor = ? OR vendor = ?) ORDER BY date ASC

Ein ziemlich simples Select. Doch der Query-Plan sah nicht gut aus:

EXPLAIN QUERY PLAN SELECT * FROM priceHistory WHERE ean = "05032037108652" AND (vendor = "vendor1" OR vendor = "vendor2") ORDER BY date ASC;
0|0|0|SCAN TABLE priceHistory
0|0|0|USE TEMP B-TREE FOR ORDER BY

SCAN TABLE priceHistory ist der problematische Teil hier. Diese Erklärung bedeutet, dass zum Erfüllen dieser Abfrage die gesamte Tabelle gelesen werden muss. Aber wie groß kann eine solche Tabelle mit etwas Preishistorie schon sein?

du -sh /home/pc-kombo/www.pc-kombo.de/productMeta.db
823M	/home/pc-kombo/www.pc-kombo.de/productMeta.db

Upps. Nicht alles davon sind die Preisdaten. Aber der größte Teil.

Um also die Detailseite anzuzeigen musste der Server jedes mal eine 800MB große Tabelle auslesen. Das führte dazu, dass ein Prozessorkern für ein paar Sekunden komplett ausgelastet war (was in Sprachen wie Ruby ohne echten Parallelismus besonders problematisch ist), und auch die Festplatte wurde dadurch natürlich komplett in Beschlag genommen. Kein Wunder, dass dann auch die anderen Seitenaufrufe langsam wurden.

Hier hilft normalerweise ein Index:

CREATE INDEX priceHistory_ean_vendor ON priceHistory(ean, vendor);

Und tatsächlich:

EXPLAIN QUERY PLAN SELECT * FROM priceHistory WHERE ean = "05032037108652" AND (vendor = "vendor1" OR vendor = "vendor2") ORDER BY date ASC;
0|0|0|EXECUTE LIST SUBQUERY 1
0|0|0|USE TEMP B-TREE FOR ORDER BY

Der Index wird direkt genutzt. Und so viel bringt das in Praxis:

Alleine durch diesen einen Index ist die Preishistorie nun nicht mehr der größte Zeitfaktor in der Berechnung, sondern mit 16% einer von mehreren. Und htop bestätigt das, denn bei dem Seitenaufruf schießt die Prozessorlast des einen Kerns nun nicht mehr auf 100%, sondern bleibt irgendwo unter 10%. Dementsprechend werden auch die anderen Seiten nicht mehr ausgebremst.

Die eigentliche Ursache

Es ist fast immer problematisch, wenn ein Provisorium länger genutzt wird als geplant. Genau das ist hier passiert. Als ich die Preishistorie entwickelte wollte ich die Preise nur für wenige Wochen in der Datenbank speichern. Die eigentliche Lösung sollte eine Zeitseriendatenbank wie rrdtool sein. Solche Datenbanken können die Datenmenge begrenzen, in dem für längere zurückliegende Zeiträume Datenpunkte entfernt werden. Statt den Preis einer Grafikkarte von vor zehn Jahren alle 5 Minuten parat zu haben, speichert rrdtool dann eben nur den Durchschnittspreis einer zehn Jahre zurückliegenden Kalenderwoche. Und bestimmt wäre bei der richtigen Lösung dann auch der Index gesetzt gewesen.

Stattdessen blieb das Provisorium bestehen, bis die Datenmenge so sehr anstieg, dass der fehlende Index – dessen Fehlen beim Entwickeln mit den wenigen Datenpunkten ja noch kein Problem war – den Server ausbremsen konnte.