Problema
Uma instância do MySQL 5.6.20 executando (principalmente apenas) um banco de dados com tabelas InnoDB está exibindo travamentos ocasionais para todas as operações de atualização com duração de 1 a 4 minutos, com todas as consultas INSERT, UPDATE e DELETE permanecendo no estado "Fim da consulta". Isso obviamente é muito lamentável. O log de consultas lentas do MySQL está registrando até mesmo as consultas mais triviais com tempos de consulta insanos, centenas delas com o mesmo carimbo de data/hora correspondente ao ponto no tempo em que a parada foi resolvida:
# Query_time: 101.743589 Lock_time: 0.000437 Rows_sent: 0 Rows_examined: 0
SET timestamp=1409573952;
INSERT INTO sessions (redirect_login2, data, hostname, fk_users_primary, fk_users, id_sessions, timestamp) VALUES (NULL, NULL, '192.168.10.151', NULL, 'anonymous', '64ef367018099de4d4183ffa3bc0848a', '1409573850');
E as estatísticas do dispositivo estão mostrando um aumento, embora não haja uma carga de I/O excessiva neste intervalo de tempo (neste caso, as atualizações estavam travando 14:17:30 - 14:19:12 de acordo com os timestamps da declaração acima):
# sar -d
[...]
02:15:01 PM DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util
02:16:01 PM dev8-0 41.53 207.43 1227.51 34.55 0.34 8.28 3.89 16.15
02:17:01 PM dev8-0 59.41 137.71 2240.32 40.02 0.39 6.53 4.04 24.00
02:18:01 PM dev8-0 122.08 2816.99 1633.44 36.45 3.84 31.46 1.21 2.88
02:19:01 PM dev8-0 253.29 5559.84 3888.03 37.30 6.61 26.08 1.85 6.73
02:20:01 PM dev8-0 101.74 1391.92 2786.41 41.07 1.69 16.57 3.55 36.17
[...]
# sar
[...]
02:15:01 PM CPU %user %nice %system %iowait %steal %idle
02:16:01 PM all 15.99 0.00 12.49 2.08 0.00 69.44
02:17:01 PM all 13.67 0.00 9.45 3.15 0.00 73.73
02:18:01 PM all 10.64 0.00 6.26 11.65 0.00 71.45
02:19:01 PM all 3.83 0.00 2.42 24.84 0.00 68.91
02:20:01 PM all 20.95 0.00 15.14 6.83 0.00 57.07
Na maioria das vezes, noto no log lento do mysql que a interrupção da consulta mais antiga é um INSERT em uma tabela grande (~ 10 M linhas) com uma chave primária VARCHAR e um índice de pesquisa de texto completo:
CREATE TABLE `files` (
`id_files` varchar(32) NOT NULL DEFAULT '',
`filename` varchar(100) NOT NULL DEFAULT '',
`content` text,
PRIMARY KEY (`id_files`),
KEY `filename` (`filename`),
FULLTEXT KEY `content` (`content`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
Uma investigação mais aprofundada (ou seja, SHOW ENGINE INNODB STATUS) mostrou que, de fato, sempre é uma atualização em uma tabela usando índices de texto completo que está causando a paralisação. A respectiva seção TRANSACTIONS de "SHOW ENGINE INNODB STATUS" tem entradas como estas duas para as transações em execução mais antigas:
---TRANSACTION 162269409, ACTIVE 122 sec doing SYNC index
6 lock struct(s), heap size 1184, 0 row lock(s), undo log entries 19942
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_1" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_2" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_3" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_4" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_5" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_6" trx id 162269409 lock mode IX
---TRANSACTION 162269408, ACTIVE (PREPARED) 122 sec committing
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 165998, OS thread handle 0x7fe0e239c700, query id 91208956 192.168.10.153 root query end
INSERT INTO files (id_files, filename, content) VALUES ('f19e63340fad44841580c0371bc51434', '1237716_File_70380a686effd6b66592bb5eeb3d9b06.doc', '[...]
TABLE LOCK table `vw`.`files` trx id 162269408 lock mode IX
Portanto, há alguma ação pesada de índice de texto completo acontecendo lá ( doing SYNC index) parando TODAS AS atualizações SUBSEQUENTES em QUALQUER tabela.
A partir dos logs, parece que o undo log entriesnúmero doing SYNC indexestá avançando a ~ 150/s até atingir 20.000, ponto em que a operação é concluída.
O tamanho FTS desta tabela específica é bastante impressionante:
# du -c FTS_000000000000224a_00000000000036b9_*
614404 FTS_000000000000224a_00000000000036b9_INDEX_1.ibd
2478084 FTS_000000000000224a_00000000000036b9_INDEX_2.ibd
1576964 FTS_000000000000224a_00000000000036b9_INDEX_3.ibd
1630212 FTS_000000000000224a_00000000000036b9_INDEX_4.ibd
1978372 FTS_000000000000224a_00000000000036b9_INDEX_5.ibd
1159172 FTS_000000000000224a_00000000000036b9_INDEX_6.ibd
9437208 total
embora o problema também seja acionado por tabelas com tamanho de dados FTS significativamente menor como este:
# du -c FTS_0000000000002467_0000000000003a21_INDEX*
49156 FTS_0000000000002467_0000000000003a21_INDEX_1.ibd
225284 FTS_0000000000002467_0000000000003a21_INDEX_2.ibd
147460 FTS_0000000000002467_0000000000003a21_INDEX_3.ibd
135172 FTS_0000000000002467_0000000000003a21_INDEX_4.ibd
155652 FTS_0000000000002467_0000000000003a21_INDEX_5.ibd
106500 FTS_0000000000002467_0000000000003a21_INDEX_6.ibd
819224 total
O tempo de estol nesses casos também é aproximadamente o mesmo. Eu abri um bug em bugs.mysql.com para que os desenvolvedores pudessem investigar isso.
A natureza das paradas primeiro me fez suspeitar que a atividade de liberação de log seja a culpada e este artigo da Percona sobre problemas de desempenho de liberação de log com o MySQL 5.5 está descrevendo sintomas muito semelhantes, mas outras ocorrências mostraram que as operações INSERT na única tabela MyISAM neste banco de dados também são afetados pela parada, então isso não parece ser um problema apenas do InnoDB.
No entanto, decidi rastrear os valores de Log sequence numbere Pages flushed up todas saídas da seção "LOG"SHOW ENGINE INNODB STATUS a cada 10 segundos. De fato, parece que a atividade de descarga está em andamento durante a parada, pois a dispersão entre os dois valores está diminuindo:
Mon Sep 1 14:17:08 CEST 2014 LSN: 263992263703, Pages flushed: 263973405075, Difference: 18416 K
Mon Sep 1 14:17:19 CEST 2014 LSN: 263992826715, Pages flushed: 263973811282, Difference: 18569 K
Mon Sep 1 14:17:29 CEST 2014 LSN: 263993160647, Pages flushed: 263974544320, Difference: 18180 K
Mon Sep 1 14:17:39 CEST 2014 LSN: 263993539171, Pages flushed: 263974784191, Difference: 18315 K
Mon Sep 1 14:17:49 CEST 2014 LSN: 263993785507, Pages flushed: 263975990474, Difference: 17377 K
Mon Sep 1 14:17:59 CEST 2014 LSN: 263994298172, Pages flushed: 263976855227, Difference: 17034 K
Mon Sep 1 14:18:09 CEST 2014 LSN: 263994670794, Pages flushed: 263978062309, Difference: 16219 K
Mon Sep 1 14:18:19 CEST 2014 LSN: 263995014722, Pages flushed: 263983319652, Difference: 11420 K
Mon Sep 1 14:18:30 CEST 2014 LSN: 263995404674, Pages flushed: 263986138726, Difference: 9048 K
Mon Sep 1 14:18:40 CEST 2014 LSN: 263995718244, Pages flushed: 263988558036, Difference: 6992 K
Mon Sep 1 14:18:50 CEST 2014 LSN: 263996129424, Pages flushed: 263988808179, Difference: 7149 K
Mon Sep 1 14:19:00 CEST 2014 LSN: 263996517064, Pages flushed: 263992009344, Difference: 4402 K
Mon Sep 1 14:19:11 CEST 2014 LSN: 263996979188, Pages flushed: 263993364509, Difference: 3529 K
Mon Sep 1 14:19:21 CEST 2014 LSN: 263998880477, Pages flushed: 263993558842, Difference: 5196 K
Mon Sep 1 14:19:31 CEST 2014 LSN: 264001013381, Pages flushed: 263993568285, Difference: 7270 K
Mon Sep 1 14:19:41 CEST 2014 LSN: 264001933489, Pages flushed: 263993578961, Difference: 8158 K
Mon Sep 1 14:19:51 CEST 2014 LSN: 264004225438, Pages flushed: 263993585459, Difference: 10390 K
E às 14:19:11 o spread atingiu seu mínimo, então a atividade de descarga parece ter cessado aqui, apenas coincidindo com o fim da tenda. Mas esses pontos me fizeram descartar a descarga de log do InnoDB como a causa:
- para que a operação de limpeza bloqueie todas as atualizações no banco de dados, ela precisa ser "síncrona", o que significa que 7/8 do espaço de log deve ser ocupado
- seria precedido por uma fase de descarga "assíncrona" começando no
innodb_max_dirty_pages_pctnível de preenchimento - o que não estou vendo - os LSNs continuam aumentando mesmo durante a parada, então a atividade de log não está parando completamente
- Os INSERTs da tabela MyISAM também são afetados
- o thread page_cleaner para liberação adaptativa parece fazer seu trabalho e liberar os logs sem interromper as consultas DML:
(os números são ([Log Sequence Number] - [Pages flushed up to]) / 1024de SHOW ENGINE INNODB STATUS)
O problema parece um pouco aliviado ao definir innodb_adaptive_flushing_lwm=1, forçando o limpador de página a fazer mais trabalho do que antes.
O error.lognão tem entradas coincidentes com as baias. SHOW INNODB STATUStrechos após aproximadamente 24 horas de operação são assim:
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 789330
OS WAIT ARRAY INFO: signal count 1424848
Mutex spin waits 269678, rounds 3114657, OS waits 65965
RW-shared spins 941620, rounds 20437223, OS waits 442474
RW-excl spins 451007, rounds 13254440, OS waits 215151
Spin rounds per wait: 11.55 mutex, 21.70 RW-shared, 29.39 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
2014-09-03 10:33:55 7fe0e2e44700
[...]
--------
FILE I/O
--------
[...]
932635 OS file reads, 2117126 OS file writes, 1193633 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 17.00 writes/s, 1.20 fsyncs/s
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Main thread process no. 54745, id 140604272338688, state: sleeping
Number of rows inserted 528904, updated 1596758, deleted 99860, read 3325217158
5.40 inserts/s, 10.40 updates/s, 0.00 deletes/s, 122969.21 reads/s
Então, sim, o banco de dados tem impasses, mas eles são muito raros (o "mais recente" foi tratado cerca de 11 horas antes da leitura das estatísticas).
Tentei rastrear os valores da seção "SEMAPHORES" durante um período de tempo, especialmente em uma situação de operação normal e durante uma parada (escrevi um pequeno script verificando a lista de processos do servidor MySQL e executando alguns comandos de diagnóstico em uma saída de log no caso de uma parada óbvia). Como os números foram obtidos em diferentes intervalos de tempo, normalizei os resultados para eventos/segundo:
normal stall
1h avg 1m avg
OS WAIT ARRAY INFO:
reservation count 5,74 1,00
signal count 24,43 3,17
Mutex spin waits 1,32 5,67
rounds 8,33 25,85
OS waits 0,16 0,43
RW-shared spins 9,52 0,76
rounds 140,73 13,39
OS waits 2,60 0,27
RW-excl spins 6,36 1,08
rounds 178,42 16,51
OS waits 2,38 0,20
Não tenho certeza do que estou vendo aqui. A maioria dos números caiu em uma ordem de magnitude - provavelmente devido à interrupção das operações de atualização, "esperas de rotação mutex" e "rodadas de rotação mutex", no entanto, aumentaram pelo fator de 4.
Investigando isso ainda mais, a lista de mutexes ( SHOW ENGINE INNODB MUTEX) tem ~480 entradas de mutex listadas tanto na operação normal quanto durante uma parada. Eu habilitei innodb_status_output_lockspara ver se ele vai me dar mais detalhes.
Variáveis de configuração
(Eu mexi com a maioria deles sem sucesso definitivo):
mysql> show global variables where variable_name like 'innodb_adaptive_flush%';
+------------------------------+-------+
| Variable_name | Value |
+------------------------------+-------+
| innodb_adaptive_flushing | ON |
| innodb_adaptive_flushing_lwm | 1 |
+------------------------------+-------+
mysql> show global variables where variable_name like 'innodb_max_dirty_pages_pct%';
+--------------------------------+-------+
| Variable_name | Value |
+--------------------------------+-------+
| innodb_max_dirty_pages_pct | 50 |
| innodb_max_dirty_pages_pct_lwm | 10 |
+--------------------------------+-------+
mysql> show global variables where variable_name like 'innodb_log_%';
+-----------------------------+-----------+
| Variable_name | Value |
+-----------------------------+-----------+
| innodb_log_buffer_size | 8388608 |
| innodb_log_compressed_pages | ON |
| innodb_log_file_size | 268435456 |
| innodb_log_files_in_group | 2 |
| innodb_log_group_home_dir | ./ |
+-----------------------------+-----------+
mysql> show global variables where variable_name like 'innodb_double%';
+--------------------+-------+
| Variable_name | Value |
+--------------------+-------+
| innodb_doublewrite | ON |
+--------------------+-------+
mysql> show global variables where variable_name like 'innodb_buffer_pool%';
+-------------------------------------+----------------+
| Variable_name | Value |
+-------------------------------------+----------------+
| innodb_buffer_pool_dump_at_shutdown | OFF |
| innodb_buffer_pool_dump_now | OFF |
| innodb_buffer_pool_filename | ib_buffer_pool |
| innodb_buffer_pool_instances | 8 |
| innodb_buffer_pool_load_abort | OFF |
| innodb_buffer_pool_load_at_startup | OFF |
| innodb_buffer_pool_load_now | OFF |
| innodb_buffer_pool_size | 29360128000 |
+-------------------------------------+----------------+
mysql> show global variables where variable_name like 'innodb_io_capacity%';
+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| innodb_io_capacity | 200 |
| innodb_io_capacity_max | 2000 |
+------------------------+-------+
mysql> show global variables where variable_name like 'innodb_lru_scan_depth%';
+-----------------------+-------+
| Variable_name | Value |
+-----------------------+-------+
| innodb_lru_scan_depth | 1024 |
+-----------------------+-------+
Coisas já tentadas
- desativando o cache de consulta por
SET GLOBAL query_cache_size=0 - aumentando
innodb_log_buffer_sizepara 128 milhões - brincando com
innodb_adaptive_flushing,innodb_max_dirty_pages_pcte os respectivos_lwmvalores (eles foram definidos como padrão antes das minhas alterações) - crescente
innodb_io_capacity(2000) einnodb_io_capacity_max(4000) - contexto
innodb_flush_log_at_trx_commit = 2 - executando com innodb_flush_method = O_DIRECT (sim, usamos uma SAN com um cache de gravação persistente)
- definindo o /sys/block/sda/queue/scheduler para
noopoudeadline
We were seeing the same issue on two servers on versions 5.6.12 and 5.6.16 running on Windows, with a pair of slaves each. We were stumped, like you, for almost two months.
Solution:
See https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_binlog_order_commits for details of the variable.
Explanation:
InnoDB full-text uses a cache (by default 8M in size) containing changes that need to be applied to the actual full-text index on disk.
Depois que o cache fica cheio, algumas transações são criadas para executar o trabalho de mesclar os dados contidos no cache - isso tende a ser uma grande quantidade de IO aleatório; portanto, a menos que todo o índice de texto completo possa ser carregado no o buffer pool, é uma transação longa e lenta.
Com binlog_order_commits definido como true, todas as transações contendo inserções e atualizações, iniciadas após a transação fts_sync_index de execução longa, devem aguardar até que ela seja concluída antes de poderem ser confirmadas.
Isso só é um problema se o registro binário estiver ativado
Deixe-me tentar descrever o problema histórico com a descarga de log e como a descarga adaptativa funciona:
Os redo logs são um design de buffer em anel . Eles são apenas gravados (nunca lidos em operação normal) e fornecidos na recuperação de falhas. Eu gosto de descrever um buffer de anel como semelhante ao piso de um tanque.
O InnoDB não poderá sobrescrever o espaço do arquivo de log se contiver alterações que ainda não foram modificadas no disco. Então, historicamente, o que aconteceria é que o InnoDB tentaria uma certa quantidade de trabalho por segundo (configurado por
innodb_io_capacity) e, se isso não fosse suficiente, você atingiria o espaço total do log. Uma parada ocorreria quando a descarga síncrona precisasse ocorrer para liberar espaço repentinamente, tornando o que geralmente é uma tarefa em segundo plano repentinamente em primeiro plano.Para resolver esse problema, foi introduzida a descarga adaptativa. Onde em 10% (padrão) o espaço de log consumido, o trabalho em segundo plano começa a ficar progressivamente mais agressivo. O objetivo disso é, em vez de uma parada repentina, você tem mais uma 'pequena queda' no desempenho.
Independentemente da liberação adaptativa, é importante ter espaço de log suficiente para sua carga de trabalho (
innodb_log_file_sizevalores de 4G agora são bastante seguros) e certifique-se de queinnodb_io_capacityestãoinnodb_lru_scan_depthdefinidos com valores realistas. A descarga adaptativa de 10%innodb_adaptive_flushing_lwmé algo que você não estende muito, é mais um mecanismo de defesa contra falta de espaço.Apenas para trazer ao InnoDB algum alívio de contenção, você pode brincar com
innodb_purge_threads.Antes do MySQL 5.6, o Master Thread fazia toda a limpeza da página. No MySQL 5.6, um thread separado pode lidar com isso. O valor padrão para
innodb_purge_threadsno MySQL 5.5 era 0 com um máximo de 1. No MySQL 5.6, o padrão é 1 com um máximo de 32.O que a configuração
innodb_purge_threadsrealmente faz?Eu começaria definindo innodb_purge_threads como 4 e veria se a limpeza da página InnoDB é reduzida.
ATUALIZAÇÃO 2014-09-02 12:33 EDT
Morgan Tocker apontou no comentário abaixo que o limpador de página é a vítima e o MySQL 5.7 pode resolvê-lo . Não obstante, sua situação está no MySQL 5.6.
Dei uma segunda olhada e notei que você tem innodb_max_dirty_pages_pct em 50.
The default for innodb_max_dirty_pages_pct in MySQL 5.5+ is 75. Lowering it would increase the incidence of stalls from flushing. I would do three(3) things
my.cnfUPDATE 2014-09-03 11:06 EDT
You may need to change your flushing behavior
Try setting the following dynamically
These variables, flush and flush_time, will make flushing more aggressive by closing open file handles on tables every 10 seconds. MyISAM can definitely benefit from it because it does not cache data. All writes to MyISAM tables require full table locks, followed by atomic writes, and depend on the OS for disk changes.
Flushing InnoDB that way would require a mysql restart. The options to see are innodb_flush_log_at_trx_commit and innodb_flush_method.
Before you restart, please add these
Before going this route, you should check if journaling is an issue. I saw this cool mysqlperformanceblog post on O_DIRECT being faked because of the kernel. The same post also mentions MyISAM being affected.
I wrote about this post before : ib_logfile opened with O_SYNC when innodb_flush_method=O_DSYNC
Give it a Try !!!