Megosztás a következőn keresztül:

Lassan futó lekérdezések hibaelhárítása és azonosítása az Azure Database for PostgreSQL-ben

Ez a cikk azt ismerteti, hogyan azonosíthatja és diagnosztizálhatja a lassú futtatású lekérdezések kiváltó okát.

Ebben a cikkben a következőt ismerheti meg:

  • Lassú lekérdezések azonosítása.
  • Lassú futású eljárás azonosítása 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.

Előfeltételek

  1. A hibaelhárítási útmutatókban leírt lépések végrehajtásával engedélyezheti a hibaelhárítási útmutatókat.

  2. Konfigurálja a bővítményt a auto_explain bővítmény engedélyezésével és betöltésével.

  3. A auto_explain bővítmény konfigurálása után módosítsa a következő kiszolgálóparamétereket, amelyek a bővítmény viselkedését szabályozzák:

    • auto_explain.log_analyze ON hez
    • auto_explain.log_buffers ON hez
    • auto_explain.log_min_duration a forgatókönyvben ésszerűnek megfelelően.
    • auto_explain.log_timing ON hez
    • auto_explain.log_verbose ON hez

    Képernyőkép auto_explain konfigurálni kívánt kiszolgálóparaméterekről.

Feljegyzés

Ha 0 értékre állítja auto_explain.log_min_duration , a bővítmény elkezdi naplózni a kiszolgálón végrehajtott összes lekérdezést. 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 az összes lekérdezés kevesebb, mint 30 másodperc alatt fejeződik be, és ez elfogadható az alkalmazás számára, akkor javasoljuk, hogy frissítse a paramétert 30 000 ezredmásodpercre. Ez ezután naplózza a lekérdezéseket, ami 30 másodpercnél hosszabb időt vesz igénybe.

Lassú lekérdezés azonosítása

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

Van egy olyan forgatókönyvünk, amelyben a cpu-kihasználtság 90%-ra emelkedik, és meg szeretné határozni a kiugró értéket. 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, válassza a Rugalmas Azure Database for PostgreSQL-kiszolgáló érintett példányának erőforrásmenüjében a Figyelés szakaszban válassza a Hibaelhárítási útmutatók lehetőséget.

    Képernyőkép a hibaelhárítási útmutatók menüpontról.

  2. Válassza a CPU lapot. Megnyílik a magas cpu-kihasználtság optimalizálása hibaelhárítási útmutató.

    Képernyőkép a hibaelhárítási útmutatók menüjéről – lapok.

  3. Az Elemzési időszak (helyi idő) legördülő listában válassza ki azt az időtartományt, amelyre az elemzést összpontosítani szeretné.

    Képernyőkép a hibaelhárítási útmutatók menüjéről – CPU lap.

  4. Válassza a Lekérdezések lapot. A 90%-os processzorkihasználtság időszakában futtatott összes lekérdezés részleteit mutatja. 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. Valószínűleg ez a lekérdezés okozza a processzor kiugró csúcsait.

    Képernyőkép a hibaelhárítási útmutatók menüjéről – A legnagyobb processzorhasználati lekérdezések lap.

  5. A lekérdezés tényleges szövegének lekéréséhez csatlakozzon az azure_sys adatbázishoz, és hajtsa végre a következő lekérdezést.

    psql -h <server>.postgres.database.azure.com -U <user> -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <query_id>;
  1. 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;

  1. A pontos magyarázó terv létrehozásához használja az Azure Database for PostgreSQL-naplókat. Minden alkalommal, amikor a lekérdezés befejeződött az adott időszak alatt, a auto_explain bővítménynek be kell írnia egy bejegyzést a naplókba. Az erőforrásmenü Figyelés szakaszában válassza a Naplók lehetőséget.

    Képernyőkép a hibaelhárítási útmutatók menüjéről – Naplók.

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

    Képernyőkép egy időablak kiválasztásáról a hibaelhárítási útmutatókban.

  3. Hajtsa végre az alábbi lekérdezést az azonosított lekérdezés EXPLAIN ANALYZE kimenetének lekéréséhez.

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

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

2024-11-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, ahogy a hibaelhárítási útmutató is mutatja. A duration lekért végrehajtási terv kimenetéből származó 150692.864 ms érték megerősíti. A EXPLAIN ANALYZE kimenetével további hibaelhárítást és a lekérdezés finomhangolását használhatja.

Feljegyzés

Figyelje meg, hogy a lekérdezés 22 alkalommal futott az intervallum alatt, és a megjelenített naplók tartalmazzák az intervallum során rögzített bejegyzéseket.

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 olyan forgatókönyvünk, amelyben a cpu-kihasználtság 90%-ra emelkedik, és meg szeretné határozni a kiugró értéket. 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, válassza a Rugalmas Azure Database for PostgreSQL-kiszolgáló érintett példányának erőforrásmenüjében a Figyelés szakaszban válassza a Hibaelhárítási útmutatók lehetőséget.

    Képernyőkép a hibaelhárítási útmutatók menüjéről.

  2. Válassza a CPU lapot. Megnyílik a magas cpu-kihasználtság optimalizálása hibaelhárítási útmutató.

    Képernyőkép a hibaelhárítási útmutatók lapjairól.

  3. Az Elemzési időszak (helyi idő) legördülő listában válassza ki azt az időtartományt, amelyre az elemzést összpontosítani szeretné.

    Képernyőkép a hibaelhárítási útmutatókról – CPU lap.

  4. Válassza a Lekérdezések lapot. A 90%-os processzorkihasználtság időszakában futtatott összes lekérdezés részleteit mutatja. 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. Valószínűleg ez a lekérdezés okozza a processzor kiugró csúcsait.

    Képernyőkép a hibaelhárítási útmutatókról – CPU lap – lekérdezések.

  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 <server>.postgres.database.azure.com -U <user> -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <query_id>;
  1. A vizsgált példában a lassúnak talált lekérdezés tárolt eljárás volt:
    call autoexplain_test ();
  1. A pontos magyarázó terv létrehozásához használja az Azure Database for PostgreSQL-naplókat. Minden alkalommal, amikor a lekérdezés befejeződött az adott időszak alatt, a auto_explain bővítménynek be kell írnia egy bejegyzést a naplókba. Az erőforrásmenü Figyelés szakaszában válassza a Naplók lehetőséget. Ezután az Időtartományban válassza ki azt az időablakot, ahová az elemzést összpontosítani szeretné.

Képernyőkép a hibaelhárítási útmutatók menüjéről – Naplók időtartománya.

  1. 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 "<snippet of SQL text identified or name of any of the tables referenced in the query>"
| 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ó.

2024-11-10 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

2024-11-10 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

2024-11-10 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

Bemutató célokra az eljárásban használt néhány lekérdezés EXPLAIN ANALYZE kimenete jelenik meg. Az ötlet az, hogy összegyűjtheti a naplók összes lekérdezésének EXPLAIN ANALYZE kimenetét, és azonosíthatja a leglassabb lekérdezéseket, és megpróbálhatja finomhangolni őket.

Kapcsolódó tartalom

  • Last updated on