it-swarm-eu.dev

Snaží se ladit vysoké využití CPU na instanci Amazon RDS MySQL

Provozujeme server m1.xlarge MySQL RDS a máme problémy s vysokým využitím procesoru. Před několika týdny jsme měli nějaké problémy, když využití procesoru dosáhlo 100% na velké instanci. Když jsme upgradovali velikost na xlarge, která stabilizovala věci na chvíli, ale využití procesoru se postupně znovu plížilo.

Za poslední týden bylo využití procesoru v 90. letech 20. století, kdy včera dosáhlo 100% či dalších, což zastavilo naše výrobní místo. Po restartu serveru db se využití procesoru během několika hodin vyšplhalo na stejnou úroveň.

Spustil jsem seznam procesů show na serveru mysql a sledoval jsem je také pomocí administrátora MySQL. Nezdá se, že by existovaly žádné zvláště dlouhodobé dotazy ani velké množství dotazů. Existuje několik procesů ležících ve spánkovém stavu po dlouhou dobu ... jedná se o izolované dělnické démony běžící mimo naši hlavní aplikaci, které komunikují s databází. Zkopíroval jsem se do výstupu procesního seznamu níže se změnami názvů serverů, abych popsal, co jsou:

+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+
| 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 |
+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+

Také bych měl říci, že provoz na tomto místě je během tohoto období extrémně nízký, vzhledem k normálním špičkovým hodinám, kolem 10% zatížení, které vidíme ve špičkách.

Máme také nové sledování relikvie, které nám ukazuje, jaké jsou nejnáročnější volání databáze aplikací. Ukazuje nám, že jedno konkrétní volání, které představuje 99% času, který naše aplikace stráví v db, je jednoduché hledání pomocí id dotazu, jako je tento:

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

(ne úplně stejné jako dotazy, které byly spuštěny ve výše uvedeném seznamu procesů)

Tato operace se za poslední týden zhruba zpomalila, přičemž standardní odchylka mezi časovými požadavky trvá a také se měří maximální doba, kterou je třeba měřit v sekundách. Myslím, že je to spíše výsledek problémů s využitím procesoru než příčina.

Tato tabulka má asi 80 000 řádků, takže není obrovská. Očekává se, že většinu času aplikací v databázi strávíte vyhledáním záznamů v této tabulce, hlavní funkčnost aplikace je založena na tomto. Několikrát jsem spustil podobný dotaz z aplikačního serveru do produkční databáze několikrát, zatímco využití procesoru zůstává kolem 100% a odpovídá do 1 nebo 2 ms.

Na základě výše uvedeného si nejsme jistí, jak pokračovat v ladění. Jen jsem přemýšlel, jestli má někdo nějaké nápady, jaké věci by mohly být hlavní příčinou a jak je vyšetřit? Přístup k podkladovému serveru, na kterém je spuštěn náš server db, je od instance Amazon RDS omezený.

21
WillJThomas

Podařilo se to vyřešit, to jsou kroky, které jsem následoval:

Nejprve jsem kontaktoval tým Amazon RDS zveřejněním na jejich diskusním fóru, potvrdili, že to byl proces mysqld, který zabral celý tento procesor - to eliminovalo chybu konfigurace s něčím jiným, co běží na fyzickém serveru.

Za druhé jsem sledoval zdroj dotazů, které byly spuštěny:

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

Původně jsem to přehlédl jako příčinu, protože se zdálo, že žádný z těchto dotazů netrval zvlášť dlouho, když jsem sledoval výstup showlistu. Po vyčerpání dalších cest jsem se rozhodl, že by stálo za to sledovat ... a jsem rád, že jsem to udělal.

Jak můžete vidět na výstupu seznamu procesů zobrazení, tyto dotazy přicházely ze serveru utlility, který spouští některé taktické obslužné úlohy, které existují mimo náš hlavní kód aplikace. To je důvod, proč se v našem novém sledování relikvií nezobrazovaly tak pomalu nebo způsobovaly problémy, protože nový agent relic je nainstalován pouze na našem hlavním aplikačním serveru.

Volně podle tohoto průvodce:

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

Tyto dotazy jsem byl schopen vystopovat do konkrétního běžícího procesu v naší schránce obslužného serveru. Byl to kousek kódu Ruby), který byl velmi neefektivně iterován okolo 70 000 záznamů, zkontroloval některé hodnoty polí a pomocí nich rozhodl, zda je třeba vytvořit nový záznam v 'mytable'. nějaká analýza, kterou jsem byl schopen určit, proces již nebyl potřeba, takže mohl být zabit.

Zdálo se, že něco, co zhoršuje situaci, se zdálo, že ve stejném čase probíhá 6 instancí stejného procesu kvůli způsobu, jakým byla nakonfigurována úloha cronu a jak dlouho to trvalo! Tyto procesy jsem zabil a neuvěřitelně se naše využití procesoru snížilo z přibližně 100% na přibližně 5%!

15
WillJThomas