Problème

Une instance de MySQL 5.6.20 exécutant (principalement juste) une base de données avec des tables InnoDB présente des blocages occasionnels pour toutes les opérations de mise à jour pendant une durée de 1 à 4 minutes avec toutes les requêtes INSERT, UPDATE et DELETE restant dans l'état "Query end". C'est évidemment très regrettable. Le journal des requêtes lentes MySQL enregistre même les requêtes les plus triviales avec des temps de requête insensés, des centaines d'entre elles avec le même horodatage correspondant au moment où le blocage a été résolu:

# 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');

Et les statistiques de l'appareil montrent une charge d'E / S accrue, mais pas excessive dans ce laps de temps (dans ce cas, les mises à jour étaient bloquées de 14h17h30 à 14h19h12 selon les horodatages de la déclaration ci-dessus):

# 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

Plus souvent qu'autrement, je remarque dans le journal lent mysql que la plus ancienne requête bloquant est un INSERT dans une table de grande taille (~ 10 M lignes) avec une clé primaire VARCHAR et un index de recherche en texte intégral:

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

Une enquête plus approfondie (c'est-à-dire SHOW ENGINE INNODB STATUS) a montré qu'il s'agit en effet toujours d' une mise à jour d'une table utilisant des index de texte intégral qui est à l'origine du blocage. La section TRANSACTIONS respective de "SHOW ENGINE INNODB STATUS" contient des entrées comme celles-ci pour les transactions en cours les plus anciennes:

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

Il y a donc une action d'index de texte intégral lourde en cours là ( doing SYNC index) arrêtant TOUTES LES MISES À JOUR ULTÉRIEURES à N'IMPORTE QUELLE table.

D'après les journaux, il semble un peu que le undo log entriesnombre de doing SYNC indexprogresse à ~ 150 / s jusqu'à ce qu'il atteigne 20 000, auquel point l'opération est terminée.

La taille FTS de cette table spécifique est assez impressionnante:

# 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

bien que le problème soit également déclenché par des tables avec une taille de données FTS beaucoup moins massive comme celle-ci:

# 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

Le temps de décrochage dans ces cas est à peu près le même aussi. J'ai ouvert un bogue sur bugs.mysql.com afin que les développeurs puissent se pencher sur cela.

La nature des décrochages m'a d'abord fait soupçonner que l'activité de vidage des journaux était le coupable et cet article de Percona sur les problèmes de performances de vidage des journaux avec MySQL 5.5 décrit des symptômes très similaires, mais d'autres événements ont montré que les opérations INSERT dans la seule table MyISAM de cette base de données sont également affectés par le blocage, donc cela ne semble pas être un problème uniquement avec InnoDB.

Néanmoins, j'ai décidé de suivre les valeurs de Log sequence numberet à Pages flushed up topartir des sorties de la section "LOG" de SHOW ENGINE INNODB STATUStoutes les 10 secondes. Il semble en effet que l'activité de rinçage se poursuive pendant le décrochage car l'écart entre les deux valeurs diminue:

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

Et à 14:19:11 la propagation a atteint son minimum, donc l'activité de rinçage semble avoir cessé ici, coïncidant juste avec la fin du décrochage. Mais ces points m'ont fait rejeter la purge du journal InnoDB comme cause:

• pour que l'opération de vidage bloque toutes les mises à jour de la base de données, elle doit être "synchrone", ce qui signifie que 7/8 de l'espace journal doit être occupé
• elle serait précédée d'une phase de rinçage "asynchrone" commençant au innodb_max_dirty_pages_pctniveau de remplissage - ce que je ne vois pas
• les LSN continuent d'augmenter même pendant le décrochage, donc l'activité des journaux ne cesse pas complètement
• Les INSERT de table MyISAM sont également affectés
• le thread page_cleaner pour le vidage adaptatif semble faire son travail et vider les journaux sans provoquer l'arrêt des requêtes DML:

^{(les chiffres proviennent ([Log Sequence Number] - [Pages flushed up to]) / 1024de SHOW ENGINE INNODB STATUS)}

Le problème semble quelque peu atténué par le réglage innodb_adaptive_flushing_lwm=1, forçant le nettoyeur de page à faire plus de travail qu'auparavant.

Le error.logn'a aucune entrée coïncidant avec les étals. SHOW INNODB STATUSdes extraits après environ 24 heures de fonctionnement ressemblent à ceci:

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

Donc, oui, la base de données a des blocages, mais ils sont très peu fréquents (le "dernier" a été traité environ 11 heures avant la lecture des statistiques).

J'ai essayé de suivre les valeurs de la section "SEMAPHORES" sur une période de temps, en particulier dans une situation de fonctionnement normal et pendant un décrochage (j'ai écrit un petit script vérifiant la liste de processus du serveur MySQL et exécutant quelques commandes de diagnostic dans une sortie de journal au cas où d'un décrochage évident). Comme les chiffres ont été pris sur différentes périodes, j'ai normalisé les résultats en événements / seconde:

                          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

Je ne suis pas sûr de ce que je vois ici. La plupart des chiffres ont chuté d'un ordre de grandeur - probablement en raison de l'arrêt des opérations de mise à jour, les "Mutex spin waits" et les "Mutex spin rounds" ont cependant tous deux augmenté d'un facteur 4.

En examinant cela plus avant, la liste des mutex ( SHOW ENGINE INNODB MUTEX) a environ 480 entrées de mutex répertoriées à la fois en fonctionnement normal et pendant un décrochage. J'ai permis innodb_status_output_locksde voir si cela allait me donner plus de détails.

Variables de configuration

(J'ai bricolé avec la plupart d'entre eux sans succès définitif):

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

Les choses ont déjà essayé

• désactivation du cache de requête par SET GLOBAL query_cache_size=0
• augmentant innodb_log_buffer_sizeà 128M
• jouer avec innodb_adaptive_flushing, innodb_max_dirty_pages_pctet les _lwmvaleurs respectives (elles ont été définies par défaut avant mes modifications)
• en augmentation innodb_io_capacity(2000) et innodb_io_capacity_max(4000)
• réglage innodb_flush_log_at_trx_commit = 2
• fonctionnant avec innodb_flush_method = O_DIRECT (oui, nous utilisons un SAN avec un cache d'écriture persistant)
• définition de / sys / block / sda / queue / scheduler sur noopoudeadline

Nous avons vu le même problème sur deux serveurs sur les versions 5.6.12 et 5.6.16 fonctionnant sous Windows, avec une paire d'esclaves chacun. Nous avons été perplexes, comme vous, pendant près de deux mois.

Solution :

set global binlog_order_commits = 0;

Voir https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_binlog_order_commits pour plus de détails sur la variable.

Explication :

InnoDB en texte intégral utilise un cache (par défaut de 8 Mo) contenant les modifications qui doivent être appliquées à l'index de texte intégral réel sur le disque.

Une fois le cache rempli, quelques transactions sont créées pour effectuer le travail de fusion des données qui étaient contenues dans le cache - cela a tendance à être une grande quantité d'E / S aléatoires, donc à moins que votre index de texte intégral ne puisse être chargé dans le pool de tampons, c'est une transaction longue et lente.

Lorsque binlog_order_commits est défini sur true, toutes les transactions contenant des insertions et des mises à jour, démarrées après la transaction fts_sync_index de longue durée, doivent attendre sa fin avant de pouvoir se valider.

Ce n'est un problème que si la journalisation binaire est activée

Permettez-moi peut-être d'essayer de décrire le problème historique de la purge des journaux et comment fonctionne la purge adaptative:

• Les journaux de rétablissement sont une conception de tampon en anneau . Ils ne sont écrits que sur (jamais lus en fonctionnement normal) et fournissent une récupération après incident. J'aime décrire un tampon annulaire comme semblable à la bande de roulement d'un réservoir.

• InnoDB ne pourra pas écraser l'espace du fichier journal s'il contient des modifications qui n'ont pas encore été modifiées sur le disque. Donc, historiquement, ce qui se passerait, c'est qu'InnoDB tenterait une certaine quantité de travail par seconde (configuré par innodb_io_capacity) et si cela ne suffisait pas, vous atteindriez l'espace de journal complet. Un décrochage se produirait car un rinçage synchrone devait se produire pour libérer soudainement de l'espace, faisant de ce qui est généralement une tâche d'arrière-plan soudainement au premier plan.

• Pour résoudre ce problème, un rinçage adaptatif a été introduit. Alors qu'à 10% (par défaut) de l' espace journal consommé, le travail en arrière-plan commence à devenir progressivement plus agressif. Le but de ceci est plutôt qu'un décrochage soudain, vous avez plutôt un «bref creux» dans les performances.

• Indépendamment de rinçage adaptatif, il est important d'avoir un espace de journal suffisant pour votre charge de travail ( innodb_log_file_sizevaleurs de 4G sont maintenant tout à fait sûr), et assurez - vous que innodb_io_capacityet innodb_lru_scan_depthsont fixés à des valeurs réalistes. Le rinçage adaptatif à 10% innodb_adaptive_flushing_lwmest quelque chose dans lequel vous ne vous étirez pas très loin, c'est plus un mécanisme de défense contre l'espace.

Juste pour apporter un peu de soulagement à InnoDB, vous pouvez jouer avec innodb_purge_threads.

Avant MySQL 5.6, le thread principal faisait tout le vidage de page. Dans MySQL 5.6, un thread séparé peut le gérer. La valeur par défaut de innodb_purge_threadsMySQL 5.5 était 0 avec un maximum de 1. Dans MySQL 5.6, la valeur par défaut est 1 avec un maximum de 32.

Que fait innodb_purge_threadsréellement le réglage ?

Les valeurs non nulles exécutent l'opération de purge dans un ou plusieurs threads d'arrière-plan, ce qui peut réduire les conflits internes dans InnoDB, améliorant ainsi l'évolutivité. Augmenter la valeur à plus de 1 crée autant de threads de purge distincts, ce qui peut améliorer l'efficacité sur les systèmes où les opérations DML sont effectuées sur plusieurs tables.

Je commencerais par définir innodb_purge_threads à 4 et voir si le vidage de page InnoDB est réduit.

MISE À JOUR 2014-09-02 12:33 EDT

Morgan Tocker a souligné dans le commentaire ci-dessous que le nettoyeur de page est la victime et MySQL 5.7 peut y remédier . Néanmoins, votre situation est dans MySQL 5.6.

J'ai jeté un deuxième coup d'œil et j'ai remarqué que vous avez innodb_max_dirty_pages_pct à 50.

La valeur par défaut pour innodb_max_dirty_pages_pct dans MySQL 5.5+ est 75. L'abaisser augmenterait l'incidence des blocages dus au rinçage. Je ferais trois (3) choses

• Augmentez innodb_max_dirty_pages_pct à 90 (c'était la valeur par défaut pour MySQL 5.1)
• Définissez innodb_max_dirty_pages_pct_lwm = 0 (par défaut) ou supprimez-le demy.cnf
• Augmentez innodb_log_buffer_size à 128M (la moitié de votre innodb_log_file_size )

MISE À JOUR 2014-09-03 11:06 EDT

Vous devrez peut-être modifier votre comportement de rinçage

Essayez de définir les éléments suivants dynamiquement

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

Ces variables, flush et flush_time , rendront le vidage plus agressif en fermant les descripteurs de fichiers ouverts sur les tables toutes les 10 secondes. MyISAM peut certainement en bénéficier car il ne met pas en cache les données. Toutes les écritures dans les tables MyISAM nécessitent des verrous de table complets, suivis d'écritures atomiques, et dépendent du système d'exploitation pour les modifications de disque.

Flushing InnoDB de cette façon nécessiterait un redémarrage mysql. Les options à voir sont innodb_flush_log_at_trx_commit et innodb_flush_method .

Avant de redémarrer, veuillez les ajouter

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

Avant de suivre cette route, vous devez vérifier si la journalisation est un problème. J'ai vu ce cool article mysqlperformanceblog sur O_DIRECT truqué à cause du noyau. Le même article mentionne également que MyISAM est affecté.

J'ai déjà écrit à propos de cet article: ib_logfile s'est ouvert avec O_SYNC lorsque innodb_flush_method = O_DSYNC

Essaie !!!