4000% kürzere Abfragelaufzeit durch explizites Joinen in PostgreSQL
Ein Bugreport im Helpdesk System des Rechenzentrums machte uns auf ein Problem mit der Notenspiegel-Funktion in mein campus aufmerksam. In einigen Fällen wurde der Notenspiegel nur unvollständig angezeigt.
Um diesem Problem auf die Spur zu kommen wurden zunächst die Logfiles des Applikationsservers durchforstet. In diesen wurden immer wieder Verbindungsprobleme mit der Datenbank protokolliert. Eine Überwachung der Verbindungen zeigte jedoch, dass die Verbindungen zwischen Applikationsserver und Datenbank stabil waren.
Als mögliche Ursache des Fehlers wurde also angenommen, dass die Bearbeitung der Abfrage einfach zu lange dauert und das Ausbleiben einer Antwort über einen bestimmten Zeitraum (Timeout) den Fehler auslöst. Ausgehend von dieser Hypothese wurde das letzte Statement vor dem Fehler direkt auf der Datenbank ausgeführt. Tatsächlich dauerte es sehr lange bis Ergebnisse vorlagen. Um das Problem genauer einschätzen zu können und eine exakte Laufzeitmessung zu erhalten wurde der Queryplan angezeigt, sowie die tatsächlichen Laufzeiten mit ausgegeben. Das anonymisierte Statement, sowie die zugehörige Ausgabe sahen wie folgt aus:
SELECT DISTINCT lab.pnr AS pnr, lab.psem AS psem, lab.pversuch AS pversuch, lab.pdatum AS pdatum, pord.pordnr AS pordnr, lab.pstatus AS pstatus, pord.pltxt1 AS deTxt, pord.pltxt1 AS enTxt, pord.abschl AS abschl, lab.pnote AS pnote, lab.bonus AS bonus, lab.malus AS malus, lab.ppruef1 AS ppruef1, lab.psws AS psws, lab.labnr AS labnrzu, lab.zuordposid AS zuordposid FROM lab INNER JOIN labzuord ON lab.labnr=labzuord.labnrzu INNER JOIN pord ON lab.pordnr=pord.pordnr WHERE lab.mtknr=XXXXXXXX AND labzuord.pordnrzu=pord.pordnr AND (pord.pdum IN ('D','B','M','A') or pord.pdum IS NULL) AND pord.abschl='52' and pord.stg='022' and pord.vert=' ' AND pord.schwp='' AND pord.kzfa='Z' and pord.pversion=2007 and pord.pordnr IN (SELECT pordnr FROM pnrzuord WHERE pnrzuord.artzuord IN ('FG','F2')) ORDER BY 2,1,3; Unique (cost=17949.40..17949.44 rows=1 width=336) (actual time=2267.815..2267.878 rows=2 loops=1) -> Sort (cost=17949.40..17949.40 rows=1 width=336) (actual time=2267.809..2267.826 rows=12 loops=1) Sort Key: lab.psem, lab.pnr, lab.pversuch, lab.pdatum, pord.pordnr, lab.pstatus, pord.pltxt1, pord.pltxt1, pord.abschl, lab.pnote, lab.bonus, lab.malus, lab.ppruef1, lab.psws, lab.labnr, lab.zuordposid -> Nested Loop (cost=42.79..17949.39 rows=1 width=336) (actual time=1383.153..2267.508 rows=12 loops=1) Join Filter: (labzuord.pordnrzu = lab.pordnr) -> Hash Join (cost=42.79..17940.95 rows=1 width=281) (actual time=1382.809..2264.782 rows=247 loops=1) Hash Cond: (labzuord.pordnrzu = pord.pordnr) -> Seq Scan on labzuord (cost=0.00..14717.55 rows=848055 width=8) (actual time=0.051..1114.409 rows=848055 loops=1) -> Hash (cost=42.77..42.77 rows=1 width=273) (actual time=0.372..0.372 rows=2 loops=1) -> Nested Loop IN Join (cost=22.99..42.77 rows=1 width=273) (actual time=0.266..0.358 rows=2 loops=1) -> Index Scan using i_pord on pord (cost=0.00..8.29 rows=1 width=269) (actual time=0.130..0.147 rows=2 loops=1) Index Cond: ((abschl = '52'::bpchar) AND (stg = '022'::bpchar) AND (vert = ' '::bpchar) AND (schwp = ''::bpchar) AND (kzfa = 'Z'::bpchar) AND (pversion = 2007)) Filter: ((pdum = ANY ('{D,B,M,A}'::bpchar[])) OR (pdum IS NULL)) -> Bitmap Heap Scan on pnrzuord (cost=22.99..34.44 rows=3 width=4) (actual time=0.092..0.092 rows=1 loops=2) Recheck Cond: ((pord.pordnr = pnrzuord.pordnr) AND (pnrzuord.artzuord = ANY ('{FG,F2}'::bpchar[]))) -> Bitmap Index Scan on i_pnrzuord (cost=0.00..22.99 rows=3 width=0) (actual time=0.065..0.065 rows=28 loops=2) Index Cond: ((pord.pordnr = pnrzuord.pordnr) AND (pnrzuord.artzuord = ANY ('{FG,F2}'::bpchar[]))) -> Index Scan using i_lab_labnr on lab (cost=0.00..8.42 rows=1 width=71) (actual time=0.008..0.008 rows=0 loops=247) Index Cond: (lab.labnr = labzuord.labnrzu) Filter: (mtknr = XXXXXXXX) Total runtime: 2268.164 ms
Deutlich zu sehen ist die Gesamtlaufzeit der Abfrage mit 91795.591 ms (ca. 1:30 Minuten). Wie in Zeile 2 deutlich zu sehen ist, werden dabei 777.708 Datensätze sortiert (der Grund für das Sortieren ist das DISTINCT), was der Hauptgrund für die lange Laufzeit sein dürfte.
Nach einem Gedankenaustausch mit Florian Wagner, der erst kürzlich eine Klausur zum Thema Datenbanken ablegen durfte :), kamen wir zu dem Ergebnis, dass explizites Joinen die Anzahl der Datensätze die sortiert werden müssen reduzieren könnte (Arbeitshypothese: Der Queryplaner arbeitet hier nicht intelligent genug). Eine weitere Alternative wäre die Anzahl der abgefragten Spalten zureduzieren und so zumindest den Sortierschlüssel etwas handlicher zu bekommen (Arbeitshypothese: Wenn weniger Spalten sortieren werden müssen, sollte sich die Laufzeit verkürzen).
Dem ersten Ansatz wurde aus folgenden Gründen der Vorzug gegeben:
1. Wenn sich durch explizites Joinen die Anzahl der Datensätze signifikant verringern läßt, sollte die Laufzeit auch deutlich kürzer ausfallen
2. Da alle abgefragten Spalten erhalten bleiben entsteht kein Risiko bei der weiteren Verarbeitung auf Daten angewiesen zu sein die „wegoptimiert“ wurden.
Nach dem Unmschreiben der Anfrage auf explizites Joinen sehen Abfrage und Ergebnis wie folgt aus:
SELECT DISTINCT lab.pnr AS pnr, lab.psem AS psem, lab.pversuch AS pversuch, lab.pdatum AS pdatum, pord.pordnr AS pordnr, lab.pstatus AS pstatus, pord.pltxt1 AS deTxt, pord.pltxt1 AS enTxt, pord.abschl AS abschl, lab.pnote AS pnote, lab.bonus AS bonus, lab.malus AS malus, lab.ppruef1 AS ppruef1, lab.psws AS psws, lab.labnr AS labnrzu, lab.zuordposid AS zuordposid FROM lab INNER JOIN labzuord ON lab.labnr=labzuord.labnrzu INNER JOIN pord ON lab.pordnr=pord.pordnr WHERE lab.mtknr=XXXXXXXX AND labzuord.pordnrzu=pord.pordnr AND (pord.pdum IN ('D','B','M','A') or pord.pdum IS NULL) AND pord.abschl='52' and pord.stg='022' and pord.vert=' ' AND pord.schwp='' AND pord.kzfa='Z' and pord.pversion=2007 and pord.pordnr IN (SELECT pordnr FROM pnrzuord WHERE pnrzuord.artzuord IN ('FG','F2')) ORDER BY 2,1,3; Unique (cost=17949.40..17949.44 rows=1 width=336) (actual time=2267.815..2267.878 rows=2 loops=1) -> Sort (cost=17949.40..17949.40 rows=1 width=336) (actual time=2267.809..2267.826 rows=12 loops=1) Sort Key: lab.psem, lab.pnr, lab.pversuch, lab.pdatum, pord.pordnr, lab.pstatus, pord.pltxt1, pord.pltxt1, pord.abschl, lab.pnote, lab.bonus, lab.malus, lab.ppruef1, lab.psws, lab.labnr, lab.zuordposid -> Nested Loop (cost=42.79..17949.39 rows=1 width=336) (actual time=1383.153..2267.508 rows=12 loops=1) Join Filter: (labzuord.pordnrzu = lab.pordnr) -> Hash Join (cost=42.79..17940.95 rows=1 width=281) (actual time=1382.809..2264.782 rows=247 loops=1) Hash Cond: (labzuord.pordnrzu = pord.pordnr) -> Seq Scan on labzuord (cost=0.00..14717.55 rows=848055 width=8) (actual time=0.051..1114.409 rows=848055 loops=1) -> Hash (cost=42.77..42.77 rows=1 width=273) (actual time=0.372..0.372 rows=2 loops=1) -> Nested Loop IN Join (cost=22.99..42.77 rows=1 width=273) (actual time=0.266..0.358 rows=2 loops=1) -> Index Scan using i_pord on pord (cost=0.00..8.29 rows=1 width=269) (actual time=0.130..0.147 rows=2 loops=1) Index Cond: ((abschl = '52'::bpchar) AND (stg = '022'::bpchar) AND (vert = ' '::bpchar) AND (schwp = ''::bpchar) AND (kzfa = 'Z'::bpchar) AND (pversion = 2007)) Filter: ((pdum = ANY ('{D,B,M,A}'::bpchar[])) OR (pdum IS NULL)) -> Bitmap Heap Scan on pnrzuord (cost=22.99..34.44 rows=3 width=4) (actual time=0.092..0.092 rows=1 loops=2) Recheck Cond: ((pord.pordnr = pnrzuord.pordnr) AND (pnrzuord.artzuord = ANY ('{FG,F2}'::bpchar[]))) -> Bitmap Index Scan on i_pnrzuord (cost=0.00..22.99 rows=3 width=0) (actual time=0.065..0.065 rows=28 loops=2) Index Cond: ((pord.pordnr = pnrzuord.pordnr) AND (pnrzuord.artzuord = ANY ('{FG,F2}'::bpchar[]))) -> Index Scan using i_lab_labnr on lab (cost=0.00..8.42 rows=1 width=71) (actual time=0.008..0.008 rows=0 loops=247) Index Cond: (lab.labnr = labzuord.labnrzu) Filter: (mtknr = XXXXXXXX) Total runtime: 2268.164 ms
Das Sortieren findet immernoch über alle Spalten statt (Zeile Sort Key) dafür sind aber nur noch 12 Datensätze zu bearbeiten (Zeile Sort). Das schlägt sich dann einer Laufzeit von 2268.164 ms (ca. 2 Sekunden) nieder und entspricht einer Beschleunigung um den Faktor 40.
Zur Ehrenrettung der PostgreSQL-Entwickler sei gesagt, dass das Datenbankschema als suboptimal zu bezeichnen ist und daraus resultierende Redundanzen efffektive Abfragen schwer machen (DISTINCT ist ein ständiger Begleiter und in keiner Abfrage ist das DISTINCT ON).
Für die Nutzer von mein campus hat diese Optimierung leider keine merkliche Auswirkung auf die Performance, da die lange Laufzeit dieser Abfrage ohnehin nur durch den unvollständigen Notenspiegel aufgefallen ist, d.h. mein campus hat nie wirklich auf das Ergebnis dieser Abfrage gewartet. Die Gesamtlaufzeit vom Klicken bis zur Anzeige des Notenspiegels errechnet sich durch eine Vielzahl von Abfragen, sowie der Organisation dieser Daten in passende Hierarchien (Studiengang->Studienabschnitt->Module->Teilleistungen).
Für die Zukunft ist aber bereits angedacht die wichtigsten Abfragen einem Audit zu unterziehen und diese soweit möglich zu optimieren. Von dieser Arbeit werden die Anwender dann auch spürbar profitieren.