MySQL udostępnia administratorowi kilka rodzajów logów – error log, slowlog, general log, binlog. W sytuacji, gdy pojawiają się problemy wydajnościowe i konieczne jest przeanalizowanie obciążenia i znalezienie przyczyny kłopotów, przydatny staje się głównie jeden z nich – slowlog. Log ten zawiera informacje na temat zapytań, które wykonywały się dłużej niż wartość zmiennej ‚long_query_time’ w sekundach. Domyślnie jest to 10 sekund. Zazwyczaj domyślna wartość jest dużo za duża – kilkadziesiąt zapytań, z których każde wykonuje się po kilka sekund, może spokojnie zatkać serwer bazodanowy. Z tego powodu, jak również z pewnych historycznych względów, często ustawia się ten parametr na jedną sekundę.
W przypadku MySQL w wersji 5.1 przykładowy wpis ze slowloga może wyglądać następująco:
# User@Host: root[root] @ localhost []
# Query_time: 0.000274 Lock_time: 0.000075 Rows_sent: 5 Rows_examined: 5
SET timestamp=1272394552;
select * from mysql.user;
Co widzimy?
– czas, kiedy zapytanie zostało wykonane: 27 kwietnia 2010 roku o godzinie 20:55:52
– jaki użytkownik i z jakiego hosta wykonał zapytanie: użytkownik root logujący się lokalnie, po sockecie (localhost)
– ile trwało wykonanie zapytania: 0.000274 sekundy
– jak długo tabela była blokowana: 0.000075 sekundy
– ile rekordów zostało przesłanych do klienta: 5
– ile rekordów zostało sprawdzonych w bazie: 5
– zapytanie, jakie zostało wykonane
Najistotniejszymi informacjami są: czasy wykonywania zapytania i blokowania tabeli oraz ilość rekordów do sprawdzenia.
Czas trwania zapytania – rzecz raczej oczywista. Im krócej trwa zapytanie, tym lepiej, bo użytkownik szybciej otrzyma wynik. Jaka wartość jest akceptowana, zależy od tego, do czego konkretna baza danych ma służyć. Jeśli baza służy do przechowywania dużych ilości danych i generowania raportów i zestawień, często można zaakceptować zapytania, które trwają dłużej niż 30 – 60 sekund. W przypadku gdy baza jest zapleczem jakiejś interaktywnej aplikacji (w szczególności strony internetowej), już opóźnienie rzędu 0.1 sekundy może być problemem. Szczególnie jest to widoczne gdy do wygenerowania strony konieczne jest dwadzieścia takich zapytań – łącznie mamy opóźnienie dwóch sekund i to nie licząc opóźnienia w komunikacji pomiędzy serwerem www a bazą danych – nawet jeśli znajdują się na tej samej maszynie i łączą się po uniksowych socketach, opóźnienie nadal występuje a użytkownik czeka na wygenerowanie strony internetowej. Analizując zapytania pod kątem czasu wykonywania należy zwrócić szczególną uwagę na to, aby nie pomylić przyczyny ze skutkiem. To, że serwer bazodanowy zaczyna zwalniać, zazwyczaj ma związek z jakimś zapytaniem. Zgoda. Problem w tym, że jeśli serwer zaczyna zwalniać, zwalniają także i wszystkie zapytania – także te „niewinne”. Jeśli przykładowo jedno z zapytań generuje ogromną tablicę tymczasową (bo ktoś użył ORDER BY RAND() na sporej tabeli) i dysk pracuje na wysokich obrotach, to właściwie wszystkie pozostałe zapytania, także te, które normalnie wykonują się w ułamku sekundy, będą się także wolniej wykonywały – dłużej trwa dobicie się do potrzebnych danych na dysku. Należy o tym pamiętać, aby poprawnie zidentyfikować właściwe źródło wystąpienia problemu, a nie tracić czas na optymalizowanie zapytań, które w normalnych warunkach są błyskawiczne.
Czas w jakim tabele były zablokowane zapytaniem ważny jest o tyle, że w tym czasie na tabelach uczestniczących w zapytaniu nie ma możliwości wykonywania modyfikacji. W przypadku silnika MyISAM, podczas wykonywania zapytania typu SELECT, na uczestniczące w nim tabele, na czas potrzebny do pobrania z nich danych, nakładany jest READ LOCK – dostępne są tylko do odczytu. Jeśli na danej tabeli wykonywanych jest też duża ilość zapytań modyfikujących dane, zapytania te będą czekały aż READ LOCK zostanie z tabeli zdjęty.
Ilość rekordów sprawdzonych w bazie to informacja przydatna do tego, aby wstępnie wyłapać te zapytania, które są kandydatami do głębszej analizy. Jeśli widzimy tu sporą wartość (dziesiątki tysięcy, albo i więcej – zależy od wielkości całej bazy), może to być informacją o tym, że dane zapytanie nie jest poprawnie poindeksowane i wykonywany jest pełny skan tabeli. Szczególnie w przypadku JOIN’ów indeksowanie jest bardzo istotne, bo w przypadku kombinacji kilku JOIN’ów bez indeksów ilość rekordów koniecznych do przeglądnięcia może pójść w dziesiątki milionów. Spora ilość sprawdzonych rekordów może także świadczyć o tym, że przydałoby się doprecyzować zapytanie – brakuje warunków WHERE bądź są zbyt ogólne. Jasne, to jakie stosujemy warunki zależy od tego, co chcemy osiągnąć, ale w takiej sytuacji zawsze dobrze jest się przyglądnąć zapytaniu. Może być na przykład tak, że z jakichś względów (przenośność i recycling kodu) ktoś wyciąga z bazy zawartość adresów dla całej Polski, a konkretne województwo wybiera dopiero po stronie aplikacji. Różnie bywa w życiu.
Dobrze jest też zwrócić uwagę na stosunek ilości rekordów sprawdzanych do rekordów przesyłanych. Może się okazać, że MySQL niepotrzebnie analizuje kilkadziesiąt tysięcy rekordów a następnie przesyła pięć. Przyczyną może być np. zastosowanie LIMIT. LIMIT w MySQL działa tak, że z tabeli pobierane są dane do rekordu o podanej pozycji, a następnie tyle kolejnych rekordów ile podano w drugim parametrze LIMIT’a. Przykładowo:
# User@Host: root[root] @ localhost []
# Query_time: 0.000318 Lock_time: 0.000077 Rows_sent: 5 Rows_examined: 155
SET timestamp=1272397223;
SELECT * FROM actor LIMIT 150,5;
Widzimy, że MySQL przeanalizował 155 rekordów – 150 do początku warunku LIMIT i 5 kolejnych. Wysłane zostało jedynie te pięć właściwych. Często jest tak, że możemy zamienić tego typu ograniczenie na warunki w WHERE:
# User@Host: root[root] @ localhost []
# Query_time: 0.000418 Lock_time: 0.000095 Rows_sent: 5 Rows_examined: 5
SET timestamp=1272397250;
SELECT * FROM actor WHERE actor_id > 150 AND actor_id < 156;
Jak widać, w tym drugim przypadku konieczne było sprawdzenie tylko pięcu rekordów. Co prawda, w tym konkretnym przypadku drugie zapytanie było o 25% wolniejsze, ale tego typu zapytanie będzie miało zawsze z grubsza taką samą wydajność – nie ważne czy tabela ma 200 czy 2000000 rekordów i nie ważne, czy chcemy uzyskać kolejnych pięć rekordów począwszy od rekordu 150 czy od rekordu 1500000.
W przypadku MySQL w wersji 5.1 parametr long_query_time może przyjmować ułamki sekundy – 0.01, 0.0001 i tak dalej. Jest to bardzo przydatne w sytuacji, gdy na danym poziomie szczegółowości nic nie chce się w logi złapać, a ciągle widać że problem nie został rozwiązany. Zdarza się tak, że przyczyną nie jest jedno wielkie zapytanie, ale kilkaset (kilka tysięcy) razy na sekundę występujące małe, niezoptymalizowane zapytanie – na przykład bez indeksu. W przypadku MySQL 5.0 niestety, takiej opcji nie ma. Zmienna long_query_time ma tam rozdzielczość 1 sekundy. Możemy co najwyżej ustawić wartość 0 – logowanie wszystkich zapytań. Jest to jeden z powodów, aby rozstać się z taką wersją bazy danych.
Dodatkową opcją przydatną w takich sytuacjach jest zmienna log-queries-not-using-indexes. Włączenie jej skutkuje tym, że do slowloga logowane są dodatkowo wszystkie zapytania, w przypadku których konieczne jest przeanalizowanie wszystkich rekordów w tabeli. Można w ten sposób wyłapać zapytania, które nie są indeksowane lub wykonują pełny skan tabeli.
O tym, że pomimo posiadania tych wszystkich informacji nadal błądzimy we mgle (i co zrobić, żeby przestać błądzić), napiszę przy innej okazji.
Komentarze