Tak jak obiecałem w poprzednim poście, tym razem opiszę dlaczego narzędzie mk-query-digest jest czymś genialnym, dlaczego Barona Schwartza należałoby ozłocić i dlaczego trudno mi wyobrazić sobie pracę bez tego narzędzia.
W trakcie analizy wydajności serwera i szukania przyczyn wolniejszego działania bazy najbardziej przydatnym źródłem informacji dla administratora są slowlogi. Dawno dawno temu opisywałem (tu i tu) jakie informacje można w nich znaleźć. W zależności od tego, jaką wersję serwera MySQL używamy może ich być mniej lub więcej. W przypadku Percona Server informacji tych jest zazwyczaj wystarczająco aby zlokalizować zapytanie będące przyczyną problemu – zapytanie to jednak najpierw musi do logów trafić. Domyślnie, MySQL loguje zapytania o czasie wykonywania dłuższym niż 10 sekund. W większości wypadków jest to dużo za dużo. Osobiście stosuję long_query_time=1;. W przypadku interaktywnej pracy z bazą (czyli ktoś klika na stronie, zapytanie idzie do bazy a w tym czasie użytkownik czeka na wynik) jedna sekunda to takie minimum przyzwoitości. Jeśli konieczne jest dłuższe oczekiwanie, użytkownik zacznie się frustrować. Zazwyczaj takie ustawienie logowania wystarczy, aby wyłapać te zapytania, które są nieoptymalne i które są przyczyną dużego obciążenia CPU czy dysku. Problem pojawia się jednak wtedy, gdy w slowlogu niczego podejrzanego nie widać. Oczywiście, rozwiązaniem jest włączenie logowania wszystkich zapytań – ustawiamy zmienną long_query_time na 0. W ten sposób wszystkie zapytania trafiają do slowlogów a my liczymy na to, że skoro przyczyną nie jest jedno długie zapytanie, to może będzie to większa liczba szybkich. Niestety, tu mamy kolejny problem. O ile kilkaset zapytań w logu możemy ręcznie przeglądnąć i przeanalizować, to po włączeniu logowania wszystkich zapytań do logów trafią nawet miliony zapytań dziennie. Tego już nie da się ręcznie przeglądnąć. Tu przydaje się agregator taki jak mk-query-digest.
Zasada działania jest prosta – skrypt parsuje slowlogi wybierając występujące w nich pewne powtarzalne schematy zapytań. Czyli np. wszystkie zapytania typu:
SELECT a,b,c FROM x WHERE a=42;
SELECT a,b,c FROM x WHERE a=69;
SELECT a,b,c FROM x WHERE a=134;
podpadają pod schemat:
Dla każdej takiej grupy zliczane są statystyki takie jak np. łączny czas wykonywania, ilość odczytywanych rekordów, ilość przesłanych danych. Całe zestawienie jest sortowane po jakimś podanym parametrze i w efekcie mamy ładne podsumowanie tego, co się dzieje w logach serwera.
Ok, teraz konkrety.
# 2.6s user time, 300ms system time, 26.39M rss, 70.62M vsz
# Current date: Mon Jan 10 15:02:05 2011
# Hostname: mysql.example.com
# Files: STDIN
# Overall: 1.19k total, 209 unique, 0.06 QPS, 0.19x concurrency __________
# Attribute total min max avg 95% stddev median
# ========= ======= ======= ======= ======= ======= ======= =======
# Exec time 3824s 1s 51s 3s 9s 4s 2s
# Lock time 14s 0 5s 12ms 348us 168ms 103us
# Rows sent 1.36M 0 537.46k 1.17k 19.46 17.91k 0.99
# Rows exam 12.60M 0 4.30M 10.87k 27.29k 134.74k 0.99
# Time range 2011-01-10 07:25:00 to 2011-01-10 13:01:04
# bytes 598.90k 6 53.37k 516.66 1.33k 2.80k 118.34
# Bytes sen 789.00M 11 346.78M 680.65k 65.68k 10.70M 130.47
# IDB IO rb 0 0 0 0 0 0 0
# IDB IO ro 0 0 0 0 0 0 0
# IDB IO rw 0 0 0 0 0 0 0
# IDB pages 353 1 121 13.07 27.38 21.94 4.96
# IDB queue 0 0 0 0 0 0 0
# IDB rec l 0 0 0 0 0 0 0
# Killed 0 0 0 0 0 0 0
# Last errn 7.90k 0 1.33k 6.81 0 94.80 0
# Merge pas 21 0 1 0.02 0 0.13 0
# Rows affe 8.01k 0 3.52k 6.91 0.99 148.46 0
# Rows read 2.33M 0 537.46k 2.01k 8.89k 18.13k 1.96
# Tmp disk 246 0 1 0.21 0.99 0.40 0
# Tmp table 263 0 1 0.22 0.99 0.41 0
# Tmp table 1.47G 0 366.42M 1.27M 2.62M 18.15M 0
# 26% (314) Filesort
# 1% (21) Filesort_on_disk
# 3% (37) Full_join
# 25% (304) Full_scan
# 22% (263) Tmp_table
# 20% (246) Tmp_table_on_disk
Powyżej pierwsza sekcja z całości wyniku działania mk-query-digest. Zawiera ona podsumowanie statystyk z wszystkich zapytań, jakie znajdowały się w slowlogu. Przyglądnijmy się im po kolei.
# Current date: Mon Jan 10 15:02:05 2011
# Hostname: mysql.example.com
# Files: STDIN
# Overall: 1.19k total, 209 unique, 0.06 QPS, 0.19x concurrency __________
Widać tu informacje o tym, jak dużo zasobów potrzebował mk-query-digest aby sparsować slowlog, podana jest data i host, którego dotyczy raport. Mamy także informację o źródle danych – w tym wypadku STDIN, slowlog był przesyłany przez pipe. Raport dotyczy ok. 1190 zapytań, z czego unikalnych typów jest 209. Łącznie daje to 0,06 zapytania na sekundę.
# ========= ======= ======= ======= ======= ======= ======= =======
# Exec time 3933s 1s 51s 3s 9s 4s 2s
# Lock time 14s 0 5s 11ms 348us 165ms 103us
# Rows sent 1.36M 0 537.46k 1.13k 19.46 17.61k 0.99
# Rows exam 13.03M 0 4.30M 10.87k 34.83k 132.54k 0.99
# Time range 2011-01-10 07:25:00 to 2011-01-10 13:14:03
# bytes 613.10k 6 53.37k 511.25 1.33k 2.76k 118.34
# Bytes sen 789.41M 11 346.78M 658.27k 65.68k 10.52M 130.47
# IDB IO rb 0 0 0 0 0 0 0
# IDB IO ro 0 0 0 0 0 0 0
# IDB IO rw 0 0 0 0 0 0 0
# IDB pages 353 1 121 13.07 27.38 21.94 4.96
# IDB queue 0 0 0 0 0 0 0
# IDB rec l 0 0 0 0 0 0 0
# Killed 0 0 0 0 0 0 0
# Last errn 7.90k 0 1.33k 6.58 0 93.22 0
# Merge pas 22 0 1 0.02 0 0.13 0
# Rows affe 8.03k 0 3.52k 6.69 0.99 145.97 0
# Rows read 2.36M 0 537.46k 1.96k 8.89k 17.83k 1.96
# Tmp disk 257 0 1 0.21 0.99 0.40 0
# Tmp table 274 0 1 0.22 0.99 0.41 0
# Tmp table 1.48G 0 366.42M 1.24M 2.62M 17.84M 0
Kolejna część to zestawienie statystyk dla poszczególnych atrybutów. Podawane są dane łączne, minimum, maksimum, średnia, 95 percentyl (czyli wartość w której mieści się 95% zapytań), odchylenie standardowe i medianę.
Atrybuty natomiast to: Exec time – czas wykonywania zapytania, Lock time – czas zablokowania tabeli, Rows sent – ilość przesłanych rekordów, Rows exam – ilość rekordów odczytanych z bazy, Time range – przedział czasowy jakiego dotyczy raport, Bytes sen – ilość przesłanych danych, IDB IO rb – ilość danych odczytanych dla tabel InnoDB, IDB IO ro – ilość operacji odczytu dla tabel InnoDB, IDB IO rw – czas oczekiwania na dostęp do tabel InnoDB, IDB pages – ilość stron odczytanych dla tabel z InnoDB, IDB queue – czas oczekiwania zapytań w kolejce InnoDB, IDB rec l – czas oczekiwania na otrzymanie odpowiednich locków dla tabel InnoDB, Killed – ilość zabitych zapytań, Last errn – mówiąc szczerze, nie mam pojęcia – bierze się to z ‚Last_errno’, co przekłada się na numer błędu dla danego zapytania w slowlogu (0 jeśli wszystko jest ok), ale jak to jest sumowane, nie analizowałem kodu. Dalej mamy Merge pas – ilość przejść w trakcie łączenia tabel algorytmem sort, Rows affe – ilość rekordów zmodyfikowanych, Rows read – ilość rekordów odczytanych, Tmp disk – ilość tabel tymczasowych utworzonych na dysku, Tmp table – ilość tabel tymczasowych utworzonych w ogóle, Tmp table (powinno być tu Tmp table size) – łączna wielkość utworzonych tabel tymczasowych.
Powyżej przedstawione atrybuty odpowiadają tym udostępnianym przez Percona Server, dokładne informacje można znaleźć na tej stronie.
Ostatni element pierwszej sekcji wygląda następująco:
# 1% (22) Filesort_on_disk
# 3% (42) Full_join
# 25% (317) Full_scan
# 22% (274) Tmp_table
# 20% (257) Tmp_table_on_disk
Mamy tu informację na temat tego, jak zachowują się zapytania. Widzimy np. że 26% wszystkich zapytań (327 dokładnie) stosuje algorytm filesort, 1% robi to na dysku. 42 zapytania (3% całości) wykonuje full join (czyli JOIN między tabelami, w przypadku którego nie ma możliwości skorzystania z indeksu), 25% wykonuje pełny skan tabeli, 274 tworzy tabele tymczasowe a 257 robi to na dysku.
Następny post będzie opisywał sekcję w której analizowane są poszczególne zapytania.
Komentarze