Problema

Uma instância do MySQL 5.6.20 executando (principalmente apenas) um banco de dados com tabelas do InnoDB está exibindo paradas ocasionais para todas as operações de atualização pela duração de 1 a 4 minutos, com todas as consultas INSERT, UPDATE e DELETE restantes no estado "Query end". Obviamente, isso é muito lamentável. O log de consultas lentas do MySQL está registrando até as consultas mais triviais com tempos de consulta insanos, centenas deles com o mesmo registro de data e hora correspondente ao ponto no tempo em que a paralisação 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 carga excessiva de E / S nesse período (nesse caso, as atualizações foram interrompidas 14:17:30 - 14:19:12 de acordo com os registros de data e hora 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, percebo no log lento do mysql que a parada mais antiga da consulta é 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 (por exemplo, SHOW ENGINE INNODB STATUS) mostrou que, de fato, sempre é uma atualização para uma tabela usando índices de texto completo que estão causando a paralisação. A seção respectiva TRANSACTIONS do "SHOW ENGINE INNODB STATUS" possui entradas como estas 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), interrompendo TODAS AS SUBSEQUENTES atualizações para QUALQUER tabela.

A partir dos registros, parece um pouco o undo log entriesnúmero dedoing SYNC index avança em ~ 150 / s até atingir 20.000, momento em que a operação é concluída.

O tamanho do STF 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 desencadeado por tabelas com tamanho de dados do STF 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. Abri um bug no bugs.mysql.com para que os desenvolvedores pudessem analisar isso.

A natureza das barracas fez com que eu suspeitasse que a atividade de descarga de logs fosse a culpada e este artigo da Percona sobre problemas de desempenho de descarga de logs com o MySQL 5.5 está descrevendo sintomas muito semelhantes, mas outras ocorrências mostraram que INSERIR operações na única tabela MyISAM neste banco de dados também são afetados pelo estol, portanto, isso não parece ser um problema apenas do InnoDB.

No entanto, decidi rastrear os valores de Log sequence numbere a Pages flushed up topartir das saídas da seção "LOG" aSHOW ENGINE INNODB STATUS cada 10 segundos. De fato, parece que a atividade de descarga está em andamento durante a paralisação, 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 a propagação atingiu seu mínimo, então a atividade de descarga parece ter cessado aqui, apenas coincidindo com o fim da barraca. Mas esses pontos me fizeram descartar a liberação do log do InnoDB como a causa:

• para que a operação de liberação bloqueie todas as atualizações no banco de dados, ela precisa ser "síncrona", o que significa que 7/8 do espaço do log deve ser ocupado
• seria precedida por uma fase de descarga "assíncrona" iniciando no innodb_max_dirty_pages_pctnível de preenchimento - o que não estou vendo
• os LSNs continuam aumentando mesmo durante a paralisação, portanto a atividade de log não é completamente interrompida
• Os INSERTs da tabela MyISAM também são afetados
• o encadeamento page_cleaner para liberação adaptativa parece fazer seu trabalho e liberar os logs sem fazer com que as consultas DML parem:

^{(os números são ([Log Sequence Number] - [Pages flushed up to]) / 1024de SHOW ENGINE INNODB STATUS)}

A questão parece um pouco aliviada 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 possui entradas coincidentes com as barracas. 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

Portanto, sim, o banco de dados possui impasses, mas são muito pouco frequentes (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 paralisação (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, caso de uma tenda óbvia). Como os números foram tomados em períodos diferentes, 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 muita certeza do que estou vendo aqui. A maioria dos números caiu em uma ordem de magnitude - provavelmente devido a operações de atualização interrompidas, "as rotações do Mutex esperam" e "rodadas de rotação do Mutex", no entanto, aumentaram pelo fator 4.

Investigando isso ainda mais, a lista de mutexes ( SHOW ENGINE INNODB MUTEX) possui ~ 480 entradas de mutex listadas tanto na operação normal quanto durante uma paralisação. Eu habilitei innodb_status_output_lockspara ver se isso vai me dar mais detalhes.

Variáveis ​​de configuração

(Eu consertei a maioria deles sem sucesso definido):

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

As coisas já tentaram

• desabilitando o cache de consulta SET GLOBAL query_cache_size=0
• aumentando innodb_log_buffer_sizepara 128M
• brincar com innodb_adaptive_flushing, innodb_max_dirty_pages_pcte os respectivos _lwmvalores (que foram criados para os padrões antes de as minhas alterações)
• crescente innodb_io_capacity(2000) einnodb_io_capacity_max (4000)
• configuração 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 como noopoudeadline

Estávamos vendo o mesmo problema em dois servidores nas versões 5.6.12 e 5.6.16 em execução no Windows, com um par de escravos cada. Ficamos perplexos, como você, por quase dois meses.

Solução :

set global binlog_order_commits = 0;

Consulte https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_binlog_order_commits para obter detalhes da variável.

Explicação :

O texto completo do InnoDB usa um cache (por padrão, 8M de tamanho), contendo alterações que precisam ser aplicadas ao índice de texto completo do disco.

Depois que o cache é preenchido, duas transações são criadas para realizar o trabalho de mesclar os dados que estavam contidos no cache - isso tende a ser uma grande quantidade de E / S aleatória, 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 que contêm inserções e atualizações, iniciadas após a transação fts_sync_index de execução demorada, devem esperar até que sejam concluídas antes de serem confirmadas.

Isso é apenas um problema se o log binário estiver ativado

Deixe-me talvez tentar descrever o problema histórico com a descarga de logs e como funciona a descarga adaptável:

• Os logs refazer são um design de buffer de anel . Eles só são gravados (nunca lidos em operação normal) e são 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á substituir o espaço no arquivo de log se ele contiver alterações que ainda não foram modificadas no disco. Portanto, 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 bastasse, você alcançaria o espaço total do log. Uma paralisação ocorreria com a liberação síncrona necessária para liberar espaço repentinamente, tornando o que geralmente é uma tarefa em segundo plano repentinamente em primeiro plano.

• Para resolver esse problema, a liberação adaptável foi introduzida. Onde com 10% (padrão) de espaço de log consumido, o trabalho em segundo plano começa a ficar progressivamente mais agressivo. O objetivo disso é, em vez de uma interrupção repentina, você tem mais uma "queda curta" no desempenho.

• Independente de rubor de adaptação, é importante ter espaço de log suficiente para sua carga de trabalho ( innodb_log_file_sizevalores de 4G estão agora bastante seguro), e certifique-se de que innodb_io_capacitye innodb_lru_scan_depthsão definidas para valores realistas. Os 10% de descarga adaptável innodb_adaptive_flushing_lwmsão algo que você não estica muito, é mais um mecanismo de defesa contra o espaço.

Só para trazer ao InnoDB algum alívio, você pode brincar 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 o innodb_purge_threadsMySQL 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?

Valores diferentes de zero executam a operação de limpeza em um ou mais encadeamentos em segundo plano, o que pode reduzir a contenção interna no InnoDB, melhorando a escalabilidade. Aumentar o valor para mais de 1 cria muitos encadeamentos de eliminação separados, o que pode melhorar a eficiência nos sistemas em que as operações DML são executadas em várias tabelas.

Eu começaria definindo innodb_purge_threads como 4 e ver se a liberação da página do InnoDB é reduzida.

ATUALIZAÇÃO 02-09-2014 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 aos 50 anos.

O padrão para innodb_max_dirty_pages_pct no MySQL 5.5+ é 75. Reduzi- lo aumentaria a incidência de paradas por descarga. Eu faria três (3) coisas

• Aumente innodb_max_dirty_pages_pct para 90 (esse era o padrão para o MySQL 5.1)
• Defina innodb_max_dirty_pages_pct_lwm = 0 (o padrão) ou remova-o demy.cnf
• Aumente innodb_log_buffer_size para 128M (metade do seu innodb_log_file_size )

ATUALIZAÇÃO 03-09-2014 11:06 EDT

Pode ser necessário alterar seu comportamento de descarga

Tente definir o seguinte dinamicamente

SET GLOBAL flush = 1;
SET GLOBAL flush_time = 10;

Essas variáveis, flush e flush_time , tornarão a liberação mais agressiva, fechando identificadores de arquivos abertos nas tabelas a cada 10 segundos. O MyISAM pode definitivamente se beneficiar dele porque não armazena dados em cache. Todas as gravações nas tabelas MyISAM requerem bloqueios completos, seguidos de gravações atômicas e dependem do sistema operacional para alterações no disco.

Esvaziar o InnoDB dessa maneira exigiria uma reinicialização do mysql. As opções para ver são innodb_flush_log_at_trx_commit e innodb_flush_method .

Antes de reiniciar, adicione estes

[mysqld]
flush = 1
flush_time = 10
innodb_flush_log_at_trx_commit = 0
innodb_flush_method = O_DIRECT

Antes de seguir esta rota, verifique se o registro no diário é um problema. Eu vi esse post legal do mysqlperformanceblog no O_DIRECT sendo falsificado por causa do kernel. O mesmo post também menciona o MyISAM sendo afetado.

Eu escrevi sobre este post antes: ib_logfile aberto com O_SYNC quando innodb_flush_method = O_DSYNC

De uma chance !!!