MySQL slow_log: Pronadji najcesce i najsporije query digeste

Kada MySQL aplikacija uspori, gledanje samo najduzeg pojedinacnog upita cesto nije dovoljno.

Upit koji je jednom trajao 15 sekundi moze biti manje vazan od drugog upita koji traje 800 ms, ali se izvrsava 50,000 puta.

Tokom resavanja problema sa performansama baze podataka, obicno zelimo da odgovorimo na tri razlicita pitanja:

1. Koji obrasci upita se pojavljuju najcesce?
2. Koji obrasci upita trose najvise ukupnog vremena baze podataka?
3. Koji obrasci upita imaju najlosije pojedinacno vreme izvrsavanja?

Ako MySQL upisuje svoj slow query log u TABLE, sva tri pitanja mogu da se odgovore direktno iz mysql.slow_log.

Problem sa gledanjem sirovih upita

Posmatrajmo upite kao sto su:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

SELECT *
FROM orders
WHERE customer_id = 12891;

SELECT *
FROM orders
WHERE customer_id = 73102;

SELECT *
FROM orders
WHERE customer_id = 44183;

Ovo su tri razlicita SQL niza, ali operativno su to isti upit:

1
2
3

SELECT *
FROM orders
WHERE customer_id = ?;

Grupisanje po originalnom sql_text bi zato sakrilo stvarnu ucestalost obrasca upita.

Ono sto nam treba jeste otisak upita, ili normalizovana reprezentacija nalik digestu.

Prvo proverite da li je slow log dostupan

Za ovaj pristup, MySQL treba da upisuje spore upite u tabelu mysql.slow_log.

1
2
3
4
5
6

SHOW VARIABLES
WHERE Variable_name IN (
    'slow_query_log',
    'log_output',
    'long_query_time'
);

Tipicna konfiguracija izgleda ovako:

1
2
3

slow_query_log = ON
log_output      = TABLE
long_query_time = 1

Odgovarajuci long_query_time u velikoj meri zavisi od workload-a. Ako je previsok, sakricete vazne upite koji se cesto izvrsavaju; ako je prenizak, mozete dobiti veoma veliki slow log.

Zasto jednostavno ne koristiti STATEMENT_DIGEST()?

MySQL 8 pruza:

1
2

STATEMENT_DIGEST()
STATEMENT_DIGEST_TEXT()

Na primer:

1
2
3
4

SELECT
    STATEMENT_DIGEST_TEXT(
        'SELECT * FROM orders WHERE customer_id = 123'
    );

vraca normalizovanu reprezentaciju slicnu ovoj:

1

SELECT * FROM `orders` WHERE `customer_id` = ?

Ovo izgleda idealno.

Postoji jedan praktican problem kada se ovo primenjuje na istorijske podatke iz mysql.slow_log: ove funkcije pozivaju MySQL SQL parser.

Ako makar jedan sacuvani statement ne moze da se parsira, sama analiza moze da propadne sa greskom kao sto je:

1

ERROR 3677 (HY000): Could not parse argument to digest function.

To je posebno nezgodno kada se analiziraju hiljade ili milioni istorijskih slow-log zapisa.

Za istrazivacko resavanje problema, jednostavan SQL fingerprint zato moze da bude robusniji.

Napravite bezbedan query fingerprint

Sledeci primer:

• konvertuje sql_text u tekst;
• uklanja string literale;
• zamenjuje numericke literale;
• sabija beline;
• generise kratak SHA-256 fingerprint.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40

WITH normalized AS (
    SELECT
        start_time,
        TIME_TO_SEC(query_time) AS query_sec,
        rows_examined,

        REGEXP_REPLACE(
            REGEXP_REPLACE(
                REGEXP_REPLACE(
                    TRIM(CONVERT(sql_text USING utf8mb4)),
                    '''([^'']|'''')*''',
                    '?'
                ),
                '[[:digit:]]+([.][[:digit:]]+)?',
                '?'
            ),
            '[[:space:]]+',
            ' '
        ) AS normalized_query

    FROM mysql.slow_log

    WHERE start_time >= NOW() - INTERVAL 24 HOUR
)
SELECT
    LEFT(SHA2(normalized_query, 256), 16) AS digest,
    normalized_query,
    COUNT(*) AS executions,
    ROUND(AVG(query_sec), 3) AS avg_sec,
    ROUND(MAX(query_sec), 3) AS max_sec,
    ROUND(SUM(query_sec), 3) AS total_sec,
    SUM(rows_examined) AS rows_examined,
    MAX(start_time) AS last_seen

FROM normalized

GROUP BY normalized_query

ORDER BY executions DESC, total_sec DESC
LIMIT 20;

Rezultat odmah pretvara veliki slow log u nesto mnogo korisnije:

1
2
3
4
5

digest            executions  avg_sec  max_sec  total_sec
----------------  ----------  -------  -------  ---------
a9d41765d18bf731       12843    0.821    7.192   10543.2
d921ef580c21899a        3812    1.972   11.402    7516.4
ef112046e59898a4          41   18.241   29.102     747.9

Sada mozemo da razlikujemo veoma razlicite probleme sa performansama.

Pronadjite najcesce obrasce upita

Za upite koji generisu opterecenje kroz ponavljanje:

1
2

ORDER BY executions DESC, total_sec DESC
LIMIT 20;

Ovo je posebno korisno za otkrivanje ponasanja aplikacije kao sto su:

• polling;
• N+1 upiti;
• preterani API pozivi;
• ponovljena trazenja sesija;
• neefikasni pozadinski worker-i;
• nedostajuce keširanje na strani aplikacije.

Upit ne mora da bude izuzetno spor pojedinacno da bi postao skup.

Na primer:

1

0.4 seconds × 100,000 executions = 11.1 database-hours

Taj upit moze zasluziti vise paznje nego jedan 20-sekundni izvestaj.

Pronadjite upite koji stvaraju najvise ukupnog opterecenja

U mnogim ispitivanjima, ovo je najkorisnije rangiranje:

1
2

ORDER BY total_sec DESC
LIMIT 20;

total_sec odgovara na drugo pitanje:

Koliko je ukupnog vremena izvrsavanja baze podataka potrosila ova familija upita tokom izabranog intervala?

Ovo cesto identifikuje najbolje ciljeve za optimizaciju jer kombinuje ucestalost i latenciju.

Upit sa:

1
2
3

executions = 20,000
avg_sec    = 0.7
total_sec  = 14,000

je obicno mnogo zanimljiviji od:

1
2
3

executions = 3
avg_sec    = 20
total_sec  = 60

Drugi upit izgleda mnogo gore kada se posmatraju pojedinacni slow-log zapisi, ali prvi znatno vise opterecuje bazu podataka.

Pronadjite obrasce upita sa najgorom latencijom

Za istrazivanje ekstremnih vremena odziva, koristite:

1
2

ORDER BY max_sec DESC
LIMIT 20;

Alternativno, koristite prosecno vreme izvrsavanja:

1
2

ORDER BY avg_sec DESC
LIMIT 20;

Ova rangiranja su korisna za pronalazenje upita na koje uticu:

• losi planovi izvrsavanja;
• veliki scan-ovi;
• nedostajuci indeksi;
• privremene tabele;
• sortiranje;
• zakljucavanja;
• veoma promenljiva selektivnost parametara.

Ipak, uvek pogledajte i executions i total_sec. Veoma spor upit koji se izvrsava jednom nedeljno mozda nije problem sa najvisim prioritetom.

Iskljucite interval odrzavanja

Slow log cesto sadrzi backup-e, izvestaje, batch obradu, odrzavajuce poslove ili druga opterecenja koja ne bi trebalo da uticu na normalnu analizu aplikacije.

Na primer, da biste ignorisali upite izmedju ponoci i 04:00:

1
2

WHERE start_time >= NOW() - INTERVAL 7 DAY
  AND TIME(start_time) NOT BETWEEN '00:00:00' AND '03:59:59'

Ovaj mali korak filtriranja moze potpuno da promeni rangiranje na sistemima sa velikim nocnim workload-om.

Pregledajte stvarne primere nakon sto pronadjete digest

Normalizacija je korisna za rangiranje, ali optimizacija i dalje zahteva originalni SQL.

Nakon sto identifikujete interesantnu familiju upita, preuzmite nedavne primere iz mysql.slow_log i pregledajte ih:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15

SELECT
    start_time,
    query_time,
    lock_time,
    rows_sent,
    rows_examined,
    db,
    CONVERT(sql_text USING utf8mb4) AS query_text

FROM mysql.slow_log

WHERE start_time >= NOW() - INTERVAL 24 HOUR

ORDER BY query_time DESC
LIMIT 50;

Odavde se standardna istraga nastavlja alatima kao sto su:

1

EXPLAIN

ili, tamo gde je bezbedno i odgovarajuce:

1

EXPLAIN ANALYZE

Slow log nam govori koji upiti zasluzuju paznju. Plan izvrsavanja nam govori zasto su skupi.

Native MySQL digesti su i dalje korisni

Ako je poznato da se SQL sacuvan u logu moze parsirati, native MySQL digest funkcije pruzaju tacniju SQL-svesnu normalizaciju:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19

SELECT
    STATEMENT_DIGEST(
        CONVERT(sql_text USING utf8mb4)
    ) AS digest,

    STATEMENT_DIGEST_TEXT(
        CONVERT(sql_text USING utf8mb4)
    ) AS digest_text,

    COUNT(*) AS executions

FROM mysql.slow_log

GROUP BY
    digest,
    digest_text

ORDER BY executions DESC
LIMIT 20;

Ovo bi obicno trebalo preferirati kada radi pouzdano.

Fingerprint baziran na regularnim izrazima opisan ranije nije namenjen da tacno reprodukuje MySQL parser. Njegova svrha je drugacija: da obezbedi robusan nacin za grupisanje istorijskih slow-log zapisa kada digest na osnovu parsera nije pouzdan za svaki sacuvani statement.

Najsporije ne znaci i najvaznije

Korisni pregled performansi obicno cuva najmanje tri rangiranja:

U praksi, ukupno vreme izvrsavanja je cesto najbolji prvi red za optimizaciju, zatim ucestalost, pa tek onda pojedinacni ekstremi.

Ovo sprecava cesto gresku pri resavanju problema: trosenje sati na optimizaciju vizuelno impresivnog 30-sekundnog upita dok mnogo manji upit tiho trosi redove velicine vise kapaciteta baze podataka.

Od jednokratnog upita do monitoringa

Kada ova analiza postane korisna tokom incidenta, obicno vredi pretvoriti je u mali Grafana dashboard.

Korisni raspored je:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

Slow queries over time
        |
        +-- Top query load
        |      ORDER BY total_sec
        |
        +-- Most frequent
        |      ORDER BY executions
        |
        +-- Slowest
               ORDER BY query_time

Ovo daje inzenjerima brz put od:

1

"Baza podataka je spora"

do:

1

"Ove tri familije upita su proizvele vecinu opterecenja baze tokom incidenta."

To je mnogo bolja polazna tacka za optimizaciju baze podataka.