Poprzednio pisałem o tym, co znajduje się w pierwszej części raportu generowanego przez mk-query-digest. Dziś zajmiemy się resztą. Pierwsza sekcja to posortowana pod względem wybranego przez użytkownika atrybutu lista wszystkich schematów zapytań. Domyślnie sortowane są one po sumie czasu wykonania – na początku lądują schematy zapytania, które zajęły najwięcej czasu. Przykładowo taka sekcja może wyglądać tak:
# Rank Query ID Response time Calls R/Call Item
# ==== ================== ================ ===== ======== ================
# 1 0x2C4499CEBFBDE985 355.1854 9.0% 90 3.9465 SELECT ps_product ps_product_lang ps_image ps_image_lang ps_tax ps_category_group ps_category_product
# 2 0x043BCFC15A4C7F15 300.3267 7.6% 76 3.9517 SELECT allegro_auctions
# 3 0xF4230AF7750CF4AA 227.8298 5.8% 98 2.3248 UPDATE mybb_users
# 4 0xE1598CBB9AEE7DE1 149.4173 3.8% 49 3.0493 SELECT mybb_posts
# 5 0x4967BBEDCF36B29C 142.6522 3.6% 18 7.9251 SELECT jos_session
# 6 0x2DD7929E432F2112 139.5068 3.5% 50 2.7901 SELECT mybb_users mybb_userfields
# 7 0x05872ECC22546540 131.2421 3.3% 44 2.9828 DELETE jos_session
# 8 0xE8C426410BF3D7B0 130.6269 3.3% 19 6.8751 SELECT produkty seo
# 9 0x8921FDE85D08295F 114.1535 2.9% 45 2.5367 DELETE mybb_sessions
# 10 0xFACBD40CFACD1AAE 107.4832 2.7% 15 7.1655 UPDATE vld_members
# 11 0x19C1D3FB71C3F6F8 99.9117 2.5% 37 2.7003 SELECT mybb_sessions
# 12 0x71E6CCAC8F09C2E1 81.3847 2.1% 24 3.3910 DELETE mybb_sessions
# 13 0x9F0F56AE4E89EDEF 69.4614 1.8% 24 2.8942 SELECT product_special review product product_description product_special manufacturer stock_status product_discount
# 14 0xDC9489D1478B5CEF 68.0753 1.7% 11 6.1887 INSERT logi_www
# 15 0x6813B9B896477FF4 66.2721 1.7% 26 2.5489 SELECT mybb_threads
# 16 0x127EB9004F7C71C3 58.2252 1.5% 10 5.8225 SELECT produkty seo
# 17 0x4DDD16DF961337F4 54.4435 1.4% 21 2.5925 UPDATE stats_counters
# 18 0x7F84F05DFBF5C3E3 52.7417 1.3% 13 4.0571 SELECT produkty producenci
# 19 0x39EF8414BAABF63A 51.4078 1.3% 16 3.2130 SELECT mybb_privatemessages
# 20 0x50B012B84A236154 49.7462 1.3% 22 2.2612 UPDATE jos_session
# 21 0x813031B8BBC3B329 46.4510 1.2% 11 4.2228 COMMIT
# 22 0xE8AEB5F449FBFCFD 45.8707 1.2% 20 2.2935 UPDATE mybb_sessions
# 24 0x4CE83FC120FC4C2E 34.6862 0.9% 13 2.6682 SELECT produkty
# 25 0x13883BD7B91A0823 34.3275 0.9% 16 2.1455 SELECT mybb_threads mybb_users mybb_threadratings mybb_threadprefixes
# 26 0x10590E2776FFB443 33.8784 0.9% 20 1.6939 SELECT mybb_privatemessages
# 30 0x58E0C2660F51564E 30.4800 0.8% 18 1.6933 UPDATE mybb_threads
# 31 0xA2D023311A41CD63 30.3245 0.8% 10 3.0324 SELECT vld_members vld_members_data_members
# 42 0xE80ED521B2432DA1 19.2108 0.5% 10 1.9211 INSERT mybb_posts
# MISC 0xMISC 1207.7081 30.7% 402 3.0042 <186 ITEMS>
Jak widać, mamy tu kilka kolumn. Pozycja na liście, ID zapytania (przydaje się do bardziej zaawansowanych kombinacji, generowania zestawień, raportów itp.), łączy czas wykonania danego schematu, jaki procent całości czasu wykonania wszystkich zapytań zajmuje ten konkretny schemat, ile zapytań podchodzących pod dany schemat zostało znalezionych w slowlogach, jaki jest średni czas wywołania pojedynczego zapytania, jak wygląda dany schemat (jaki rodzaj zapytania, jakie tabele biorą w nim udział). Ostatnia pozycja w zestawieniu to suma czasów wywołać pozostałych schematów zapytań, które nie załapały się na miejsce wyżej w zestawieniu.
Przechodzimy do informacji o poszczególnych zapytaniach.
# This item is included in the report because it matches --limit.
# Attribute pct total min max avg 95% stddev median
# ========= ====== ======= ======= ======= ======= ======= ======= =======
# Count 7 90
# Exec time 9 355s 1s 29s 4s 11s 4s 2s
# Lock time 0 24ms 148us 393us 267us 316us 40us 260us
# Rows sent 0 88 0 1 0.98 0.99 0.15 0.99
# Rows exam 1 178.70k 240 2.03k 1.99k 1.96k 261.00 1.96k
# Users 2 user1 (88/97%), user2 (2/2%)
# Hosts 1 host.example.com
# Databases 2 baza1 (88/97%), baza2 (2/2%)
# Time range 2011-01-10 07:28:23 to 2011-01-10 13:13:21
# bytes 13 83.94k 955 955 955 955 0 955
# Bytes sen 0 931.76k 2.65k 37.40k 10.35k 20.37k 6.71k 8.46k
# Killed 0 0 0 0 0 0 0 0
# Last errn 0 0 0 0 0 0 0 0
# Merge pas 0 0 0 0 0 0 0 0
# Rows affe 0 0 0 0 0 0 0 0
# Rows read 0 88 0 1 0.98 0.99 0.15 0.99
# Tmp disk 35 90 1 1 1 1 0 1
# Tmp table 32 90 1 1 1 1 0 1
# Tmp table 14 224.18M 0 2.70M 2.49M 2.62M 496.99k 2.62M
# 100% (90) Filesort
# 100% (90) Full_scan
# 100% (90) Tmp_table
# 100% (90) Tmp_table_on_disk
Powyższy fragment to statystyki, podobne do tych opisanych w poprzednim poście. Tam dotyczyły zbiorczo wszystkich zapytań, tu dotyczą tego konkretnego schematu. Dodatkowymi informacjami, jakie się pojawiają, jest to do jakich baz idą zapytania o takim schemacie i jacy użytkownicy je wykonują. W powyższym przykładzie widać, że zapytanie tego typu wykonywane jest w dwóch bazach danych – baza1 i baza2. 97% zapytań pochodzi z bazy baza1.
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+ ######
# Tables
# SHOW TABLE STATUS FROM `baza1` LIKE 'ps_product'\G
# SHOW CREATE TABLE `baza1`.`ps_product`\G
# SHOW TABLE STATUS FROM `baza1` LIKE 'ps_product_lang'\G
# SHOW CREATE TABLE `baza1`.`ps_product_lang`\G
# SHOW TABLE STATUS FROM `baza1` LIKE 'ps_image'\G
# SHOW CREATE TABLE `baza1`.`ps_image`\G
# SHOW TABLE STATUS FROM `baza1` LIKE 'ps_image_lang'\G
# SHOW CREATE TABLE `baza1`.`ps_image_lang`\G
# SHOW TABLE STATUS FROM `baza1` LIKE 'ps_tax'\G
# SHOW CREATE TABLE `baza1`.`ps_tax`\G
# SHOW TABLE STATUS FROM `baza1` LIKE 'ps_category_group'\G
# SHOW CREATE TABLE `baza1`.`ps_category_group`\G
# SHOW TABLE STATUS FROM `baza1` LIKE 'ps_category_product'\G
# SHOW CREATE TABLE `baza1`.`ps_category_product`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT p.*....\G
Ostatni fragment to rozkład czasu wykonywania zapytania – widzimy tu że w większości wypadków zapytanie to trwa 1 – 9 sekundy. Czasami jednak jest to ponad 10 sekund. Tego typu wykres staje się pełniejszy jeśli posiadamy MySQL w wersji 5.1, lub zaaplikowany odpowiedni patch do MySQL 5.0. Wtedy możemy zmniejszyć long_query_time do wartości mniejszych niż 1 sekunda i uzyskać pełniejszy rozkład czasów wykonania zapytania. Takie informacje są bardzo przydatne do zlokalizowania problematycznych zapytań. Zazwyczaj ważne jest to, aby dane zapytanie wykonywało się w przewidywalnym czasie. Jeśli widzimy, że jedno zapytanie raz wykonuje się w 0.001 sekundy, raz zajmuje to kilka sekund a raz ponad dziesięć, znaczy to że coś jest mocno nie tak. Z zapytaniem, z konfiguracją serwera, ze sprzętem – trzeba to sprawdzić, bo tego typu rozpiętość czasowa jest bardzo dziwna.
Dalsze informacje w tym fragmencie to polecenia do wklejenia do konsoli mysql. Dzięki nim uzyskamy informację o tabelach, które są wykorzystywane w danym zapytaniu, a także zobaczymy jaki plan ma dany typ zapytania. W powyższym przykładzie usunąłem zawartość SELECT’a – mk-query-digest umieszcza tam jedno, konkretne zapytanie w pełnej postaci. Wybrane zapytanie jest najgorszym z całego analizowanego zestawu danych, pod kątem parametru według którego sortowane są zapytania (domyślnie jest to zapytanie, które było najdłużej wykonywane).
Takie precyzyjne informacje pozwalają na określenie najbardziej problematycznych zapytań – łatwo sprawdzić np. które zapytanie generuje obciążenie na dysku (tabele tymczasowe, ilość sprawdzonych rekordów), można wyłapać te zapytania, które wykonują pełny skan tabeli itp. Warto zaznajomić się z mk-query-digest – to narzędzie jest na prawdę niezastąpione jeśli chodzi o analizę zapytań serwera MySQL. Najlepiej będzie współpracować z Percona Server, jako że ta wersja serwera dodaje dużo dodatkowych informacji do slowloga, które to informacje można wykorzystać do analizy. Jednak nawet w przypadku standardowego MySQL tego typu zestawienie będzie pomocne, choć już nie tak pełne danych.
Komentarze