Estamos executando um servidor MySQL RDS m1.xlarge e tendo alguns problemas com alto uso da CPU. Tivemos alguns problemas há algumas semanas com a utilização da CPU atingindo 100% em uma instância grande. Quando atualizamos o tamanho para xlarge, isso estabilizou as coisas por um tempo, mas o uso da CPU aumentou gradualmente novamente.
Na última semana, a utilização da CPU esteve na casa dos 90, atingindo 100% ou mais ou menos consistentemente ontem, o que paralisou nosso local de produção. Após a reinicialização do servidor db, em poucas horas o uso da CPU voltou aos mesmos níveis.
Eu executei show processlist no servidor mysql e monitorei o mesmo através do MySQL admin. Não parece haver consultas particularmente longas ou um grande volume de consultas. Há alguns processos em estado de suspensão por um longo tempo... esses são daemons de trabalhadores isolados executados fora do nosso aplicativo principal que se comunicam com o banco de dados. Copiei a saída da lista de processos abaixo com os nomes dos servidores alterados para fornecer uma descrição do que são:
+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+
| 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 |
+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+
Devo também dizer que o tráfego no site é extremamente baixo durante este período, em relação ao horário normal de pico, cerca de 10% da carga que vemos nos horários de pico.
Também temos um novo monitoramento de relíquias que nos mostra quais são as chamadas de banco de dados de aplicativos mais demoradas. Isso nos mostra que uma chamada específica que representa 99% do tempo que nosso aplicativo gasta no banco de dados é uma consulta simples de localização por id como esta:
SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`id` = 123 LIMIT 1
(não é exatamente o mesmo que as consultas que estavam sendo executadas na lista de processos acima)
Essa operação ficou mais lenta na última semana, com o desvio padrão entre as solicitações de tempo aumentando e também a quantidade máxima de tempo que leva sendo medida em termos de segundos. Eu acho que isso é apenas um resultado dos problemas de utilização da CPU e não uma causa.
Esta tabela tem cerca de 80.000 linhas, portanto, não é enorme. Espera-se que a maior parte do tempo dos aplicativos no banco de dados seja gasto procurando registros nesta tabela, a principal funcionalidade do aplicativo é baseada nisso. Eu mesmo executei uma consulta semelhante do meu servidor de aplicativos para o banco de dados de produção algumas vezes, enquanto o uso da CPU permanece em torno de 100% e responde em 1 ou 2 ms.
Com base em todos os itens acima, não temos certeza de como proceder com nossa depuração. Gostaria de saber se alguém tem alguma idéia de que tipo de coisas podem ser a causa raiz e como investigá-las? O acesso ao servidor subjacente que executa nosso servidor db é limitado, pois é uma instância do Amazon RDS.
Consegui resolver isso, estes são os passos que segui:
Em primeiro lugar, entrei em contato com a equipe do Amazon RDS postando em seu fórum de discussão, eles confirmaram que era o processo mysqld ocupando toda essa CPU - isso eliminou uma falha de configuração com outra coisa em execução no servidor físico
Em segundo lugar, rastreei a fonte das consultas que estavam em execução:
Originalmente, ignorei isso como a causa, porque nenhuma dessas consultas parecia demorar muito quando monitorei a saída show processlist. Depois de esgotar outros caminhos, decidi que poderia valer a pena continuar... e estou feliz por ter feito isso.
Como você pode ver na saída show processlist, essas consultas vinham de um servidor utilitário, que executa alguns trabalhos utilitários táticos que existem fora do nosso código principal do aplicativo. É por isso que eles não estavam aparecendo como lentos ou causando problemas em nosso novo monitoramento de relíquias, porque o novo agente de relíquias está instalado apenas em nosso servidor de aplicativos principal.
Seguindo vagamente este guia:
http://www.mysqlperformanceblog.com/2007/02/08/debugging-sleeping-connections-with-mysql/
Consegui rastrear essas consultas para um processo específico em execução em nossa caixa de servidor de utilitários. Este era um pouco de código ruby que estava iterando de forma muito ineficiente por cerca de 70.000 registros, verificando alguns valores de campo e usando-os para decidir se é necessário criar um novo registro em 'mytable'. Depois de fazer algumas análises que pude determinar, o processo não era mais necessário, então poderia ser morto.
Algo que estava piorando as coisas, parecia haver 6 instâncias desse mesmo processo em execução ao mesmo tempo devido à maneira como o cron job foi configurado e quanto tempo cada um levou! Eu matei esses processos e, incrivelmente, nosso uso de CPU caiu de cerca de 100% para cerca de 5%!