In jeder Bereitstellung gibt es immer ein paar Abfragen, die zu langsam laufen.
Lesen Sie weiter, um zu erfahren, wie Sie Abfragen erkennen, deren Ausführung zu lange dauert, und wie Sie herausfinden, warum sie langsam sind.
Einfach pg_stat_statements verwenden?
pg_stat_statements ist eine beliebte Erweiterung, die in der zentralen PostgreSQL-Distribution enthalten und standardmäßig bei fast allen DBaaS-Anbietern verfügbar ist. Es ist von unschätzbarem Wert und mehr oder weniger die einzige Möglichkeit, Statistiken zu Abfragen zu erhalten, ohne benutzerdefinierte Erweiterungen zu installieren.
Es hat jedoch ein paar Einschränkungen, wenn es darum geht, langsame Abfragen zu erkennen.
Kumulative Statistiken
Die pg_stat_statements-Erweiterung bietet kumulativ Statistiken über jede jemals vom Server ausgeführte Abfrage. Für jede Abfrage zeigt es neben anderen Metriken die Gesamtzahl der ausgeführten Male und die Gesamtzeit für alle Ausführungen.
Um langsame Abfragen „abzufangen“, wenn sie auftreten, müssen Sie regelmäßig den gesamten Inhalt der pg_stat_statements abrufen anzeigen, in einer Zeitreihendatenbank speichern und die Ausführungszahlen vergleichen. Wenn Sie beispielsweise den Inhalt von pg_stat_statements um 10:00 Uhr und 10:10 Uhr haben, können Sie die Abfragen auswählen, die um 10:10 Uhr eine höhere Ausführungsanzahl haben als um 10:00 Uhr. Für diese Abfragen können Sie die durchschnittliche Ausführungszeit während dieses Intervalls berechnen, indem Sie Folgendes verwenden:
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Wenn diese durchschnittliche Ausführungszeit einen oberen Schwellenwert überschreitet, können Sie eine Warnung auslösen, um Maßnahmen zu ergreifen.
Dies funktioniert in der Praxis ziemlich gut, aber Sie benötigen eine gute Überwachungsinfrastruktur oder einen dedizierten Dienst wie pgDash.
Abfrageparameter
pg_stat_statements erfasst nicht die Werte von Bindungsparametern, die an Abfragen übergeben werden.
Eines der Dinge, die der Postgres-Abfrageplaner für die Auswahl eines Ausführungsplans schätzt, ist die Anzahl der Zeilen, die eine Bedingung wahrscheinlich herausfiltern wird. Zum Beispiel, wenn die meisten Zeilen einer Tabelle den Wert einer indizierten Spalte Land haben B. „US“, entscheidet sich der Planer möglicherweise für einen sequentiellen Scan der gesamten Tabelle für das wo Klausel country = "US" , und entscheiden sich möglicherweise für einen Index-Scan für country = "UK" seit dem ersten wo -Klausel wird erwartet, dass sie mit den meisten Zeilen in der Tabelle übereinstimmt.
Wenn Sie den tatsächlichen Wert der Parameter kennen, für die die Abfrageausführung langsam war, können Sie Probleme mit langsamen Abfragen schneller diagnostizieren.
Langsame Abfrageprotokollierung
Die einfachere Alternative besteht darin, langsame Abfragen zu protokollieren. Im Gegensatz zu einem bestimmten anderen DBMS, das dies einfach macht, präsentiert uns PostgreSQL eine Reihe ähnlich aussehender Konfigurationseinstellungen:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Diese sind in der Postgres-Dokumentation ausführlich beschrieben. Hier ist ein vernünftiger Ausgangspunkt:
# next line says only log queries that take longer 5 seconds
log_min_duration_statement = 5s
log_parameter_max_length = 1024
log_parameter_max_length_on_error = 1024
Was zu Protokollen wie diesen führt:
2022-04-14 06:17:11.462 UTC [369399] LOG: duration: 5.060 ms statement: select i.*, t."Name" as track, ar."Name" as artist
from "InvoiceLine" as i
join "Track" as t on i."TrackId" = t."TrackId"
join "Album" as al on al."AlbumId" = t."AlbumId"
join "Artist" as ar on ar."ArtistId" = al."ArtistId";
Wenn zu viele Protokolle vorhanden sind, können Sie Postgres bitten, nur (sagen wir) 50 % der Abfragen zu protokollieren, die länger als 5 Sekunden laufen:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Sie sollten sich natürlich die Dokumentation darüber durchlesen, was diese Parameter bedeuten und implizieren, bevor Sie sie zu Ihrer Postgres-Konfiguration hinzufügen. Seien Sie gewarnt, dass die Einstellungen eigenartig und nicht intuitiv sind.
Ausführungspläne für langsame Abfragen
Es reicht im Allgemeinen nicht aus zu wissen, dass eine langsame Abfrage stattgefunden hat, Sie müssen auch herausfinden, warum es war langsam. Dazu überprüfen Sie normalerweise zuerst den Ausführungsplan der Abfrage.
auto_explain ist eine weitere zentrale PostgreSQL-Erweiterung (wiederum auch für die meisten DBaaS verfügbar), die die Ausführungspläne von Abfragen protokollieren kann, die gerade ausgeführt wurden. Es ist hier dokumentiert.
Um auto_explain zu aktivieren, fügen Sie es normalerweise zu shared_preload_libraries hinzu und starten Sie Postgres neu. Hier ist ein Beispiel für eine Starterkonfiguration:
# logs execution plans of queries that take 10s or more to run
auto_explain.log_min_duration = 10s
auto_explain.log_verbose = on
auto_explain.log_settings = on
auto_explain.log_format = json
auto_explain.log_nested_statements = on
# enabling these provide more information, but have a performance cost
#auto_explain.log_analyze = on
#auto_explain.log_buffers = on
#auto_explain.log_wal = on
#auto_explain.log_timing = on
#auto_explain.log_triggers = on
Dadurch werden Pläne im JSON-Format protokolliert, die dann in Tools wie diesen visualisiert werden können.
Abfragen werden noch ausgeführt
Alle oben aufgeführten Techniken haben eines gemeinsam:Sie erzeugen nur nach umsetzbare Ergebnisse eine Abfrage hat die Ausführung beendet. Sie können nicht verwendet werden, um Abfragen zu verarbeiten, die diesmal so langsam sind, dass ihre Ausführung noch nicht abgeschlossen ist.
Jede Verbindung zu einem PostgreSQL-Server wird von einem Backend verwaltet , insbesondere ein Client-Backend . Wenn ein solches Backend eine Abfrage ausführt, ist sein Status aktiv . Es könnte auch eine Transaktion gestartet haben, ist dann aber im Leerlauf, genannt Idle in Transaction Zustand.
Die pg_stat_activity Die hier dokumentierte Systemansicht bietet eine Liste aller laufenden Postgres-Backends. Sie können diese Ansicht abfragen, um Abfragen zu erhalten, die noch ausgeführt werden:
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
Übrigens gibt es ohne die Verwendung von Erweiterungen von Drittanbietern keine Möglichkeit, den Ausführungsplan einer Abfrage zu kennen, die derzeit von einem Backend ausgeführt wird.
Sperren
Wenn der Ausführungsplan einer langsamen Abfrage keine offensichtlichen Probleme anzeigt, wurde das Backend, das die Abfrage ausführt, möglicherweise durch umstrittene Sperren verzögert.
Sperren werden aus verschiedenen Gründen entweder explizit oder implizit während der Abfrageausführung abgerufen. Dem ist ein ganzes Kapitel in der Postgres-Dokumentation gewidmet.
Logging-Sperren
Typischerweise wird mit der Option lock_timeout eine Obergrenze für die Wartezeit festgelegt , normalerweise auf der Clientseite. Wenn eine Abfrage so lange auf eine Sperre gewartet hat, bricht Postgres die Ausführung dieser Abfrage ab und protokolliert einen Fehler:
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 ERROR: canceling statement due to lock timeout
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 STATEMENT: cluster t;
Angenommen, Sie möchten ein Sperrzeitlimit von 1 Minute festlegen, aber Abfragen protokollieren, die länger als beispielsweise 30 Sekunden auf Sperren warten. Sie können dies tun mit:
log_lock_waits = on
deadlock_timeout = 30s
Dadurch werden Protokolle wie diese erstellt:
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 LOG: process 70 still waiting for ShareLock on transaction 493 after 30009.004 ms
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 68. Wait queue: 70.
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 STATEMENT: select * from t for update;
Die Verwendung von deadlock_timeout ist kein Tippfehler:Es ist der Wert, den der Lock-Wait-Protokollierungsmechanismus verwendet. Idealerweise sollte so etwas wie log_min_duration_lock_wait stehen , aber das ist leider nicht der Fall.
Im Falle tatsächlicher Deadlocks bricht Postgres die Deadlock-Transaktionen nach deadlock_timeout ab Dauer und protokolliert die anstößigen Aussagen. Es ist keine explizite Konfiguration erforderlich.
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 LOG: process 68 detected deadlock while waiting for ShareLock on transaction 496 after 30007.633 ms
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 70. Wait queue: .
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 ERROR: deadlock detected
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process 68 waits for ShareLock on transaction 496; blocked by process 70.
Process 70 waits for ShareLock on transaction 495; blocked by process 68.
Process 68: select * from t where a=4 for update;
Process 70: select * from t where a=0 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 HINT: See server log for query details.
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
Aktuelle Sperren entdecken
Die gesamte Liste der derzeit gewährten Sperren ist in der pg_locks-Systemansicht verfügbar. In der Regel ist es jedoch einfacher, die Funktion pg_blocking_pids zu verwenden , zusammen mit pg_stat_activity , etwa so:
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
die eine Ausgabe wie diese zeigen kann:
state | pid | pg_blocking_pids | query
---------------------+--------+------------------+-------------------------------------------------
active | 378170 | {} | SELECT state, pid, pg_blocking_pids(pid), query+
| | | FROM pg_stat_activity +
| | | WHERE backend_type='client backend';
active | 369399 | {378068} | cluster "Track";
idle in transaction | 378068 | {} | select * from "Track" for update;
(3 rows)
was anzeigt, dass es ein Backend gibt, das blockiert ist (dasjenige, das die CLUSTER-Anweisung ausführt), und dass es von PID 378068 blockiert wird (die ein SELECT..FOR UPDATE ausgeführt hat, aber dann innerhalb der Transaktion im Leerlauf ist).
