Lassú lekérdezések hibaelhárítása és azonosítása a rugalmas Azure Database for PostgreSQL-kiszolgálón

A következőkre vonatkozik: Azure Database for PostgreSQL – Rugalmas kiszolgáló

Ez a cikk bemutatja, hogyan háríthatja el és azonosíthatja a lassan futó lekérdezéseket a rugalmas Azure Database for PostgreSQL-kiszolgálóval.

A magas cpu-kihasználtság esetén ebben a cikkben a következő lépéseket ismerheti meg:

• Lassú lekérdezések azonosítása.

• Azonosítsa a lassan futó eljárást vele együtt. Azonosítsa a lassú lekérdezést egy olyan lekérdezések listájában, amelyek ugyanahhoz a lassan futó tárolt eljáráshoz tartoznak.

Magas cpu-forgatókönyv – Lassú lekérdezés azonosítása

Előfeltételek

Engedélyezni kell a hibaelhárítási útmutatókat és auto_explain bővítményt a rugalmas Azure Database for PostgreSQL-kiszolgálópéldányon. A hibaelhárítási útmutatók engedélyezéséhez kövesse az itt ismertetett lépéseket.

A auto_explain bővítmény engedélyezéséhez kövesse az alábbi lépéseket:

1. Adja hozzá auto_explain bővítményt a megosztott előbetöltési kódtárakhoz, ahogyan az alább látható, a rugalmas Azure Database for PostgreSQL kiszolgálói portál kiszolgálóparaméterek lapján látható.

   

Feljegyzés

A módosítás elvégzéséhez a kiszolgáló újraindítása szükséges.

2. Miután hozzáadta a auto_explain bővítményt a megosztott előtöltési kódtárakhoz, és a kiszolgáló újraindult, módosítsa az alábbi kiemelt auto_explain kiszolgálóparamétereket ON a rugalmas Azure Database for PostgreSQL kiszolgálói portál kiszolgálóparaméterek oldaláról, és hagyja meg a többit alapértelmezett értékekkel az alábbiak szerint.

   

Feljegyzés

A paraméter 0-ra való frissítése auto_explain.log_min_duration megkezdi a kiszolgálón végrehajtott összes lekérdezés naplózását. Ez befolyásolhatja az adatbázis teljesítményét. A megfelelő kellő gondossággal olyan értéket kell létrehozni, amely lassúnak minősül a kiszolgálón. Ha például 30 másodpercet tekintünk küszöbértéknek, és minden 30 másodperc alatt futtatott lekérdezés elfogadható az alkalmazás számára, javasoljuk, hogy frissítse a paramétert 30000 ezredmásodpercre. Ez ezután naplózza a kiszolgálón 30 másodpercnél hosszabban végrehajtott lekérdezéseket.

Forgatókönyv – Lassú lekérdezés azonosítása

A hibaelhárítási útmutatók és auto_explain bővítmények segítségével egy példa segítségével ismertetjük a forgatókönyvet.

Van egy forgatókönyvünk, amelyben a processzorhasználat 90%-ra nőtt, és tudni szeretné a kiugró teljesítmény kiváltó okát. A forgatókönyv hibakereséséhez kövesse az alábbi lépéseket.

1. Amint egy CPU-forgatókönyv riasztást kap, lépjen a rugalmas Azure Database for PostgreSQL-kiszolgáló portáljának Súgó lapján elérhető hibaelhárítási útmutatókra.

   

2. A megnyitott lapon válassza a Magas processzorhasználat lapot. Megnyílik a magas cpu-kihasználtság hibaelhárítási útmutatója.

   

3. Válassza ki a jelentett cpu-csúcs időtartományát az időtartomány legördülő listájával.

   

4. Válassza a Processzorhasználati lekérdezések lapfület.

   A lap az összes lekérdezés részleteit osztja meg, amelyek abban az időszakban futottak, amikor a processzorhasználat 90%-os volt. A pillanatképből úgy tűnik, hogy a leglassabb átlagos végrehajtási időt tartalmazó lekérdezés az időintervallum alatt ~2,6 perc volt, a lekérdezés pedig 22-szer futott az intervallum alatt. Ez valószínűleg a cpu-kiugró csúcsok oka.

   

5. Csatlakozzon azure_sys adatbázishoz, és hajtsa végre a lekérdezést a lekérdezés tényleges szövegének lekéréséhez az alábbi szkripttel.

    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. A vizsgált példában a lassúnak talált lekérdezés a következő volt:

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

7. A pontos magyarázó terv létrehozásához használja az Azure Database for PostgreSQL rugalmas kiszolgálónaplóit. Az automatikus magyarázó bővítmény minden alkalommal naplózott egy bejegyzést a naplókban, amikor a lekérdezés végrehajtása az intervallum alatt befejeződött. Az Azure Database for PostgreSQL rugalmas kiszolgálóportál áttekintési lapján válassza a Monitoring Naplók szakaszt a lapról.

   

8. Válassza ki azt az időtartományt, ahol a processzorhasználat 90%-os volt.

   

9. Hajtsa végre a következő lekérdezést az azonosított lekérdezés magyarázó elemzési kimenetének lekéréséhez.

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

Az üzenetoszlop az alábbi módon tárolja a végrehajtási tervet:

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

A lekérdezés ~2,5 percig futott a hibaelhárítási útmutatókban látható módon, és a lekért végrehajtási terv kimenetének 150692,864 ms-os értéke megerősíti duration . A magyarázó elemzési kimenettel további hibaelhárítást és a lekérdezés finomhangolását használhatja.

Feljegyzés

Vegye figyelembe, hogy a lekérdezés 22 alkalommal futott az intervallum alatt, és a fent látható naplók az intervallum során rögzítettek egy ilyen bejegyzést.

Magas cpu-forgatókönyv – Az eljáráshoz társított lassú eljárás és lassú lekérdezések azonosítása

A második forgatókönyvben a tárolt eljárás végrehajtási ideje lassú, a cél pedig a tárolt eljárás részét képező lassú lekérdezés azonosítása és finomhangolása.

Előfeltételek

Előfeltételként engedélyezni kell a hibaelhárítási útmutatókat és auto_explain bővítményt a rugalmas Azure Database for PostgreSQL-kiszolgálópéldányon. A hibaelhárítási útmutatók engedélyezéséhez kövesse az itt ismertetett lépéseket.

A auto_explain bővítmény engedélyezéséhez kövesse az alábbi lépéseket:

1. Adja hozzá auto_explain bővítményt a megosztott előbetöltési kódtárakhoz, ahogyan az alább látható, a rugalmas Azure Database for PostgreSQL kiszolgálói portál kiszolgálóparaméterek lapján látható.

   

Feljegyzés

A módosítás elvégzéséhez a kiszolgáló újraindítása szükséges.

2. Miután hozzáadta a auto_explain bővítményt a megosztott előtöltési kódtárakhoz, és a kiszolgáló újraindult, módosítsa az alábbi kiemelt auto_explain kiszolgálóparamétereket ON a rugalmas Azure Database for PostgreSQL kiszolgálói portál kiszolgálóparaméterek oldaláról, és hagyja meg a többit alapértelmezett értékekkel az alábbiak szerint.

   

Feljegyzés

• A paraméter 0-ra való frissítése auto_explain.log_min_duration megkezdi a kiszolgálón végrehajtott összes lekérdezés naplózását. Ez befolyásolhatja az adatbázis teljesítményét. A megfelelő kellő gondossággal olyan értéket kell létrehozni, amely lassúnak minősül a kiszolgálón. Ha például 30 másodpercet tekintünk küszöbértéknek, és minden 30 másodperc alatt futtatott lekérdezés elfogadható az alkalmazás számára, javasoljuk, hogy frissítse a paramétert 30000 ezredmásodpercre. Ez ezután naplózza a kiszolgálón 30 másodpercnél hosszabban végrehajtott lekérdezéseket.
• A paraméter auto_explain.log_nested_statements a beágyazott utasításokat (függvényben vagy eljárásban végrehajtott utasításokat) a naplózás szempontjából figyelembe veszi. Ha ki van kapcsolva, csak a legfelső szintű lekérdezési tervek lesznek naplózva. 

Forgatókönyv – Lassú lekérdezés azonosítása tárolt eljárásban

A hibaelhárítási útmutatók és auto_explain bővítmények segítségével egy példa segítségével ismertetjük a forgatókönyvet.

Van egy forgatókönyvünk, amelyben a processzorhasználat 90%-ra nőtt, és tudni szeretné a kiugró teljesítmény kiváltó okát. A forgatókönyv hibakereséséhez kövesse az alábbi lépéseket.

1. Amint egy CPU-forgatókönyv riasztást kap, lépjen a rugalmas Azure Database for PostgreSQL-kiszolgáló portáljának Súgó lapján elérhető hibaelhárítási útmutatókra.

   

2. A megnyitott lapon válassza a Magas processzorhasználat lapot. Megnyílik a magas cpu-kihasználtság hibaelhárítási útmutatója.

   

3. Válassza ki a jelentett cpu-csúcs időtartományát az időtartomány legördülő listájával.

   

4. Válassza a Processzorhasználati lekérdezések lapfület.

   A lap az összes lekérdezés részleteit osztja meg, amelyek abban az időszakban futottak, amikor a processzorhasználat 90%-os volt. A pillanatképből úgy tűnik, hogy a leglassabb átlagos végrehajtási időt tartalmazó lekérdezés az időintervallum alatt ~6,3 perc volt, a lekérdezés pedig 35-ször futott az intervallum alatt. Ez valószínűleg a cpu-kiugró csúcsok oka.

   

   Fontos megjegyezni az alábbi pillanatképből, hogy az alább kiemelt lekérdezéstípus a "Segédprogram". A segédprogramok általában az intervallum alatt futó tárolt eljárások vagy függvények lehetnek.

5. Csatlakozzon azure_sys adatbázishoz, és hajtsa végre a lekérdezést a lekérdezés tényleges szövegének lekéréséhez az alábbi szkript használatával.

    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. A vizsgált példában a lassúnak talált lekérdezés egy tárolt eljárás volt az alábbiak szerint:

    call autoexplain_test ();

7. A tárolt eljárás részét képező lekérdezések pontos magyarázatainak megismeréséhez használja a rugalmas Azure Database for PostgreSQL-kiszolgálónaplókat. Az automatikus magyarázó bővítmény minden alkalommal naplózott egy bejegyzést a naplókban, amikor a lekérdezés végrehajtása az intervallum alatt befejeződött. A rugalmas Azure Database for PostgreSQL kiszolgálóportál áttekintési oldalán válassza a Monitoring Naplók szakaszt a lapról.

   

8. Válassza ki azt az időtartományt, ahol a processzorhasználat 90%-os volt.

   

9. Hajtsa végre az alábbi lekérdezést az azonosított lekérdezés magyarázó elemzési kimenetének lekéréséhez.

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

Az eljárás több lekérdezéssel rendelkezik, amelyeket az alábbiakban emelünk ki. A tárolt eljárásban használt összes lekérdezés kimenetének magyarázata be van jelentkezve a további elemzéshez és a hibaelhárításhoz. A naplózott lekérdezések végrehajtási ideje a tárolt eljárás részét képező leglassabb lekérdezések azonosítására használható.

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

Feljegyzés

Kérjük, vegye figyelembe, hogy a bemutató célja az eljárásban használt kevés lekérdezés kimenetének elemzése. Az ötlet az, hogy összegyűjtheti a naplókból származó összes lekérdezés kimenetének elemzését, majd azonosíthatja a leglassabb lekérdezéseket, és megpróbálhatja finomhangolni őket.

Kapcsolódó tartalom

• Magas cpu-kihasználtság
• Autovacuum hangolása