Identifizieren langsam ausgeführter Abfragen in Azure Database for PostgreSQL – Flexibler Server und Problembehandlung

GILT FÜR: Azure Database for PostgreSQL – Flexible Server

In diesem Artikel erfahren Sie, wie Sie langsam ausgeführte Abfragen mithilfe von Azure Database for PostgreSQL flexiblen Server behandeln und identifizieren.

In diesem Artikel, der von einem Szenario mit hoher CPU-Auslastung ausgeht, erfahren Sie, wie Sie:

• langsam ausgeführte Abfragen identifizieren.

• eine in diesem Zusammenhang langsam ausgeführte Prozedur identifizieren. eine langsame Abfrage innerhalb einer Liste von Abfragen identifizieren, die zur gleichen langsam ausgeführten gespeicherten Prozedur gehören.

Szenario mit hoher CPU-Auslastung: Identifizieren einer langsam ausgeführten Abfrage

Voraussetzungen

Eine muss Anleitungen zur Problembehandlung und auto_explain Erweiterung in der Azure-Datenbank für flexible Serverinstanz von PostgreSQL aktivieren. Um die Anleitungen zur Problembehandlung zu aktivieren, führen Sie die hier aufgeführten Schritte aus.

Führen Sie die folgenden Schritte aus, um die auto_explain-Erweiterung zu aktivieren:

1. Fügen Sie auto_explain Erweiterung zu den freigegebenen Vorabladebibliotheken hinzu, wie unten auf der Seite "Serverparameter" im flexiblen Serverportal der Azure-Datenbank für PostgreSQL gezeigt.

   

Hinweis

Für diese Änderung ist ein Serverneustart erforderlich.

2. Nachdem die auto_explain-Erweiterung freigegebenen Preload-Bibliotheken hinzugefügt wurde und der Server neu gestartet wurde, ändern Sie die unten hervorgehobenen auto_explain Serverparameter ON von der Serverparameterseite im Flexiblen Serverportal der Azure-Datenbank für PostgreSQL, und lassen Sie die neu Standard mit Standardwerten wie unten dargestellt.

   

Hinweis

Das Aktualisieren des auto_explain.log_min_duration-Parameters auf Null startet die Protokollierung aller Abfragen, die auf dem Server ausgeführt werden. Dies kann sich auf die Leistung der Datenbank auswirken. Sie müssen eine ordnungsgemäße Due Diligence durchführen, um zu einem Wert zu gelangen, der auf dem Server als langsam betrachtet werden kann. Wenn beispielsweise 30 Sekunden als Schwellenwert betrachtet und alle Abfragen, die in weniger als 30 Sekunden ausgeführt werden, für die Anwendung akzeptabel sind, wird empfohlen, den Parameter auf 30.000 Millisekunden zu aktualisieren. Dies würde dazu führen, dass jede Abfrage protokolliert wird, deren Ausführung auf dem Server mehr als 30 Sekunden dauert.

Szenario: Identifizieren langsam ausgeführte Abfragen

Da Ihnen nun die Anleitungen zur Problembehandlung und die auto_explain-Erweiterung zur Verfügung stehen, kann das Szenario mithilfe eines Beispiels erläutert werden.

Wir befinden uns in einem Szenario, in dem die CPU-Auslastung auf 90 % gestiegen ist, und möchten die Ursache dieser Auslastungsspitze herausfinden. Führen Sie die unten angegebenen Schritte aus, um das Szenario zu debuggen.

1. Sobald Sie von einem CPU-Szenario benachrichtigt werden, wechseln Sie zu den Anleitungen zur Problembehandlung, die auf der Registerkarte "Hilfe" auf der Übersichtsseite des flexiblen Serverportals von Azure Database für PostgreSQL zur Verfügung stehen.

   

2. Wählen Sie auf der Seite, die sich öffnet, die Registerkarte „Hohe CPU-Auslastung“ aus. Die Anleitung zur Problembehandlung bei hoher CPU-Auslastung öffnet sich.

   

3. Wählen Sie den Zeitbereich der gemeldeten CPU-Spitzen mithilfe der entsprechenden Dropdownliste aus.

   

4. Wählen Sie die Registerkarte „Abfragen mit der höchsten CPU-Auslastung“ aus.

   Auf der Registerkarte werden die Details zu allen Abfragen angezeigt, die in dem Zeitintervall ausgeführt wurden, in dem CPU-Auslastungsspitzen von 90 % vorlagen. Die Momentaufnahme lässt darauf schließen, dass die Abfrage mit der langsamsten durchschnittlichen Ausführungszeit während des Zeitintervalls ca. 2,6 Minuten benötigte und während des Intervalls 22 Mal ausgeführt wurde. Dies ist höchstwahrscheinlich die Ursache der CPU-Auslastungsspitzen.

   

5. Verbinden, um die Datenbank zu azure_sys und die Abfrage auszuführen, um den tatsächlichen Abfragetext mithilfe des folgenden Skripts abzurufen.

    psql -h ServerName.postgres.database.azure.com -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;

6. In diesem Beispiel war die als langsam identifizierte Abfrage die folgende:

SELECT  c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id,c_id
order by c_w_id;

7. Verwenden Sie Azure Database für flexible Serverprotokolle, um zu verstehen, welcher genaue Erklärungsplan generiert wurde. Die auto_explain-Erweiterung hätte bei jeder Ausführung der Abfrage im Zeitintervall einen Eintrag in den Protokollen vorgenommen. Wählen Sie den Abschnitt "Protokolle" auf der Registerkarte auf der Monitoring Übersichtsseite des Azure Database for PostgreSQL flexiblen Serverportals aus.

   

8. Wählen Sie den Zeitbereich aus, in dem eine CPU-Auslastung von 90 % gefunden wurde.

   

9. Führen Sie die folgende Abfrage aus, um die Analyseausgabe der identifizierten Abfrage abzurufen.

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<add snippet of SQL text identified or add table name involved in the query>"
| project TimeGenerated, Message

In der Nachrichtenspalte wird der Ausführungsplan wie unten dargestellt gespeichert:

2023-10-10 19:56:46 UTC-6525a8e7.2e3d-LOG: duration: 150692.864 ms plan:

Query Text: SELECT c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id,c_id
order by c_w_id;
GroupAggregate (cost=1906820.83..2131820.83 rows=10000000 width=40) (actual time=70930.833..129231.950 rows=10000000 loops=1)
Output: c_id, sum(c_balance), c_w_id
Group Key: customer.c_w_id, customer.c_id
Buffers: shared hit=44639 read=355362, temp read=77521 written=77701
-> Sort (cost=1906820.83..1931820.83 rows=10000000 width=13) (actual time=70930.821..81898.430 rows=10000000 loops=1)
Output: c_id, c_w_id, c_balance
Sort Key: customer.c_w_id, customer.c_id
Sort Method: external merge Disk: 225104kB
Buffers: shared hit=44639 read=355362, temp read=77521 written=77701
-> Seq Scan on public.customer (cost=0.00..500001.00 rows=10000000 width=13) (actual time=0.021..22997.697 rows=10000000 loops=1)
Output: c_id, c_w_id, c_balance

Die Abfrage wurde wie in den Anleitungen zur Problembehandlung dargestellt ca. 2,5 Minuten lang ausgeführt, was von der Ausgabe des duration-Werts (150.692,864 ms) aus dem abgerufenen Ausführungsplan bestätigt wird. Verwenden Sie die „Analyse erläutern“-Ausgabe, um die Problembehandlung fortzusetzen und die Abfrage zu optimieren.

Hinweis

Beachten Sie, dass die Abfrage im Zeitintervall 22 Mal ausgeführt wurde, und dass die oben gezeigten Protokolle einer der Einträge sind, die im Zeitintervall erfasst wurden.

Szenario mit hoher CPU-Auslastung: Identifizieren langsam ausgeführter Prozeduren und Abfragen, die der Prozedur zugeordnet sind

Im zweiten Szenario wird eine Ausführungszeit für gespeicherte Prozeduren als langsam erkannt. Das Ziel besteht nun darin, die langsam ausgeführte Abfrage, die Teil der gespeicherten Prozedur ist, zu identifizieren und zu optimieren.

Voraussetzungen

Eine muss Anleitungen zur Problembehandlung und auto_explain Erweiterung in der Azure-Datenbank für flexible Serverinstanz für PostgreSQL als Voraussetzung aktivieren. Um die Anleitungen zur Problembehandlung zu aktivieren, führen Sie die hier aufgeführten Schritte aus.

Führen Sie die folgenden Schritte aus, um die auto_explain-Erweiterung zu aktivieren:

1. Fügen Sie auto_explain Erweiterung zu den freigegebenen Vorabladebibliotheken hinzu, wie unten auf der Seite "Serverparameter" im flexiblen Serverportal der Azure-Datenbank für PostgreSQL gezeigt.

   

Hinweis

Für diese Änderung ist ein Serverneustart erforderlich.

2. Nachdem die auto_explain-Erweiterung freigegebenen Preload-Bibliotheken hinzugefügt wurde und der Server neu gestartet wurde, ändern Sie die unten hervorgehobenen auto_explain Serverparameter ON von der Serverparameterseite im Flexiblen Serverportal der Azure-Datenbank für PostgreSQL, und lassen Sie die neu Standard mit Standardwerten wie unten dargestellt.

   

Hinweis

• Das Aktualisieren des auto_explain.log_min_duration-Parameters auf Null startet die Protokollierung aller Abfragen, die auf dem Server ausgeführt werden. Dies kann sich auf die Leistung der Datenbank auswirken. Sie müssen eine ordnungsgemäße Due Diligence durchführen, um zu einem Wert zu gelangen, der auf dem Server als langsam betrachtet werden kann. Wenn beispielsweise 30 Sekunden als Schwellenwert betrachtet und alle Abfragen, die in weniger als 30 Sekunden ausgeführt werden, für die Anwendung akzeptabel sind, wird empfohlen, den Parameter auf 30.000 Millisekunden zu aktualisieren. Dies würde dazu führen, dass jede Abfrage protokolliert wird, deren Ausführung auf dem Server mehr als 30 Sekunden dauert.
• Der Parameter auto_explain.log_nested_statements bewirkt, dass geschachtelte Anweisungen (Anweisungen, die in einer Funktion oder Prozedur ausgeführt werden) für die Protokollierung berücksichtigt werden. Wenn deaktiviert, werden nur Abfragepläne der obersten Ebene protokolliert. 

Szenario: Identifizieren langsam ausgeführte Abfragen in einer gespeicherten Prozedur

Da Ihnen nun die Anleitungen zur Problembehandlung und die auto_explain-Erweiterung zur Verfügung stehen, kann das Szenario mithilfe eines Beispiels erläutert werden.

Wir befinden uns in einem Szenario, in dem die CPU-Auslastung auf 90 % gestiegen ist, und möchten die Ursache dieser Auslastungsspitze herausfinden. Führen Sie die unten angegebenen Schritte aus, um das Szenario zu debuggen.

1. Sobald Sie von einem CPU-Szenario benachrichtigt werden, wechseln Sie zu den Anleitungen zur Problembehandlung, die auf der Registerkarte "Hilfe" auf der Übersichtsseite des flexiblen Serverportals von Azure Database für PostgreSQL zur Verfügung stehen.

   

2. Wählen Sie auf der Seite, die sich öffnet, die Registerkarte „Hohe CPU-Auslastung“ aus. Die Anleitung zur Problembehandlung bei hoher CPU-Auslastung öffnet sich.

   

3. Wählen Sie den Zeitbereich der gemeldeten CPU-Spitzen mithilfe der entsprechenden Dropdownliste aus.

   

4. Wählen Sie die Registerkarte „Abfragen mit der höchsten CPU-Auslastung“ aus.

   Auf der Registerkarte werden die Details zu allen Abfragen angezeigt, die in dem Zeitintervall ausgeführt wurden, in dem CPU-Auslastungsspitzen von 90 % vorlagen. Die Momentaufnahme lässt darauf schließen, dass die Abfrage mit der langsamsten durchschnittlichen Ausführungszeit während des Zeitintervalls ca. 6,3 Minuten benötigte und während des Intervalls 35 Mal ausgeführt wurde. Dies ist höchstwahrscheinlich die Ursache der CPU-Auslastungsspitzen.

   

   Beachten Sie in der Momentaufnahme, dass der hervorgehobene Abfragetyp „Utility“ (Hilfsprogramm) lautet. Im Allgemeinen kann ein Hilfsprogramm (Utility) eine gespeicherte Prozedur oder Funktion sein, die im Zeitintervall ausgeführt wird.

5. Stellen Sie eine Verbindung mit der azure_sys-Datenbank her, und verwenden Sie das folgende Skript, um den tatsächlichen Abfragetext abzurufen.

    psql -h ServerName.postgres.database.azure.com -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;

6. Im Beispiel war die als langsam identifizierte Abfrage wie unten erwähnt eine gespeicherte Prozedur:

    call autoexplain_test ();

7. Verwenden Sie Azure Database für flexible Serverprotokolle, um zu verstehen, welche genauen Erklärungen für die Abfragen generiert werden, die Teil der gespeicherten Prozedur sind. Die auto_explain-Erweiterung hätte bei jeder Ausführung der Abfrage im Zeitintervall einen Eintrag in den Protokollen vorgenommen. Wählen Sie den Abschnitt "Protokolle" auf der Registerkarte auf der Monitoring Übersichtsseite des Flexiblen Serverportals von Azure Database for PostgreSQL aus.

   

8. Wählen Sie den Zeitbereich aus, in dem eine CPU-Auslastung von 90 % gefunden wurde.

   

9. Führen Sie die folgende Abfrage aus, um die „Analyse erläutern“-Ausgabe der identifizierten Abfrage abzurufen.

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<add a snippet of SQL text identified or add table name involved in the queries related to stored procedure>"
| project TimeGenerated, Message

Die Prozedur enthält mehrere Abfragen, die unten hervorgehoben sind. Die „Analyse erläutern“-Ausgabe jeder Abfrage, die in der gespeicherten Prozedur verwendet wird, wird protokolliert, um weitere Analysen und Problembehandlungen zu ermöglichen. Die Ausführungszeit der protokollierten Abfragen kann verwendet werden, um die langsamsten Abfragen zu identifizieren, die Teil der gespeicherten Prozedur sind.

2023-10-11 17:52:45 UTC-6526d7f0.7f67-LOG: duration: 38459.176 ms plan:

Query Text: insert into customer_balance SELECT c_id, SUM(c_balance) AS total_balance FROM customer GROUP BY c_w_id,c_id order by c_w_id
Insert on public.customer_balance (cost=1906820.83..2231820.83 rows=0 width=0) (actual time=38459.173..38459.174 rows=0 loops=1)Buffers: shared hit=10108203 read=454055 dirtied=54058, temp read=77521 written=77701 WAL: records=10000000 fpi=1 bytes=640002197
    -> Subquery Scan on "*SELECT*" (cost=1906820.83..2231820.83 rows=10000000 width=36) (actual time=20415.738..29514.742 rows=10000000 loops=1)
        Output: "*SELECT*".c_id, "*SELECT*".total_balance Buffers: shared hit=1 read=400000, temp read=77521 written=77701
            -> GroupAggregate (cost=1906820.83..2131820.83 rows=10000000 width=40) (actual time=20415.737..28574.266 rows=10000000 loops=1)
                Output: customer.c_id, sum(customer.c_balance), customer.c_w_id Group Key: customer.c_w_id, customer.c_id Buffers: shared hit=1 read=400000, temp read=77521 written=77701
                -> Sort (cost=1906820.83..1931820.83 rows=10000000 width=13) (actual time=20415.723..22023.515 rows=10000000 loops=1)
                    Output: customer.c_id, customer.c_w_id, customer.c_balance Sort Key: customer.c_w_id, customer.c_id Sort Method: external merge Disk: 225104kB Buffers: shared hit=1 read=400000, temp read=77521 written=77701
                     -> Seq Scan on public.customer (cost=0.00..500001.00 rows=10000000 width=13) (actual time=0.310..15061.471 rows=10000000 loops=1) Output: customer.c_id, customer.c_w_id, customer.c_balance Buffers: shared hit=1 read=400000

2023-10-11 17:52:07 UTC-6526d7f0.7f67-LOG: duration: 61939.529 ms plan:
Query Text: delete from customer_balance
Delete on public.customer_balance (cost=0.00..799173.51 rows=0 width=0) (actual time=61939.525..61939.526 rows=0 loops=1) Buffers: shared hit=50027707 read=620942 dirtied=295462 written=71785 WAL: records=50026565 fpi=34 bytes=2711252160
    -> Seq Scan on public.customer_balance (cost=0.00..799173.51 rows=15052451 width=6) (actual time=3185.519..35234.061 rows=50000000 loops=1)
        Output: ctid Buffers: shared hit=27707 read=620942 dirtied=26565 written=71785 WAL: records=26565 fpi=34 bytes=11252160


2023-10-11 17:51:05 UTC-6526d7f0.7f67-LOG: duration: 10387.322 ms plan:
Query Text: select max(c_id) from customer
Finalize Aggregate (cost=180185.84..180185.85 rows=1 width=4) (actual time=10387.220..10387.319 rows=1 loops=1) Output: max(c_id) Buffers: shared hit=37148 read=1204 written=69
    -> Gather (cost=180185.63..180185.84 rows=2 width=4) (actual time=10387.214..10387.314 rows=1 loops=1)
        Output: (PARTIAL max(c_id)) Workers Planned: 2 Workers Launched: 0 Buffers: shared hit=37148 read=1204 written=69
        -> Partial Aggregate (cost=179185.63..179185.64 rows=1 width=4) (actual time=10387.012..10387.013 rows=1 loops=1) Output: PARTIAL max(c_id) Buffers: shared hit=37148 read=1204 written=69
            -> Parallel Index Only Scan using customer_i1 on public.customer (cost=0.43..168768.96 rows=4166667 width=4) (actual time=0.446..7676.356 rows=10000000 loops=1)
               Output: c_w_id, c_d_id, c_id Heap Fetches: 24 Buffers: shared hit=37148 read=1204 written=69

Hinweis

Bitte beachten Sie, dass zur Demonstration die Analyseausgabe von nur wenigen Abfragen erläutert wird, die in der Prozedur verwendet werden. Die Idee dahinter ist, dass man die „Analyse erläutern“-Ausgabe aller Abfragen aus den Protokollen sammeln und dann die langsamsten identifizieren und versuchen kann, sie zu optimieren.

Zugehöriger Inhalt

• Hohe CPU-Auslastung
• Autovacuum-Optimierung