проблема

Экземпляр MySQL 5.6.20, на котором запущена (в основном только) база данных с таблицами InnoDB, время от времени останавливается для всех операций обновления в течение 1-4 минут, когда все запросы INSERT, UPDATE и DELETE остаются в состоянии «конец запроса». Это, очевидно, самое неудачное. Журнал медленных запросов MySQL регистрирует даже самые тривиальные запросы с безумными временами запросов, сотни из них с одной и той же отметкой времени, соответствующей моменту времени, когда остановка была разрешена:

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

И статистика устройства показывает увеличенную, хотя и не чрезмерную нагрузку ввода-вывода в этот период времени (в этом случае обновления зависали 14:17:30 - 14:19:12 в соответствии с отметками времени из приведенного выше утверждения):

# 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

Чаще всего в медленном журнале mysql я замечаю, что самым старым запросом на остановку является INSERT в таблицу с большим числом строк (~ 10 M строк) с первичным ключом VARCHAR и индексом полнотекстового поиска:

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

Дальнейшие исследования (то есть SHOW ENGINE INNODB STATUS) показали, что это действительно всегда обновление таблицы с использованием полнотекстовых индексов, вызывающее остановку. Соответствующий раздел TRANSACTIONS «SHOW ENGINE INNODB STATUS» содержит записи, подобные этим двум для самых старых запущенных транзакций:

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

Таким образом, там происходит некоторое тяжелое действие полнотекстового индекса ( doing SYNC index), которое останавливает ВСЕ ПОСЛЕДУЮЩИЕ обновления для ЛЮБОЙ таблицы.

Из журналов это похоже на то, что undo log entriesчисло doing SYNC indexувеличивается с ~ 150 / с, пока не достигнет 20000, после чего операция будет завершена.

Размер FTS этой конкретной таблицы весьма впечатляет:

# 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

хотя проблема также вызвана таблицами со значительно меньшим размером данных FTS, как эта:

# 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

Время остановки в этих случаях тоже примерно одинаковое. Я открыл ошибку на bugs.mysql.com, чтобы разработчики могли разобраться с этим.

Природа остановок сначала заставила меня заподозрить, что причиной сброса журнала является виновник, и в этой статье Percona о проблемах производительности очистки журнала с MySQL 5.5 описываются очень похожие симптомы, но дальнейшие случаи показали, что операции INSERT в одной таблице MyISAM в этой базе данных Стойл также влияет, так что это не похоже на проблему, связанную только с InnoDB.

Тем не менее, я решил отслеживать значения Log sequence numberи Pages flushed up toиз выходных данных раздела «LOG»SHOW ENGINE INNODB STATUS каждые 10 секунд. Это действительно похоже на то, что во время остановки происходит промывка, так как разброс между двумя значениями уменьшается:

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

И в 14:19:11 спред достиг своего минимума, поэтому промывочная активность здесь, похоже, прекратилась, просто совпадая с окончанием стойла. Но эти пункты заставили меня отклонить сброс журнала InnoDB как причину:

• чтобы операция сброса блокировала все обновления базы данных, она должна быть «синхронной», что означает, что 7/8 пространства журнала должно быть занято
• ему должна предшествовать «асинхронная» фаза промывки, начинающаяся на innodb_max_dirty_pages_pctуровне заполнения - чего я не вижу
• номера LSN продолжают расти даже во время остановки, поэтому активность журналов не прекращается полностью
• Влияния таблиц MyISAM также затронуты
• поток page_cleaner для адаптивной очистки, похоже, выполняет свою работу и очищает журналы, не останавливая запросы DML:

^{(номера ([Log Sequence Number] - [Pages flushed up to]) / 1024от SHOW ENGINE INNODB STATUS)}

Эта проблема, кажется, несколько облегчена установкой innodb_adaptive_flushing_lwm=1, заставляющей очиститель страниц выполнять больше работы, чем раньше.

Не error.logимеет записей, совпадающих с киосками. SHOW INNODB STATUSвыдержки примерно после 24 часов работы выглядят так:

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

Итак, да, база данных имеет взаимоблокировки, но они встречаются очень редко («последние» обрабатывались примерно за 11 часов до считывания статистики).

Я пытался отслеживать значения раздела «SEMAPHORES» в течение определенного периода времени, особенно в ситуации нормальной работы и во время остановки (я написал небольшой скрипт, проверяющий список процессов сервера MySQL и запускающий пару диагностических команд в вывод журнала в случае очевидного ларька). Поскольку числа были взяты за разные периоды времени, я нормализовал результаты к событиям / секундам:

                          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

Я не совсем уверен в том, что я вижу здесь. Большинство чисел упали на порядок - вероятно, из-за прекращения операций обновления, «ожидания вращения Mutex» и «раунды вращения Mutex», однако, увеличились в 4 раза.

Для дальнейшего изучения списка мьютексов ( SHOW ENGINE INNODB MUTEX) имеется ~ 480 записей мьютексов, перечисленных как при нормальной работе, так и во время остановки. Я включил, innodb_status_output_locksчтобы видеть, собирается ли это дать мне больше деталей.

Переменные конфигурации

(Я возился с большинством из них без определенного успеха):

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

Вещи уже пробовали

• отключение кеша запросов SET GLOBAL query_cache_size=0
• увеличивается innodb_log_buffer_sizeдо 128M
• играя с innodb_adaptive_flushing, innodb_max_dirty_pages_pctи соответствующими _lwmзначениями (они были установлены по умолчанию до моих изменений)
• увеличение innodb_io_capacity(2000) и innodb_io_capacity_max(4000)
• установка innodb_flush_log_at_trx_commit = 2
• работает с innodb_flush_method = O_DIRECT (да, мы используем SAN с постоянным кэшем записи)
• установка / sys / block / sda / queue / scheduler в noopилиdeadline

Мы видели ту же проблему на двух серверах в версиях 5.6.12 и 5.6.16, работающих под Windows, с парой ведомых устройств на каждом. Как и вы, мы были в тупике почти два месяца.

Решение :

set global binlog_order_commits = 0;

См. Https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_binlog_order_commits для получения подробной информации о переменной.

Пояснение :

В полнотекстовом InnoDB используется кэш (по умолчанию размером 8 МБ), содержащий изменения, которые необходимо применить к фактическому полнотекстовому индексу на диске.

Как только кеш заполняется, создается пара транзакций для выполнения операции объединения данных, которые содержались в кеше - это, как правило, большое количество случайных операций ввода-вывода, поэтому, если весь ваш полнотекстовый индекс не может быть загружен в буферный пул, это длинная и медленная транзакция.

Если для binlog_order_commits задано значение true, все транзакции, содержащие вставки и обновления, запущенные после длительной транзакции fts_sync_index, должны ждать, пока она не будет завершена, прежде чем они смогут выполнить фиксацию.

Это проблема, только если двоичное ведение журнала включено

Позвольте мне, возможно, попытаться описать историческую проблему с очисткой журналов и как работает адаптивная очистка:

• Журналы повторов представляют собой кольцевой буфер . Они только когда-либо записываются (никогда не читаются при нормальной работе) и обеспечивают восстановление после сбоя. Мне нравится описывать кольцевой буфер как похожий на протектор танка.

• InnoDB не сможет перезаписать пространство файла журнала, если оно содержит изменения, которые еще не были изменены на диске. Исторически сложилось так, что InnoDB будет пытаться выполнить определенное количество работы в секунду (настроено innodb_io_capacity), и если этого будет недостаточно, вы достигнете полного пространства журнала. Задержка может произойти в виде синхронного сброса, необходимого для внезапного освобождения пространства, в результате чего то, что обычно является фоновой задачей, внезапно выходит на передний план.

• Для решения этой проблемы была введена адаптивная промывка. При том, что при 10% (по умолчанию) занимаемого пространства журнала, фоновая работа начинает становиться все более агрессивной. Целью этого является скорее не внезапный срыв, у вас больше «короткого падения» в производительности.

• Независимо от адаптивного сброса, важно иметь достаточно места для журналов для вашей рабочей нагрузки ( innodb_log_file_sizeзначения 4G теперь вполне безопасны), и убедитесь, что innodb_io_capacityи innodb_lru_scan_depthустановлены реалистичные значения. Адаптивная промывка на 10% innodb_adaptive_flushing_lwm- это то, во что вы не вникаете слишком далеко, это скорее механизм защиты от нехватки пространства.

Просто, чтобы принести InnoDB некоторое облегчение раздора, вы можете поиграть с ним innodb_purge_threads.

До MySQL 5.6 мастер-нить выполняла всю очистку страницы. В MySQL 5.6 это может обрабатывать отдельный поток. Значение по умолчанию для innodb_purge_threadsв MySQL 5.5 было 0 с максимумом 1. В MySQL 5.6 по умолчанию равно 1 с максимумом 32.

Что на innodb_purge_threadsсамом деле делает установка ?

Ненулевые значения запускают операцию очистки в одном или нескольких фоновых потоках, что может уменьшить внутреннюю конкуренцию в InnoDB, улучшая масштабируемость. Увеличение значения до значения больше 1 создает такое количество отдельных потоков очистки, что может повысить эффективность в системах, где операции DML выполняются с несколькими таблицами.

Я хотел бы начать с установки innodb_purge_threads в 4 и посмотреть, уменьшена ли очистка страницы InnoDB.

ОБНОВЛЕНИЕ 2014-09-02 12:33 ПО ВОСТОЧНОМУ ВРЕМЕНИ

Морган Токер указал в комментарии ниже, что очиститель страниц является жертвой, и MySQL 5.7 может решить эту проблему . Несмотря на это, ваша ситуация в MySQL 5.6.

Я взглянул еще раз и заметил, что у вас innodb_max_dirty_pages_pct на 50.

Значение по умолчанию для innodb_max_dirty_pages_pct в MySQL 5.5+ составляет 75. Снижение этого приведет к увеличению частоты остановок при сбросе . Я бы сделал три (3) вещи

• Увеличьте innodb_max_dirty_pages_pct до 90 (это было по умолчанию для MySQL 5.1)
• Установите innodb_max_dirty_pages_pct_lwm = 0 (по умолчанию) или удалите его изmy.cnf
• Увеличьте innodb_log_buffer_size до 128M (половина вашего innodb_log_file_size )

ОБНОВЛЕНИЕ 2014-09-03 11:06 ПО ВОСТОЧНОМУ ВРЕМЕНИ

Возможно, вам придется изменить свое поведение при промывке

Попробуйте установить следующее динамически

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

Эти переменные, flush и flush_time , сделают сброс более агрессивным, закрывая дескрипторы открытых файлов на таблицах каждые 10 секунд. MyISAM определенно может извлечь из этого выгоду, потому что он не кэширует данные. Все записи в таблицы MyISAM требуют полных блокировок таблиц с последующими атомарными записями и зависят от ОС для изменений диска.

Для очистки InnoDB таким образом потребуется перезапуск MySQL. Доступные варианты: innodb_flush_log_at_trx_commit и innodb_flush_method .

Перед перезапуском, пожалуйста, добавьте эти

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

Прежде чем идти по этому пути, вы должны проверить, не является ли журналирование проблемой. Я видел этот крутой пост в mysqlperformanceblog о том, что O_DIRECT подделан из-за ядра. В том же посте также упоминается, что MyISAM подвергается воздействию.

Я писал об этом посте раньше: ib_logfile открывался с O_SYNC, когда innodb_flush_method = O_DSYNC

Попробуйте!