那些遇到过的问题

MySQL 实例停止“执行 SYNC 索引”

syn*_*-dj 12 mysql innodb myisam mysql-5.6

问题

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');
Run Code Online (Sandbox Code Playgroud)

并且设备统计数据显示增加，尽管在此时间范围内没有过多的 I/O 负载（在这种情况下，根据上述语句中的时间戳，更新在 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
Run Code Online (Sandbox Code Playgroud)

通常情况下，我在 mysql 慢日志中注意到最旧的查询停止是插入到一个大型（~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
Run Code Online (Sandbox Code Playgroud)

进一步的调查（即 SHOW ENGINE INNODB STATUS）表明，它确实总是使用全文索引更新导致停顿的表。“SHOW ENGINE INNODB STATUS”的相应 TRANSACTIONS 部分对于最旧的运行事务有如下两个条目：

---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
Run Code Online (Sandbox Code Playgroud)

所以有一些繁重的全文索引操作在那里进行（doing SYNC index）停止对任何表的所有后续更新。

从日志看来，undo log entriesfor的数字似乎doing SYNC index以 ~150/s 的速度前进，直到达到 20,000，此时操作完成。

这个特定表的 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
Run Code Online (Sandbox Code Playgroud)

尽管这个问题也是由像这样的 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
Run Code Online (Sandbox Code Playgroud)

这些情况下的失速时间也大致相同。我在 bugs.mysql.com 上打开了一个 bug，所以开发人员可以调查这个。

停顿的性质首先让我怀疑日志刷新活动是罪魁祸首，这篇关于 MySQL 5.5 日志刷新性能问题的 Percona 文章描述了非常相似的症状，但进一步的事件表明 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
Run Code Online (Sandbox Code Playgroud)

并且在 14:19:11 传播已经达到最低点，所以这里的冲洗活动似乎已经停止，正好与摊位的结束相吻合。但是这些点让我忽略了 InnoDB 日志刷新的原因：

  • 对于阻止对数据库的所有更新的刷新操作，它需要是“同步的”，这意味着必须占用 7/8 的日志空间
  • 它将在innodb_max_dirty_pages_pct填充水平开始的“异步”冲洗阶段之前- 我没有看到
  • 即使在停顿期间，LSN 也会不断增加，因此日志活动并没有完全停止
  • MyISAM 表 INSERT 也受到影响
  • 用于自适应刷新的 page_cleaner 线程似乎在完成其工作并刷新日志而不会导致 DML 查询停止：

LSN - 页面刷新

（数字([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
Run Code Online (Sandbox Code Playgroud)

所以，是的，数据库确实有死锁，但它们非常罕见（“最新”已在读取统计信息前 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
Run Code Online (Sandbox Code Playgroud)

我不太确定我在这里看到了什么。大多数数字下降了一个数量级 - 可能是由于更新操作停止，“Mutex spin waits”和“Mutex spin rounds”然而都增加了 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  |
+-----------------------+-------+
Run Code Online (Sandbox Code Playgroud)

已经尝试过的东西

  • 禁用查询缓存 SET GLOBAL query_cache_size=0
  • 增加到innodb_log_buffer_size128M
  • 玩弄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

小智 6

我们在 Windows 上运行的 5.6.12 和 5.6.16 版本的两台服务器上看到了同样的问题，每台服务器都有一对从服务器。我们和你一样被难住了将近两个月。

解决方案：

set global binlog_order_commits = 0;
Run Code Online (Sandbox Code Playgroud)

有关变量的详细信息，请参阅 https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_binlog_order_commits。

说明：

InnoDB 全文使用缓存（默认大小为 8M），其中包含需要应用于磁盘上实际全文索引的更改。

一旦缓存填满，就会创建几个事务来执行合并缓存中包含的数据的工作——这往往是大量的随机 IO，因此除非您的整个全文索引可以加载到缓冲池，这是一个漫长而缓慢的事务。

将 binlog_order_commits 设置为 true，所有包含插入和更新的事务，在长时间运行的 fts_sync_index 事务之后启动，必须​​等到它完成才能提交。

如果启用了二进制日志，这只是一个问题

归档时间：

查看次数：

3713 次

最近记录：

10 年，1 月 前
为什么 MySQL 要做串行同步 I/O？ 8
更多相关链接
相关归档
如何解决在 vps 上运行的 mysql 中的连接过多和致命错误 9
为 MyISAM 表设置复制？ 8
从 mysql 复制失败中恢复的最佳方法是什么？ 8
MySQL：大数字的字段类型是什么？ 5
列无法从“int”类型转换为“bigint(20) unsigned”类型？ 5
管理用户数据的正确方法是什么？ 3
如何设置唯一的列组合 2
恢复 MySQL 根密码 (XAMPP) 2
如何解决innodb集群冲突 2
将数据插入多个表 0
难疑归档
.bak 文件在 SSMS 的任何目录中都不可见 57
为什么主键/外键匹配不用于连接？ 52
MySQL 中的 ORDER BY FIELD() 如何在内部工作 52
如何仅在 psql (postgresql) 中关闭标头 36
如何 mysqldump 除 mysql 模式之外的所有数据库？ 25
正确使用查找表 25
消除会降低性能的键查找（集群）运算符 24
我可以在使用时在 MySQL 数据库中的表上创建索引吗 23
OPTIMIZE_FOR_SEQUENTIAL_KEY 的实施和禁忌症 23
SQL Server 2014 Express 中的 SQLCMD.EXE 在哪里？ 23