MySQL lēno vaicājumu žurnāls: kā ieslēgt, lasīt un atrast būtisko

MySQL lēno vaicājumu žurnāls (slow query log) ir vieta, no kuras vajadzētu sākt lielāko daļu veiktspējas darba. Tas ieraksta katru izteikumu, kas izpildījās ilgāk par jūsu izvēlēto slieksni, kopā ar laikiem un rindu skaitu, un tā uzturēšana maksā ļoti maz. Tomēr daudzos serveros, ko redzam, tas ir vai nu izslēgts, kas ir noklusējums, vai ieslēgts ar noklusējuma 10 sekunžu slieksni, kas tīmekļa lietotnē nozīmē, ka tas gandrīz neko nenoķer, līdz lietotāji jau sūdzas.

Kas tiek ierakstīts un kas ne

Saskaņā ar MySQL rokasgrāmatu izteikums nonāk lēno vaicājumu žurnālā tikai tad, ja izpildās visi šie nosacījumi:

1. Tas nav administratīvs izteikums, piemēram, ALTER TABLE vai OPTIMIZE TABLE, ja vien nav ieslēgts log_slow_admin_statements.
2. Tas izpildījās vismaz long_query_time sekundes, vai arī ir ieslēgts log_queries_not_using_indexes un vaicājums rindu meklēšanai neizmantoja nevienu indeksu.
3. Tas pārbaudīja vismaz min_examined_row_limit rindas.
4. To neapslāpēja log_throttle_queries_not_using_indexes.

Dažas detaļas vērts zināt, pirms uzticēties žurnālam:

• Laiks, kas pavadīts sākotnējo bloķējumu iegūšanā, netiek ieskaitīts izpildes laikā. Vaicājums, kas 40 sekundes gaidīja rindas bloķējumu, šeit var izskatīties ātrs. Par šāda veida problēmām skatiet mūsu ceļvedi par "Lock wait timeout exceeded".
• Ieraksti tiek rakstīti pēc tam, kad izteikums ir pabeigts un tā bloķējumi atbrīvoti, tāpēc secība failā var atšķirties no izpildes secības.
• Izteikumi, kurus neizdodas parsēt, netiek ierakstīti, un paroles ierakstītajos izteikumos tiek pārrakstītas.
• Replikās replicētie izteikumi netiek ierakstīti, ja nav ieslēgts log_slow_replica_statements, un arī tad tam nav ietekmes uz rindu bāzētu replikāciju.

Ieslēgšana bez restarta

Visi galvenie iestatījumi ir dinamiski, tāpēc datus var sākt vākt strādājošā serverī:

SET GLOBAL slow_query_log_file = '/var/log/mysql/slow.log';
SET GLOBAL long_query_time = 1;
SET GLOBAL log_slow_extra = ON;
SET GLOBAL slow_query_log = ON;

-- check where it goes and that FILE output is enabled
SHOW GLOBAL VARIABLES WHERE Variable_name IN
  ('slow_query_log', 'slow_query_log_file', 'long_query_time', 'log_output');

Ja faila nosaukumu nenorādāt, MySQL raksta host_name-slow.log datu direktorijā. Pārbaudiet arī log_output: ja tajā nav FILE, failā nekas netiek rakstīts, lai gan žurnāls ir "ieslēgts".

Viens slazds noķer gandrīz visus. long_query_time pastāv arī sesijas līmenī, un sesijas mainīgie tiek inicializēti no globālajām vērtībām brīdī, kad klients pieslēdzas. Jūsu SET GLOBAL attiecas tikai uz jauniem savienojumiem. Lietotne ar ilgi dzīvojošu savienojumu pūlu turpina izmantot veco 10 sekunžu slieksni, līdz savienojumi tiek atjaunoti. Ja pēc izmaiņām žurnāls aizdomīgi paliek tukšs, iemesls parasti ir šis.

Ar SET GLOBAL veiktie iestatījumi pēc restarta pazūd. Kad esat ar tiem apmierināti, ierakstiet tos konfigurācijas failā vai izmantojiet SET PERSIST.

Kā izvēlēties long_query_time

Universāli pareiza skaitļa nav, bet noklusējuma 10 sekundes OLTP lietotnei gandrīz vienmēr ir par daudz. Vērtību var samazināt līdz 0, ar mikrosekunžu precizitāti. Praksē labi strādā divas pieejas:

• Pastāvīgs slieksnis ikdienas monitoringam, pietiekami zems, lai noķertu vaicājumus, kurus pamana lietotāji. Daudzām tīmekļa lietotnēm mēs sākam ar aptuveni vienu sekundi un samazinām to, kad acīmredzamās problēmas ir salabotas.
• Īss pilns ieraksts. Iestatot long_query_time = 0 uz ierobežotu laiku, piemēram, 15 minūtēm maksimālās slodzes laikā, tiek ierakstīts katrs izteikums. Tas dod pilnu ainu, ieskaitot ātrus vaicājumus, kas izpildās miljoniem reižu. Tas arī daudz raksta, tāpēc sekojiet diska vietai un atgrieziet vērtību atpakaļ.

log_queries_not_using_indexes izklausās noderīgs, bet rada daudz trokšņa: tas ieraksta arī mazas, ātras skenēšanas, kas ir pilnīgi normālas. Ja to ieslēdzat, iestatiet log_throttle_queries_not_using_indexes, lai ierobežotu, cik šādu ierakstu tiek rakstīts minūtē. min_examined_row_limit palīdz atfiltrēt triviālus vaicājumus.

Kā lasīt ierakstu

Tipisks ieraksts izskatās šādi:

# Query_time: 3.412907  Lock_time: 0.000012 Rows_sent: 20  Rows_examined: 1843210
SET timestamp=1762070400;
SELECT * FROM orders WHERE customer_email = '...' ORDER BY created_at DESC LIMIT 20;

Visnoderīgākais skaitlis bieži vien nav Query_time, bet attiecība starp Rows_examined un Rows_sent. Šeit MySQL nolasīja 1,8 miljonus rindu, lai atgrieztu 20. Tas gandrīz vienmēr nozīmē trūkstošu vai neizmantojamu indeksu, un tieši šādi vaicājumi kļūst krasi lēnāki, tabulai augot.

Ja ieslēgts log_slow_extra, katrā ierakstā ir arī handler skaitītāji (Read_rnd_next un līdzīgi), kārtošanas skaitītāji, atmiņā un diskā izveidotās pagaidu tabulas, nosūtītie un saņemtie baiti un kļūdas numurs. Liels Read_rnd_next nozīmē pilnu skenēšanu; Created_tmp_disk_tables virs nulles nozīmē, ka kārtošana vai grupēšana nonāca diskā.

Nelasiet failu, veidojiet kopsavilkumu

Noslogots serveris dienā var uzrakstīt gigabaitiem lēno vaicājumu žurnāla. Lasīt to no sākuma līdz beigām nav jēgas, jo atsevišķi lēnākais vaicājums reti ir tas, kas izmaksā visvairāk. 30 sekunžu atskaite, kas izpildās reizi naktī, ir mazāk svarīga nekā 200 ms vaicājums, kas izpildās 50 000 reižu stundā.

MySQL komplektā ir mysqldumpslow, kas grupē līdzīgus vaicājumus. Biežāk izmantotais rīks ir pt-query-digest no Percona Toolkit:

# top queries by total time over the last 24 hours
pt-query-digest --since 24h /var/log/mysql/slow.log > slow-report.txt

# only SELECTs
pt-query-digest --filter '$event->{arg} =~ m/^select/i' /var/log/mysql/slow.log

Pēc noklusējuma tas sakārto vaicājumu "pirkstu nospiedumus" pēc kopējā izpildes laika (Query_time:sum) un parāda 95% vai 20 populārākos, atkarībā no tā, kas sasniegts pirmais. Profils atskaites sākumā katram nospiedumam rāda tā daļu kopējā atbildes laikā, izsaukumu skaitu, vidējo laiku uz izsaukumu un dispersijas un vidējās vērtības attiecību. Liela dispersija nozīmē vaicājumu, kas parasti ir ātrs un dažreiz briesmīgs, un tā bieži ir bloķēšanas vai parametru vērtībām atkarīga plāna pazīme. Zem profila katram vaicājumam ir sava sadaļa ar procentilēm, laika histogrammu un parauga izteikumu, ko var padot EXPLAIN.

Nav piekļuves žurnāla failam? Izmantojiet Performance Schema

Pārvaldītos pakalpojumos vai tad, ja skaitļi vajadzīgi tūlīt, tabula events_statements_summary_by_digest dod tādu pašu sarindojumu bez jebkāda žurnāla faila. Tā apkopo izteikumus pēc normalizēta teksta un shēmas kopš pēdējās atiestatīšanas:

SELECT SCHEMA_NAME,
       LEFT(DIGEST_TEXT, 120)               AS query,
       COUNT_STAR                           AS calls,
       ROUND(SUM_TIMER_WAIT / 1e12, 1)      AS total_s,
       ROUND(QUANTILE_95 / 1e12, 3)         AS p95_s,
       SUM_ROWS_EXAMINED, SUM_ROWS_SENT,
       SUM_NO_INDEX_USED
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC
LIMIT 10;

Taimeru kolonnas ir pikosekundēs, tāpēc dalām ar 1e12. SUM_NO_INDEX_USED skaita izpildes ar pilnu skenēšanu. Lai izmērītu konkrētu periodu, pierakstiet skaitļus pirms un pēc vai iztīriet tabulu ar TRUNCATE TABLE. Tabulai ir fiksēts izmērs, ko nosaka performance_schema_digests_size; kad tā ir pilna, jaunie izteikumi tiek sagrupēti rindā ar NULL digest vērtību. Ja šī rinda ir liela, rokasgrāmata iesaka palielināt izmēru.

Uzturiet to darbībā

• Rotējiet failu. Pēc tā pārvietošanas izpildiet FLUSH SLOW LOGS, lai MySQL atvērtu jaunu failu.
• Palaidiet kopsavilkumu pēc grafika, katru dienu vai nedēļu, un salīdziniet to ar iepriekšējo. Jauns nospiedums saraksta augšgalā parasti ieradies ar nesenu izlaidumu.
• Pēc labojuma pārliecinieties par rezultātu ar EXPLAIN ANALYZE un nākamo kopsavilkumu, nevis ar vienu ātru izpildi ar "siltu" kešatmiņu.

Metode ir vienāda jebkurā dzinējā; mūsu PostgreSQL lēno vaicājumu kontrolsaraksts to izskaidro no PostgreSQL puses.