主页 / dba / 问题 / 75439
Accepted
syneticon-dj
Asked: 2014-09-02 06:53:51 +0800 CST

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

  • 772

问题

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

并且设备统计数据显示增加，尽管在此时间范围内没有过多的 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

通常情况下，我在 mysql 慢日志中注意到最旧的查询停止是插入到具有 VARCHAR 主键和全文搜索索引的大型（约 10 M 行）表中：

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）表明，它确实总是使用全文索引对表进行更新，这导致了停顿。“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

因此，那里正在进行一些繁重的全文索引操作（doing SYNC index）停止对ANY表的所有 SUBSEQUENT更新。

undo log entries从日志来看， for 的数字似乎有点像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

尽管这个问题也是由 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 上打开了一个错误，以便开发人员可以对此进行调查。

停顿的性质首先让我怀疑日志刷新活动是罪魁祸首，这篇关于 MySQL 5.5 的日志刷新性能问题的 Percona 文章描述了非常相似的症状，但进一步的事件表明 INSERT 操作到该数据库中的单个 MyISAM 表中也受到停顿的影响，所以这似乎不是一个仅限 InnoDB 的问题。

尽管如此，我还是决定每 10 秒跟踪一次“LOG”部分输出的Log sequence number值 Pages flushed up to。由于两个值之间的差值在减小，因此在停顿期间确实看起来冲洗活动正在进行：SHOW ENGINE INNODB STATUS

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 表 INSERT 也会受到影响
  • 用于自适应刷新的 page_cleaner 线程似乎在完成其工作并刷新日志而不会导致 DML 查询停止：

LSN - PagesFlushed

（数字([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

我不太确定我在这里看到了什么。大多数数字下降了一个数量级 - 可能是由于更新操作停止，“互斥旋转等待”和“互斥旋转轮数”都增加了 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_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
mysql innodb

3 个回答

  1. Best Answer

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

    解决方案：

    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 全文使用缓存（默认大小为 8M），其中包含需要应用于磁盘上实际全文索引的更改。

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

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

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

    • 6

  2. 让我试着描述一下日志刷新的历史问题以及自适应刷新的工作原理：

    • 重做日志是环形缓冲区设计。它们只被写入（在正常操作中从不读取）并提供崩溃恢复。我喜欢将环形缓冲器描述为类似于坦克的胎面。

    • 如果 InnoDB 包含尚未在磁盘上修改的更改，它将无法覆盖日志文件空间。因此，从历史上看，InnoDB 每秒会尝试一定数量的工作（由 配置innodb_io_capacity），如果这还不够，您将达到完整的日志空间。由于需要同步刷新以突然释放空间，因此会发生停顿，从而使通常是后台任务的任务突然成为前台。

    • 为了解决这个问题，引入了自适应冲洗。在消耗10%（默认）日志空间的情况下，后台工作开始变得越来越激进。这样做的目的不是突然停止，而是让您的性能出现更多“短暂下降”。

    • 独立于自适应刷新，重要的是为您的工作负载提供足够的日志空间（ 4G 的值现在非常安全），并innodb_log_file_size确保将其设置为实际值。自适应冲洗 10%是你不会延伸到很远的东西，它更像是一种针对空间不足的防御机制。innodb_io_capacityinnodb_lru_scan_depthinnodb_adaptive_flushing_lwm

    • 4

  3. 只是为了给 InnoDB 带来一些争用缓解，您可以使用innodb_purge_threads.

    在 MySQL 5.6 之前，主线程完成了所有的页面刷新。在 MySQL 5.6 中，一个单独的线程可以处理它。MySQL 5.5 中的默认值为innodb_purge_threads0，最大值为 1。在 MySQL 5.6 中，默认值为 1，最大值为 32。

    设置innodb_purge_threads实际上是做什么的？

    非零值在一个或多个后台线程中运行清除操作，这可以减少 InnoDB 内部的争用，提高可伸缩性。将该值增加到大于 1 会创建许多单独的清除线程，这可以提高对多个表执行 DML 操作的系统的效率。

    我将从将innodb_purge_threads设置为 4 开始，看看是否减少了 InnoDB 页面刷新。

    更新 2014-09-02 12:33 EDT

    Morgan Tocker 在下面的评论中指出页面清理器是受害者，而 MySQL 5.7 可以解决它。尽管如此，您的情况是在 MySQL 5.6 中。

    我再看一眼，发现你的innodb_max_dirty_pages_pct为 50。

    MySQL 5.5+ 中innodb_max_dirty_pages_pct的默认值为 75。降低它会增加刷新停滞的发生率。我会做三（3）件事

    更新 2014-09-03 11:06 EDT

    你可能需要改变你的冲水行为

    尝试动态设置以下

    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

    在走这条路之前，您应该检查日记是否是一个问题。我看到这篇关于 O_DIRECT 的酷 mysqlperformanceblog 帖子因为内核而被伪造。同一篇文章还提到 MyISAM 受到影响。

    我之前写过这篇文章：ib_logfile opens with O_SYNC when innodb_flush_method=O_DSYNC

    试试看 ！！！

    • 2

相关问题