Um pouco atrás, há algum tempo, começamos a experimentar um alto tempo de sistema da CPU em um de nossos bancos de dados MySQL. Esse banco de dados também estava sofrendo com a alta utilização do disco, então concluímos que essas coisas estão conectadas. E como já tínhamos planos de migrá-lo para o SSD, pensamos que ele resolveria os dois problemas.
Ajudou ... mas não por muito tempo.
Por algumas semanas após a migração, o gráfico da CPU ficou assim:
Mas agora voltamos a isso:
Isso aconteceu do nada, sem alterações aparentes na carga ou na lógica do aplicativo.
Estatísticas do banco de dados:
- Versão MySQL - 5.7.20
- OS - Debian
- Tamanho do DB - 1.2Tb
- RAM - 700Gb
- Núcleos da CPU - 56
- Peek load - cerca de 5kq / s de leitura, gravação de 600q / s (embora as consultas selecionadas geralmente sejam bastante complexas)
- Linhas - 50 em execução, 300 conectadas
- Possui cerca de 300 tabelas, todas InnoDB
Configuração do MySQL:
[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock
[mysqld_safe]
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
nice = 0
[mysqld]
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /opt/mysql-data
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
explicit_defaults_for_timestamp
sql_mode = STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
log-error = /opt/mysql-log/error.log
# Replication
server-id = 76
gtid-mode = ON
enforce-gtid-consistency = true
relay-log = /opt/mysql-log/mysql-relay-bin
relay-log-index = /opt/mysql-log/mysql-relay-bin.index
replicate-wild-do-table = dbname.%
log-bin = /opt/mysql-log/mysql-bin.log
expire_logs_days = 7
max_binlog_size = 1024M
binlog-format = ROW
log-bin-trust-function-creators = 1
log_slave_updates = 1
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0
# * IMPORTANT: Additional settings that can override those from this file!
# The files must end with '.cnf', otherwise they'll be ignored.
#
!includedir /etc/mysql/conf.d/
# Here goes
skip_name_resolve = 1
general_log = 0
slow_query_log = 1
slow_query_log_file = /opt/mysql-log/slow.log
long_query_time = 3
max_allowed_packet = 16M
max_connections = 700
max_execution_time = 200000
open_files_limit = 32000
table_open_cache = 8000
thread_cache_size = 128
innodb_buffer_pool_size = 550G
innodb_buffer_pool_instances = 28
innodb_log_file_size = 15G
innodb_log_files_in_group = 2
innodb_flush_method = O_DIRECT
max_heap_table_size = 16M
tmp_table_size = 128M
join_buffer_size = 1M
sort_buffer_size = 2M
innodb_lru_scan_depth = 256
query_cache_type = 0
query_cache_size = 0
innodb_temp_data_file_path = ibtmp1:12M:autoextend:max:30G Outras observações
perf do processo mysql durante o pico de carregamento:
68,31% 68,31% mysqld [kernel.kallsyms] [k] _raw_spin_lock
- _raw_spin_lock
+ 51,63% 0x7fd118e9dbd9
+ 48,37% 0x7fd118e9dbab
+ 37,36% 0,02% mysqld libc-2.19.so [.] 0x00000000000f4bd9
+ 33,83% 0,01% mysqld libc-2.19.so [.] 0x00000000000f4bab
+ 26,92% 0,00% mysqld libpthread-2.19.so [.] start_thread
+ 26,82% 0,00% mysqld mysqld [.] pfs_spawn_thread
+ 26,82% 0,00% mysqld mysqld [.] handle_connection
+ 26,81% 0,01% mysqld mysqld [.] do_command(THD*)
+ 26,65% 0,02% mysqld mysqld [.] dispatch_command(THD*, COM_DATA const*, enum_server_command)
+ 26,29% 0,01% mysqld mysqld [.] mysql_parse(THD*, Parser_state*)
+ 24,85% 0,01% mysqld mysqld [.] mysql_execute_command(THD*, bool)
+ 23,61% 0,00% mysqld mysqld [.] handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long)
+ 23,54% 0,00% mysqld mysqld [.] 0x0000000000374103
+ 19,78% 0,00% mysqld mysqld [.] JOIN::exec()
+ 19,13% 0,15% mysqld mysqld [.] sub_select(JOIN*, QEP_TAB*, bool)
+ 13,86% 1,48% mysqld mysqld [.] row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)
+ 8,48% 0,25% mysqld mysqld [.] ha_innobase::general_fetch(unsigned char*, unsigned int, unsigned int)
+ 7,93% 0,00% mysqld [unknown] [.] 0x00007f40c4d7a6f8
+ 7,57% 0,00% mysqld mysqld [.] 0x0000000000828f74
+ 7,25% 0,11% mysqld mysqld [.] handler::ha_index_next_same(unsigned char*, unsigned char const*, unsigned int) Isso mostra que o mysql está gastando muito tempo em spin_locks . Eu esperava ter alguma pista de onde estão vindo esses bloqueios, infelizmente, sem sorte.
O perfil de consulta durante alta carga mostra uma quantidade extrema de opções de contexto. Eu usei select * from MyTable, onde pk = 123 , MyTable tem cerca de 90 milhões de linhas. Saída do perfil:
Status Duration CPU_user CPU_system Context_voluntary Context_involuntary Block_ops_in Block_ops_out Messages_sent Messages_received Page_faults_major Page_faults_minor Swaps Source_function Source_file Source_line
starting 0,000756 0,028000 0,012000 81 1 0 0 0 0 0 0 0
checking permissions 0,000057 0,004000 0,000000 4 0 0 0 0 0 0 0 0 check_access sql_authorization.cc 810
Opening tables 0,000285 0,008000 0,004000 31 0 0 40 0 0 0 0 0 open_tables sql_base.cc 5650
init 0,000304 0,012000 0,004000 31 1 0 0 0 0 0 0 0 handle_query sql_select.cc 121
System lock 0,000303 0,012000 0,004000 33 0 0 0 0 0 0 0 0 mysql_lock_tables lock.cc 323
optimizing 0,000196 0,008000 0,004000 20 0 0 0 0 0 0 0 0 optimize sql_optimizer.cc 151
statistics 0,000885 0,036000 0,012000 99 6 0 0 0 0 0 0 0 optimize sql_optimizer.cc 367
preparing 0,000794 0,000000 0,096000 76 2 32 8 0 0 0 0 0 optimize sql_optimizer.cc 475
executing 0,000067 0,000000 0,000000 10 1 0 0 0 0 0 0 0 exec sql_executor.cc 119
Sending data 0,000469 0,000000 0,000000 54 1 32 0 0 0 0 0 0 exec sql_executor.cc 195
end 0,000609 0,000000 0,016000 64 4 0 0 0 0 0 0 0 handle_query sql_select.cc 199
query end 0,000063 0,000000 0,000000 3 1 0 0 0 0 0 0 0 mysql_execute_command sql_parse.cc 4968
closing tables 0,000156 0,000000 0,000000 20 4 0 0 0 0 0 0 0 mysql_execute_command sql_parse.cc 5020
freeing items 0,000071 0,000000 0,004000 7 1 0 0 0 0 0 0 0 mysql_parse sql_parse.cc 5596
cleaning up 0,000533 0,024000 0,008000 62 0 0 0 0 0 0 0 0 dispatch_command sql_parse.cc 1902Peter Zaitsev fez um post recentemente sobre as alternâncias de contexto, onde diz:
No mundo real, porém, eu não me preocuparia se a contenção fosse um grande problema se você tiver menos de dez alternâncias de contexto por consulta.
Mas mostra mais de 600 switches!
O que pode causar esses sintomas e o que pode ser feito sobre isso? Eu aprecio qualquer indicação ou informação sobre o assunto, tudo o que me deparei até agora é bastante antigo e / ou inconclusivo.
PS Terei prazer em fornecer informações adicionais, se necessário.
Saída de SHOW STATUS GLOBAL e SHOW VARIABLES
Não posso publicá-lo aqui porque o conteúdo excede o limite de tamanho da postagem.
MOSTRAR STATUS GLOBAIS
MOSTRAR VARIÁVEIS
iostat
avg-cpu: %user %nice %system %iowait %steal %idle
7,35 0,00 5,44 0,20 0,00 87,01
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 8,00 0,00 32,00 32,00 0,00 32,00 0,00
sda 0,04 2,27 0,13 0,96 0,86 46,52 87,05 0,00 2,52 0,41 2,80 0,28 0,03
sdb 0,21 232,57 30,86 482,91 503,42 7769,88 32,21 0,34 0,67 0,83 0,66 0,34 17,50
avg-cpu: %user %nice %system %iowait %steal %idle
9,98 0,00 77,52 0,46 0,00 12,04
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00
sda 0,00 1,60 0,00 0,60 0,00 8,80 29,33 0,00 0,00 0,00 0,00 0,00 0,00
sdb 0,00 566,40 55,60 981,60 889,60 16173,60 32,90 0,84 0,81 0,76 0,81 0,51 53,28
avg-cpu: %user %nice %system %iowait %steal %idle
11,83 0,00 72,72 0,35 0,00 15,10
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00
sda 0,00 2,60 0,00 0,40 0,00 12,00 60,00 0,00 0,00 0,00 0,00 0,00 0,00
sdb 0,00 565,20 51,60 962,80 825,60 15569,60 32,32 0,85 0,84 0,98 0,83 0,54 54,56Atualização 2018-03-15
> show global status like 'uptime%'
Uptime;720899
Uptime_since_flush_status;720899
> show global status like '%rollback'
Com_rollback;351422
Com_xa_rollback;0
Handler_rollback;371088
Handler_savepoint_rollback;0
select * from MyTable where pk = 123leva em média?global statuspara ver se há algo relacionado ao aumento do uso da CPU. Não acredito que nada possa ser alcançado com os dados disponíveis no momento. Farei outra pergunta se encontrar algo novo.Respostas:
A gravação de 600q / s com um flush por confirmação provavelmente está atingindo o limite dos discos giratórios atuais. Mudar para SSDs aliviaria a pressão.
A solução rápida (antes de obter SSDs) provavelmente deve ser alterada para esta configuração:
Mas leia as advertências sobre como fazer essa alteração.
Ter essa configuração e SSDs permitiria que você crescesse ainda mais.
Outra correção possível é combinar algumas gravações em uma única
COMMIT(onde a lógica não é violada).Quase sempre, a alta CPU e / ou E / S se deve a índices inadequados e / ou formulação deficiente de consultas. Ative o slowlog com
long_query_time=1, aguarde um pouco e veja o que aparece. Com consultas na mão, fornecerSELECT,EXPLAIN SELECT ...eSHOW CREATE TABLE. O mesmo vale para as consultas de gravação. Desses, provavelmente podemos domar a CPU e / ou E / S. Mesmo com sua configuração atual de3,pt-query-digestpode encontrar algumas coisas interessantes.Observe que, com 50 threads "em execução", há muita disputa; isso pode estar causando a troca, etc., que você anotou. Precisamos que as consultas terminem mais rapidamente. Com o 5.7, o sistema pode tombar com 100 threads em execução . Indo além de cerca de 64, as alternâncias de contexto, mutexes, bloqueios etc. conspiram para diminuir a velocidade de cada encadeamento, levando a nenhuma melhoria na taxa de transferência enquanto a latência passa pelo teto.
Para uma abordagem diferente para analisar o problema, forneça
SHOW VARIABLESeSHOW GLOBAL STATUS? Mais discussão aqui .Análise de VARIÁVEIS E ESTADO
(Desculpe, nada salta como resposta à sua pergunta.)
Observações:
As questões mais importantes:
Muitas tabelas temporárias, especialmente baseadas em disco, são criadas para consultas complexas. Vamos esperar que o log lento identifique algumas consultas que podem ser aprimoradas (via indexação / reformulação / etc.) Outros indicadores são junções sem índices e sort_merge_passes; no entanto, nenhuma dessas é conclusiva, precisamos ver as consultas.
Max_used_connections = 701é> =Max_connections = 700, portanto, provavelmente houve algumas conexões recusadas. Além disso, se isso indicou mais de, digamos, 64 threads em execução , o desempenho do sistema provavelmente sofreu naquele momento. Considere limitar o número de conexões ao limitar os clientes. Você está usando Apache, Tomcat ou algo mais? 70Threads_runningindica que, no momento de fazer issoSHOW, o sistema estava com problemas.Aumentar o número de declarações em cada uma
COMMIT(quando razoável) pode ajudar no desempenho de algumas.innodb_log_file_size, com 15 GB, é maior que o necessário, mas não vejo a necessidade de alterá-lo.Milhares de tabelas geralmente não são um bom design.
eq_range_index_dive_limit = 200me preocupa, mas não sei como aconselhar. Foi uma escolha deliberada?Por que tantos CREATE + DROP PROCEDURE?
Por que tantos comandos SHOW?
Detalhes e outras observações:
( Innodb_buffer_pool_pages_flushed ) = 523,716,598 / 3158494 = 165 /sec- Grava (flushes) - verifique innodb_buffer_pool_size( table_open_cache ) = 10,000- Número de descritores de tabela para armazenar em cache - Várias centenas geralmente são boas.( (Innodb_buffer_pool_reads + Innodb_buffer_pool_pages_flushed) ) = ((61,040,718 + 523,716,598) ) / 3158494 = 185 /sec- E / S do InnoDB( Innodb_dblwr_pages_written/Innodb_pages_written ) = 459,782,684/523,717,889 = 87.8%- Parece que esses valores devem ser iguais?( Innodb_os_log_written ) = 1,071,443,919,360 / 3158494 = 339226 /sec- Este é um indicador de quão ocupado o InnoDB está. - InnoDB muito ocupado.( Innodb_log_writes ) = 110,905,716 / 3158494 = 35 /sec( Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group / innodb_log_file_size ) = 1,071,443,919,360 / (3158494 / 3600) / 2 / 15360M = 0.0379- Proporção - (ver minutos)( Uptime / 60 * innodb_log_file_size / Innodb_os_log_written ) = 3,158,494 / 60 * 15360M / 1071443919360 = 791- Minutos entre as rotações do log do InnoDB A partir da versão 5.6.8, isso pode ser alterado dinamicamente; não se esqueça de alterar também my.cnf. - (A recomendação de 60 minutos entre as rotações é um tanto arbitrária.) Ajuste innodb_log_file_size. (Não é possível alterar na AWS.)( Com_rollback ) = 770,457 / 3158494 = 0.24 /sec- ROLLBACKs no InnoDB. - Uma frequência excessiva de reversões pode indicar lógica ineficiente do aplicativo.( Innodb_row_lock_waits ) = 632,292 / 3158494 = 0.2 /sec- Com que frequência há um atraso na obtenção de um bloqueio de linha. - Pode ser causado por consultas complexas que podem ser otimizadas.( Innodb_dblwr_writes ) = 97,725,876 / 3158494 = 31 /sec- "Buffer de gravação dupla" grava no disco. "Doublewrites" são um recurso de confiabilidade. Algumas versões / configurações mais recentes não precisam delas. - (sintoma de outras questões)( Innodb_row_lock_current_waits ) = 13- O número de bloqueios de linha atualmente sendo aguardados pelas operações nas tabelas do InnoDB. Zero é bem normal. - Algo grande está acontecendo?( innodb_print_all_deadlocks ) = OFF- Se deve registrar todos os deadlocks. - Se você estiver atormentado com deadlocks, ative-o. Cuidado: Se você tiver muitos deadlocks, isso pode gravar muito no disco.( local_infile ) = ON- local_infile = ON é um possível problema de segurança( bulk_insert_buffer_size / _ram ) = 8M / 716800M = 0.00%- Buffer para INSERTs com várias linhas e LOAD DATA - Muito grande pode ameaçar o tamanho da RAM. Um tamanho muito pequeno pode dificultar essas operações.( Questions ) = 9,658,430,713 / 3158494 = 3057 /sec- Consultas (fora de SP) - "qps" -> 2000 podem estar estressando o servidor( Queries ) = 9,678,805,194 / 3158494 = 3064 /sec- Consultas (inclusive dentro de SP) -> 3000 podem estar estressando o servidor( Created_tmp_tables ) = 1,107,271,497 / 3158494 = 350 /sec- Frequência de criação de tabelas "temporárias" como parte de SELECTs complexos.( Created_tmp_disk_tables ) = 297,023,373 / 3158494 = 94 /sec- Frequência de criação de tabelas "temporárias" de disco como parte de SELECTs complexos - aumente tmp_table_size e max_heap_table_size. Verifique as regras para as tabelas temporárias quando o MEMORY for usado, em vez do MyISAM. Talvez pequenas alterações no esquema ou na consulta possam evitar o MyISAM. Melhores índices e reformulação de consultas são mais propensos a ajudar.( (Com_insert + Com_update + Com_delete + Com_replace) / Com_commit ) = (693300264 + 214511608 + 37537668 + 0) / 1672382928 = 0.565- Declarações por confirmação (assumindo todo o InnoDB) - Baixa: Pode ajudar a agrupar consultas em transações; Alto: transações longas sobrecarregam várias coisas.( Select_full_join ) = 338,957,314 / 3158494 = 107 /sec- junções sem índice - Adicione índices adequados às tabelas usadas em JOINs.( Select_full_join / Com_select ) = 338,957,314 / 6763083714 = 5.0%-% de seleções que são junção sem índice - Adicione índices adequados às tabelas usadas em JOINs.( Select_scan ) = 124,606,973 / 3158494 = 39 /sec- varreduras completas de tabelas - Adicione índices / otimize consultas (a menos que sejam pequenas tabelas)( Sort_merge_passes ) = 1,136,548 / 3158494 = 0.36 /sec- Classificação de Heafty - Aumente sort_buffer_size e / ou otimize consultas complexas.( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (693300264 + 37537668 + 198418338 + 0 + 214511608 + 79274476) / 3158494 = 387 /sec- gravações / s - 50 gravações / s + descargas de log provavelmente maximizarão a capacidade de gravação de E / S das unidades normais( ( Com_stmt_prepare - Com_stmt_close ) / ( Com_stmt_prepare + Com_stmt_close ) ) = ( 39 - 38 ) / ( 39 + 38 ) = 1.3%- Você está fechando suas declarações preparadas? - Adicionar fecha.( Com_stmt_close / Com_stmt_prepare ) = 38 / 39 = 97.4%- As declarações preparadas devem ser fechadas. - Verifique se todas as instruções preparadas estão "fechadas".( innodb_autoinc_lock_mode ) = 1- Galera: desejos 2 - 2 = "intercalados"; 1 = "consecutivo" é típico; 0 = "tradicional".( Max_used_connections / max_connections ) = 701 / 700 = 100.1%-% de pico de conexões - aumente max_connections e / ou diminua wait_timeout( Threads_running - 1 ) = 71 - 1 = 70- Threads ativos (simultaneidade quando os dados são coletados) - Otimize consultas e / ou esquemaAnormalmente grande: (A maioria deles resulta de ser um sistema muito ocupado.)
(contínuo)
fonte
innodb_flush_log_at_trx_commit = 2parece não ter nenhum efeito e a contenção de encadeamentos também não parece ser o problema, porque mesmo com cargas moderadas (Threads runnig <50) sys / usuário da CPU é algo entre 3 e 1.Nunca descobrimos qual era a causa exata desse problema, mas, para oferecer um fechamento, vou contar o que posso.
Nossa equipe fez alguns testes de carga e concluiu que
MySQLhavia problemas ao alocar memória. Então eles tentaram usar emjemallocvez deglibce o problema desapareceu. Estamos usando ajemallocprodução há mais de 6 meses, sem nunca mais ver esse problema.Não estou dizendo que
jemallocé melhor ou que todos deveriam usá-loMySQL. Mas parece que, no nosso caso específico,glibcnão estava funcionando corretamente.fonte
Meus 2 centavos.
Execute "iostat -xk 5" para tentar ver se o disco ainda está com problema. Além disso, o sistema da CPU está relacionado ao código do sistema (kernell), verifique novamente o novo disco / drivers / config.
fonte
Sugestões para a seção my.cnf / ini [mysqld] para o seu MUITO OCUPADO
Minha expectativa é uma diminuição gradual nos resultados de SHOW GLOBAL STATUS LIKE 'innodb_buffer_pool_pages_dirty'; com essas sugestões aplicadas. Em 13/1/18, você tinha mais de 4 milhões de páginas sujas.
Espero que estas ajudem. Estes podem ser modificados dinamicamente. Existem muitas outras oportunidades, se você as quiser, me avise.
fonte
Com o IOPS em 30K testado (precisamos de vários IOPS para gravações aleatórias), considere esta sugestão para a seção my.cnf / ini [mysqld]
pode ser alterado dinamicamente com SET GLOBAL e deve reduzir o innodb_buffer_pool_pages_dirty rapidamente.
A causa da média de COM_ROLLBACK 1 a cada 4 segundos continuará sendo um problema de desempenho até que seja resolvido.
@chimmi 9 de abril de 2018 Pegue esse script do MySQL em https://pastebin.com/aZAu2zZ0 para uma verificação rápida dos recursos de Status Global usados ou liberados por nn segundos que você pode configurar no SLEEP. Isso permitirá que você veja se alguém ajudou a reduzir sua frequência COM_ROLLBACK. Gostaria de ouvir você por e-mail.
fonte
Seu SHOW GLOBAL STATUS indica que innodb_buffer_pool_pages_dirty foram 4.291.574.
Para monitorar a contagem atual,
Para incentivar a redução dessa contagem,
Em uma hora, execute a solicitação do monitor para ver onde você está com as páginas sujas.
Por favor, deixe-me saber suas contagens no início e uma hora depois.
Aplique a alteração no seu my.cnf para obter uma melhor saúde a longo prazo das reduções sujas de páginas.
fonte