In dieser Folge stellen wir im Rahmen der "Optimizer Bits" das Modul auto_explain vor, das seit PostgreSQL Version 8.4 Bestandteil des contrib-Zweiges ist. Das Modul ermöglicht das Protokollieren von Abfrageplänen im PostgreSQL-Log und so eine bessere Analyse von Abfrageproblemen während der Laufzeit.
Problemstellung
Für viele Datenbank-Entwickler und -Administratoren stellt sich täglich das Problem, problematische Abfragen zu finden, zu analysieren und effizienter zu gestalten. Hauptproblem dieser Aufgabe ist das Identifizieren solcher Abfragen. Erstes Mittel ist der Logparameter
log_min_duration_statement = '30s'
In diesem Falle werden alle Abfragen, die länger als 30 Sekunden dauern, in das Log der PostgreSQL-Datenbank geschrieben. Der Administrator hat dann die Möglichkeit, diese Abfrage aus dem Logfile zu ermitteln oder aber über weitere Tools wie bspw. pgfouine zu analysieren. Allerdings kann es unter Umständen passieren, dass bei der späteren Analyse andere Pläne entstehen, die es schwer machen, das tatsächliche Problem zu spezifizieren. Solche Abhängigkeiten machen es dem Entwickler schwer, das tatsächliche Problem genau einzugrenzen.
Das Modul auto_explain
Seit PostgreSQL 8.4 gibt es das contrib-Modul auto_explain, dass die Ausgabe von Abfrageplänen während der Testphase von Abfragen gestattet. Beispielsweise lassen sich damit Läufe von umfangreichen Batchjobs protokollieren, die Pläne später analysieren und entsprechende Optimierungen an den entsprechenden Abfragen vornehmen. auto_explain kann permanent oder nur zur Fehlersuche in die Datenbank geladen werden.
Zunächst müssen die contrib-Module von PostgreSQL 8.4 oder höher installiert sein. Dies ist von Distribution zu Distribution unterschiedlich, in der Regel sollte man nach einen Paket postgresql-contrib Ausschau halten. Wenn man PostgreSQL selbst aus den Tarballs baut, wechselt man in der Verzeichnis des entpackten Quelltextes und von dort aus in das entsprechende contrib-Verzeichnis (die folgenden Schritte erfordern in der Regel Rootrechte auf dem System):
$ cd <QUELLTEXT>
$ cd contrib/auto_explain
Je nachdem. ob bereits PostgreSQL komplett gebaut wurde (in der Regel hat man dann ja noch alle benötigten Sourcen), kann man dann auto_explain zusätzlich bauen:
$ make install
Sollte der Quelltextbaum bereits bereinigt worden (make clean), aber eine komplette Installation zur Verfügung stehen, so kann man mit PGXS-Unterstützung, ohne den kompletten Quelltextbaum nochmals kompilieren zu müssen, das Modul wie folgt bauen:
$ USE_PGXS=1 make install
Dies erfordert jedoch mindestens die Präsenz des Tools pg_config im Pfad der aktuellen Umgebung.
Ist alles installiert, so kann das Modul direkt in eine Datenbankverbindung geladen werden. Dies ist nur als Superuser möglich, wie in diesem Beispiel über eine lokale Verbindung:
$ psql -U <superuser> <dbname>
#= LOAD 'auto_explain';
LOAD
Ist das Modul erfolgreich geladen worden, so steht es nur in dieser Datenbankverbindung zur Verfügung und kann auch nur von dort aus verwendet werden. Interessant ist dies, um nur Abfragen aus speziellen Verbindungen heraus zu protokollieren. Mit der folgenden SQL-Abfrage können die nun hinzugekommenen Konfigurationsparameter für auto_explain abgefragt werden:
#= SELECT name, setting FROM pg_settings WHERE name LIKE 'auto_explain%';
Dies sollte folgende Liste liefern:
name | setting
------------------------------------+---------
auto_explain.log_analyze | off
auto_explain.log_buffers | off
auto_explain.log_format | text
auto_explain.log_min_duration | -1
auto_explain.log_nested_statements | off
auto_explain.log_verbose | off
(6 rows)
Der wichtigste Parameter hier ist
auto_explain.log_min_duration
Dieser aktiviert (Werte ab 0ms) oder deaktiviert (Wert -1) das Protokollieren von Abfrageplänen. Die weiteren Einstellungen sind im Einzelnen:
- auto_explain.log_analyze = true|false: Aktiviert oder deaktiviert das Loggen von EXPLAIN ANALYZE. Dies bedeutet das Timinginformationen aller Abfragen erfasst werden (auch diejenigen, die schneller ausgeführt werden als auto_explain.log_min_duration). Dies hat einen signifikanten Einfluss auf die Ausführungsgeschwindigkeit und sollte mit Bedacht gewählt werden.
- auto_explain.log_verbose = true|false: Ausgabeformat mit zusätzlichen Informationen für EXPLAIN.
- auto_explain.log_nested_statements = true|on: Hiermit werden auch Ausführungspläne von Statements innerhalb von Funktionen mitprotokolliert. So ist es nun auch möglich, die Pläne von SQL-Abfragen, die bspw. aus pl/pgsql-Prozeduren heraus ausgeführt werden, genauer zu untersuchen.
Mit PostgreSQL 9.0 kommen zwei weitere Konfigurationsmöglichkeiten hinzu:
- auto_explain.log_format = 'text'|'xml'|'json'|'yaml': Ermöglicht die Ausgabe der Abfragepläne im XML, JSON, oder YAML Format. text entspricht dem Standardformat.
- auto_explain.log_buffers = true|false: Aktiviert oder deaktiviert die Ausgabe von Bufferinformationen in der Ausgabe des Planes. Dies enthält u.a. Informationen über Bufferhits (Treffer im Shared Buffer Pool). Voraussetzung hierfür ist das gleichzeitige Aktivieren des Parameters log_analyze.
Anwendungsbeispiel
Im folgenden betrachten wir ein wegen der Übersichtlichkeit ein stark vereinfachtes Anwendungsbeispiel. In einer Datenbank gibt es seit kurzem ein Geschwindigkeitsproblem mit einer Funktion, die plötzlich stark variierende Ausführungszeiten aufweist. Die Funktion wird vielfältig eingesetzt, da sie bestimmte ID-Nummern einem Datum zuordnet. Die Definition dieser Funktion sei wie folgt:
CREATE OR REPLACE FUNCTION get_test_datum_ids(p_datum timestamp)
RETURNS SETOF integer
STABLE
LANGUAGE plpgsql
AS
$$
DECLARE
v_id int;
BEGIN
FOR v_id IN SELECT * FROM test WHERE datum < p_datum
LOOP
RETURN
NEXT v_id;
END LOOP;
RETURN;
END;
$$;
Geübte PostgreSQL-Anwender werden schnell bemerken, dass diese Funktion deutlich effizienter implementiert werden kann, für dieses Beispiel jedoch ist eine derartige Implementierung gut geeignet. Der Administrator kann nun über log_min_duration_statement langsame Funktionsaufrufe zwar protokollieren, muss jedoch um dem Geschwindigkeitsproblem auf den Grund zu gehen, u.U. auf das System übertragen oder von Hand ausführen. Bei näherer Betrachtungsweise entsteht dann der Verdacht, dass die Schleife und die dort enthaltene Abfrage suboptimal sein könnte. Üblicherweise wird dann die Abfrage mit EXPLAIN geprüft:
#= \timing on
#= EXPLAIN ANALYZE SELECT id FROM test WHERE datum < '01.02.2008'::timestamp;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on test (cost=4.50..16.90 rows=32 width=4) (actual time=0.039..0.054 rows=31 loops=1)
Recheck Cond: (datum < '2008-02-01 00:00:00'::timestamp without time zone)
-> Bitmap Index Scan on test_datum_idx (cost=0.00..4.49 rows=32 width=0) (actual time=0.025..0.025 rows=31 loops=1)
Index Cond: (datum < '2008-02-01 00:00:00'::timestamp without time zone)
Total runtime: 0.114 ms
(5 rows)
Insofern nichts Verdächtiges, die Abfrage nutzt einen vorhandenen Index auf dem Feld datum. Mit auto_explain können wir nun jedoch ebenfalls direkt die Pläne aus dem Funktionskörper heraus prüfen:
#= SET auto_explain.log_analyze TO on;
SET
#= SET auto_explain.log_nested_statements TO on;
SET
#= SET auto_explain.log_min_duration TO '0ms';
SET
#= SELECT get_test_datum_ids('01.02.2008'::timestamp);
Durch das Setzen von auto_explain.log_analyze TO on wird die Funktion tatsächlich ausgeführt und alle Timingparameter erfasst. Nach dem Ausführen sollten sich folgende Zeilen auf STDOUT, im Logfile oder syslog finden, je nach dem was für ein log_destination verwendet wird:
LOG: duration: 0.616 ms plan:
Query Text: SELECT * FROM test WHERE datum < p_datum
Seq Scan on test (cost=0.00..25.70 rows=365 width=12) (actual time=0.424..0.597 rows=31 loops=1)
Filter: (datum < $1)
ZUSAMMENHANG: PL/pgSQL function "get_test_datum_ids" line 1 at FOR über SELECT-Zeilen
Dieser Plan sieht schon deutlich anders aus. Zwar ist die Ausführungsgeschwindigkeit aufgrund der in diesem Beispiel recht kleinen Datenmengen noch überschaubar, jedoch kann man sich jetzt schon vorstellen, dass bei einer größeren Datenmenge dieser Plan schnell ineffizient werden kann. Doch warum wird an dieser Stelle ein anderer Plan verwendet?
Des Rätsels Lösung liegt an der parametrisierten Form dieser Abfrage, die in der FOR-Schleife verwendet wird. Der Optimizer kann nur einen generischen Plan für diese Art der WHERE-Bedingung erzeugen. Da der Offset für den Bereich innerhalb der Bedingung nicht zur Planungszeit zur Verfügung steht, muss der Optimizer den Plan auf einem möglichst allgemeingültigen Kostenmodell berechnen, der effizient für jeden Wert in der WHERE-Bedingung ist.
Konfiguration über postgresql.conf
auto_explain lässt sich auch global über die postgresql.conf konfigurieren. Möchte man als DBA beispielsweise das Modul auf jeden Fall für jede Datenbankverbindung laden, so benötigt man einen entsprechend konfigurierten Parameter shared_preload_libraries in der postgresql.conf (diese befindet sich in der Regel im Datenbankverzeichnis ihrer PostgreSQL-Installation, kann aber bei einigen Distributionen abweichen):
## globales Aktivieren von auto_explain
shared_preload_libraries = 'auto_explain'
Dies lädt das Modul bereits beim Start für jede Datenbankverbindung. Da PostgreSQL noch nicht die Konfigurationsparameter beim Laden der Konfigurationsdatei kennt, muss dies noch zusätzlich über den Parameter custom_variable_classes dem Server bekannt gemacht werden:
custom_variable_classes = 'auto_explain'
Nun kann in der Datei postgresql.conf der Parameter global konfiguriert werden, wie an folgendem Listing beispielhaft gezeigt:
auto_explain.log_min_duration = '30s'
auto_explain.log_format = 'xml'
Zusammenfassung
auto_explain ist ein nützliches Tool, um Geschwindigkeitsproblemen innerhalb der Datenbank anhand der EXPLAIN-Ausgaben auf den Grund zu gehen. Als wertvoll stellt sich die Möglichkeit heraus, eingebettete Abfragen innerhalb von SQL- oder PL/pgsql-Prozeduren mitprotokollieren zu können, um so auch die Abfragen im entsprechenden Kontext auf Fehler oder unterschiedliche Pläne hin untersuchen zu können.
auto_explain eignet sich jedoch nicht, um dauerhaft auf produktiven Datenbankmaschinen eingeschaltet zu sein, hierfür ist der zusätzliche Aufwand für das Ausschreiben der Pläne zu groß. Insofern sollte auf jeden Fall Gebrauch von auto_explain.log_min_duration gemacht werden, so dass wirklich nur sehr problematische Abfragen bei Überschreiten einer bestimmten Zeitschwelle protokolliert werden. Auch sollte dann auf produktiven Maschinen auf jeden Fall auto_explain.log_analyze deaktiviert sein, da dies auch Abfragen, die noch unterhalb der Zeitschwelle von auto_explain.log_min_duration liegen, negativ beeinflusst.
