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=10;
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:

SELECT a,b,c FROM x WHERE a=zmienna;

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.

cat mysql-slow | mk-query-digest

# 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.

# 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 __________

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ę.

# Attribute          total     min     max     avg     95%  stddev  median
# =========        ======= ======= ======= ======= ======= ======= =======
# 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:

#  26% (327)  Filesort
#   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.