Trudności w debugowaniu wysokiego obciążenia procesora w instancji Amazon RDS MySQL

Korzystamy z serwera RDS MySQL m1.xlarge i mamy problemy z dużym wykorzystaniem procesora. Kilka tygodni temu mieliśmy problemy z wykorzystaniem procesora sięgającym 100% w dużej instancji. Kiedy podnieśliśmy rozmiar do xlarge, który stabilizował przez pewien czas, ale zużycie procesora stopniowo podskakiwało.

Przez ostatni tydzień wykorzystanie procesora było na wysokim poziomie w latach 90., osiągając 100% lub mniej więcej wczoraj konsekwentnie, co zatrzymało nasz zakład produkcyjny. Po ponownym uruchomieniu serwera db użycie procesora wróciło do tych samych poziomów w ciągu kilku godzin.

Uruchomiłem show list procesów na serwerze mysql i monitorowałem to samo przez administratora MySQL. Wydaje się, że nie ma żadnych szczególnie długich zapytań ani dużej liczby zapytań. Długo trwa kilka procesów w stanie uśpienia ... są to izolowane demony pracowników działające poza naszą główną aplikacją, które komunikują się z bazą danych. Skopiowałem dane wyjściowe listy procesów poniżej ze zmienionymi nazwami serwerów, aby podać ich opis:

+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+
| 13 | rdsadmin | localhost:43513 | mysql | Sleep | 14 | | NULL |
| 15 | proddbuser | app-server-1.eu-west-1.compute.internal:36460 | proddb | Sleep | 46 | | NULL |
| 451 | proddbuser | app-server-1.eu-west-1.compute.internal:55512 | proddb | Sleep | 29 | | NULL |
| 912 | proddbuser | app-server-1.eu-west-1.compute.internal:45171 | proddb | Sleep | 13 | | NULL |
| 941 | proddbuser | app-server-1.eu-west-1.compute.internal:47353 | proddb | Sleep | 53 | | NULL |
| 951 | proddbuser | app-server-1.eu-west-1.compute.internal:48014 | proddb | Sleep | 37 | | NULL |
| 1009 | proddbuser | app-server-1.eu-west-1.compute.internal:51787 | proddb | Sleep | 36 | | NULL |
| 1041 | proddbuser | app-server-1.eu-west-1.compute.internal:53777 | proddb | Sleep | 14 | | NULL |
| 1572 | proddbuser | app-server-1.eu-west-1.compute.internal:42989 | proddb | Sleep | 3 | | NULL |
| 1592 | proddbuser | app-server-1.eu-west-1.compute.internal:43279 | proddb | Sleep | 162 | | NULL |
| 2909 | proddbuser | app-server-1.eu-west-1.compute.internal:37768 | proddb | Sleep | 35 | | NULL |
| 3028 | proddbuser | app-server-1.eu-west-1.compute.internal:42568 | proddb | Sleep | 5 | | NULL |
| 3119 | proddbuser | app-server-1.eu-west-1.compute.internal:46913 | proddb | Sleep | 76 | | NULL |
| 3189 | proddbuser | app-server-1.eu-west-1.compute.internal:51466 | proddb | Sleep | 5 | | NULL |
| 3216 | proddbuser | app-server-2.eu-west-1.compute.internal:44097 | proddb | Sleep | 14552 | | NULL |
| 3218 | proddbuser | app-server-2.eu-west-1.compute.internal:44099 | proddb | Sleep | 14552 | | NULL |
| 3219 | proddbuser | app-server-2.eu-west-1.compute.internal:44107 | proddb | Sleep | 44 | | NULL |
| 3220 | proddbuser | app-server-2.eu-west-1.compute.internal:44113 | proddb | Sleep | 26 | | NULL |
| 3223 | proddbuser | app-server-2.eu-west-1.compute.internal:44184 | proddb | Sleep | 50 | | NULL |
| 3224 | proddbuser | app-server-2.eu-west-1.compute.internal:44187 | proddb | Sleep | 1 | | NULL |
| 3226 | proddbuser | app-server-2.eu-west-1.compute.internal:44208 | proddb | Sleep | 33 | | NULL |
| 3229 | proddbuser | app-server-2.eu-west-1.compute.internal:44250 | proddb | Sleep | 14 | | NULL |
| 3232 | proddbuser | app-server-2.eu-west-1.compute.internal:44279 | proddb | Sleep | 26 | | NULL |
| 3233 | proddbuser | app-server-2.eu-west-1.compute.internal:44297 | proddb | Sleep | 31 | | NULL |
| 3237 | proddbuser | app-server-2.eu-west-1.compute.internal:44334 | proddb | Sleep | 27 | | NULL |
| 3239 | proddbuser | app-server-2.eu-west-1.compute.internal:44338 | proddb | Sleep | 11 | | NULL |
| 3241 | proddbuser | app-server-2.eu-west-1.compute.internal:44356 | proddb | Sleep | 26 | | NULL |
| 3260 | proddbuser | app-server-2.eu-west-1.compute.internal:44619 | proddb | Sleep | 8 | | NULL |
| 3337 | proddbuser | utility-server-1.eu-west-1.compute.internal:45193 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 309416 LIMIT 1 |
| 3419 | proddbuser | utility-server-1.eu-west-1.compute.internal:46136 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 284530 LIMIT 1 |
| 3463 | proddbuser | app-server-1.eu-west-1.compute.internal:59619 | proddb | Sleep | 9406 | | NULL |
| 3504 | proddbuser | utility-server-1.eu-west-1.compute.internal:47063 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 260571 LIMIT 1 |
| 3577 | proddbuser | app-server-1.eu-west-1.compute.internal:34394 | proddb | Sleep | 6734 | | NULL |
| 3585 | proddbuser | utility-server-1.eu-west-1.compute.internal:47990 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 231273 LIMIT 1 |
| 3664 | proddbuser | utility-server-1.eu-west-1.compute.internal:48909 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 201525 LIMIT 1 |
| 3716 | proddbuser | app-server-2.eu-west-1.compute.internal:56301 | proddb | Sleep | 27 | | NULL |
| 3748 | proddbuser | utility-server-1.eu-west-1.compute.internal:49850 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 167839 LIMIT 1 |
| 3771 | proddbuser | my-pc:30101 | NULL | Query | 0 | NULL | show processlist |
| 3831 | proddbuser | utility-server-1.eu-west-1.compute.internal:50785 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 123228 LIMIT 1 |
+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+

Powinienem również powiedzieć, że ruch w witrynie jest wyjątkowo niski w tym okresie, w porównaniu do normalnych godzin szczytu, około 10% obciążenia, które widzimy w godzinach szczytu.

Mamy również nowy monitoring reliktów, który pokazuje nam, jakie są najbardziej czasochłonne wywołania bazy danych aplikacji. Pokazuje nam, że jedno konkretne wywołanie, które stanowi 99% czasu, w którym nasza aplikacja spędza czas w db, jest prostym znalezieniem według zapytania id:

SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`id` = 123 LIMIT 1

(niezupełnie takie same jak zapytania uruchomione na powyższej liście procesów)

W ciągu ostatniego tygodnia ta operacja uległa spowolnieniu, przy rosnącym standardowym odchyleniu między żądaniami czasu, a także mierzeniu maksymalnego czasu w sekundach. Myślę, że jest to raczej wynik problemów z wykorzystaniem procesora niż przyczyna.

Ten stół ma około 80 000 wierszy, więc nie jest ogromny. Oczekuje się, że większość czasu aplikacji w bazie danych jest spędzana na wyszukiwaniu rekordów w tej tabeli, na tym opiera się główna funkcjonalność aplikacji. Kilka razy sam uruchomiłem podobne zapytanie z serwera aplikacji do produkcyjnej bazy danych, podczas gdy użycie procesora pozostaje na poziomie około 100% i odpowiada w ciągu 1 lub 2 ms.

W związku z powyższym nie jesteśmy pewni, jak kontynuować debugowanie. Zastanawiałem się tylko, czy ktoś miał jakieś pomysły, co może być przyczyną i jak je badać? Dostęp do serwera bazowego, na którym działa nasz serwer db, jest ograniczony, ponieważ jest to instancja Amazon RDS.

Udało mi się to rozwiązać, wykonując następujące kroki:

Po pierwsze, skontaktowałem się z zespołem Amazon RDS, pisząc na forum dyskusyjnym, potwierdzili, że to proces mysqld zajmuje cały ten procesor - to wyeliminowało błąd konfiguracji z czymś innym działającym na fizycznym serwerze

Po drugie wyśledziłem źródło uruchomionych zapytań:

SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 231273 LIMIT 1 

Pierwotnie przeoczyłem to jako przyczynę, ponieważ żadne z tych zapytań nie wydawało się szczególnie długie, gdy monitorowałem dane wyjściowe listy procesów. Po wyczerpaniu innych możliwości, zdecydowałem, że warto kontynuować ... i cieszę się, że to zrobiłem.

Jak widać na liście wyników procesu show, zapytania te pochodziły z serwera narzędziowego, który uruchamia taktyczne zadania narzędziowe, które istnieją poza naszym głównym kodem aplikacji. Właśnie dlatego nie pojawiały się tak wolno ani nie powodowały problemów w naszym nowym monitorowaniu reliktów, ponieważ nowy agent reliktów jest zainstalowany tylko na naszym głównym serwerze aplikacji.

Luźno przestrzegając tego przewodnika:

http://www.mysqlperformanceblog.com/2007/02/08/debugging-sleeping-connections-w--mysql/

Udało mi się prześledzić te zapytania do określonego uruchomionego procesu na naszym serwerze narzędziowym. To był trochę rubinowy kod, który bardzo nieefektywnie iterował przez około 70 000 rekordów, sprawdzał niektóre wartości pól i używał ich do decydowania, czy musi utworzyć nowy rekord w „mytable”. Po przeprowadzeniu analizy, którą udało mi się ustalić, proces nie był już potrzebny, więc mógł zostać zabity.

Coś się pogorszyło, zdawało się, że było 6 wystąpień tego samego procesu uruchomionych jednocześnie ze względu na sposób skonfigurowania zadania cron i jak długo trwało każde! Zabiłem te procesy i niewiarygodnie nasze użycie procesora spadło z około 100% do około 5%!