Dłuższa chwila minęła od ostatniego postu. Niestety, obawiam się że częstotliwość raczej się nie zwiększy znacząco. Przyczyną jest zwykły, prozaiczny brak czasu. Postaram się jednak od czasu do czasu wrzucić coś nowego na bloga. Dziś o profilowaniu alokacji pamięci przez MySQL

Jednego z Klientów dotknął specyficzny problem – mysqld puchł, alokował coraz więcej pamięci. Buffer pool ustawiony na 16G a mysqld alokował ponad 30GB i co pewien czas umierał zabity przez OOM killera. Jako że działo się to na serwerach produkcyjnych, w szczególności na masterze, nie była to sytuacja, którą można było zignorować.

Pierwsze kroki w takiej sytuacji zawsze należy skierować do SHOW ENGINE INNODB STATUS. Znajduje się tam sekcja opisująca zużycie pamięci przez InnoDB (tylko taki silnik był w użyciu w sprawiającym problemy klastrze). Jako że nie tylko buffer pool alokuje pamięć, dobrze się upewnić jak to w praktyce wygląda i czy inne elementy (jak choćby adaptive hash index) nie zjadają brakującej pamięci. Tym razem nic ciekawego nie udało się tam znaleźć – łączna wykazywana alokacja pamięci to było ok. 17-18GB. Trzeba było znaleźć inne rozwiązanie.

Jeden ze slave’ów został wyłączony z produkcji i przeznaczony na potrzeby testów. Wcześniej, gdy jeszcze obsługiwał ruch, zebraliśmy precyzyjne slowlogi, tak aby była możliwość odtworzenia ruchu produkcyjnego. Jak już slave dostał się w moje ręce, można było zacząć zabawę. Przy pomocy pt-log-player odtworzyłem ruch read only (same SELECTy, bez DML’i – cały czas działała replikacja i nie mogłem pisać po tej maszynie) i obserwowałem zużycie pamięci. W momencie gdy udało się potwierdzić przy pomocy próbki danych, że problem występuje, mogłem przejść do dalszych testów.

Tu na scenę wkracza Valgrind, a w szczególności Massif, który służy do profilowania zużycia pamięci przez proces. Instalacja jest prosta – ściągnąć źródło z http://valgrind.org/downloads/valgrind-3.8.1.tar.bz2, zainstalować narzędzia do kompilacji, skompilować na zasadzie ./configure && make && make install i gotowe.

Następnie należy uruchomić MySQL poprzez valgrinda. Zrobić można to np. tak:

valgrind --tool=massif --massif-out-file=/tmp/massif.out /sciezka/do/mysqld --opcje-mysqld

Gdy MySQL ruszy, staramy się robić wszystko co się da, żeby wywołać problem. W moim przypadku wystarczyło uruchomienie pt-log-player i czekanie aż alokacja pamięci skoczy wystarczająco zauważalnie. Po wywołaniu problemu zatrzymujemy MySQL i sprawdzamy co się udało zebrać przy pomocy następującego polecenia:

ms_print /tmp/massif.out

W moim przypadku fragment raportu wyglądał tak:

->63.75% (597,333,544B) 0x88B160: my_malloc (in /usr/sbin/mysqld)
| ->58.08% (544,237,384B) 0x88B95C: alloc_root (in /usr/sbin/mysqld)
| | ->56.86% (532,848,400B) 0x69E59B: handler::ha_open(st_table*, char const*, int, int) (in /usr/sbin/mysqld)
| | | ->52.09% (488,133,440B) 0x6A8FD4: ha_partition::open(char const*, int, unsigned int) (in /usr/sbin/mysqld)
| | | | ->52.09% (488,133,440B) 0x69E47C: handler::ha_open(st_table*, char const*, int, int) (in /usr/sbin/mysqld)
| | | | ->52.05% (487,718,784B) 0x6A66A2: ha_partition::clone(st_mem_root*) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x68AB64: QUICK_RANGE_SELECT::init_ror_merged_scan(bool) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x689B8E: QUICK_ROR_INTERSECT_SELECT::init_ror_merged_scan(bool) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x689B06: QUICK_ROR_INTERSECT_SELECT::reset() (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x61C773: ??? (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x62A91F: sub_select(JOIN*, st_join_table*, bool) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x634A48: ??? (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x6389B1: JOIN::exec() (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x63A577: mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x63AEA3: handle_select(THD*, st_lex*, select_result*, unsigned long) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x5C660F: ??? (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x5C94D4: mysql_execute_command(THD*) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x5CF709: mysql_parse(THD*, char*, unsigned int, char const**) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x5D00FF: dispatch_command(enum_server_command, THD*, char*, unsigned int) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x5D0D46: do_command(THD*) (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x5C2CFF: handle_one_connection (in /usr/sbin/mysqld)
| | | | | ->52.05% (487,718,784B) 0x4E2A73B: start_thread (in /lib64/libpthread-2.5.so)
| | | | | ->52.05% (487,718,784B) 0x5BF2F6B: clone (in /lib64/libc-2.5.so)

Tak się składało, że akurat nie mogłem się doliczyć ok. 700MB. Jak widać, pamięć została zaalokowana przez funkcję handler::ha_open, która odpowiada za otwieranie tabeli. Można wnioskować, że ten memory leak związany jest z partycjonowaną tabelą (handler::ha_open wywołany jest przez funkcję ha_partition::open). To akurat nie wiele mi pomogło, jako że nie bardzo dało by się zrezygnować z partycjonowania tabel na tym hoście, ale przynajmniej udało się stwierdzić konkretną przyczynę problemu. Dzięki temu można było uzasadnić wykonanie upgrade całego klastra do najnowszej wersji MySQL, co w tym konkretnym przypadku załatwiło sprawę.

Podstawowym ograniczeniem jest to, że do wykonania testu konieczny jest restart MySQL i uruchomienie go przy pomocy Valgrinda. Nie da się (a przynajmniej ja nie znalazłem na to sposobu) podpiąć do działającego serwera i jeśli nie udało się opracować metody na wywołanie problemu, nie będziemy w stanie nic sprawdzić. Oczywiście, czysto teoretycznie patrząc można uruchomić Valgrinda i rzucić ruch produkcyjny na taki MySQL. Nie jest to coś, co bym polecał, co najwyżej gdy jesteśmy już zdesperowani a problem jest poważny. Zasadniczo nie powinno się uruchamiać produkcyjnie bazy danych działającej w środowisku debugującym jej działanie. Drugim, znacznie mniejszym już problemem jest konieczność doinstalowania pakietu z symbolami dla MySQL. Bez tego nie zobaczymy ładnych (i mówiących cokolwiek) nazw funkcji. Problem ten jest mniejszy, bo zazwyczaj da się te informacje doinstalować (np. dla Percona Server są dostępne w formie osobnego RPM: Percona-Server-55-debuginfo-5.5.29-rel30.0.451.rhel6.x86_64.rpm). W każdym razie, trzeba przyznać że Valgrind/Massif to narzędzie ciekawe i przydatne w pewnych sytuacjach.