binlog_group_commit_sync_delay 参数对并发的影响

一、现象

某天，开发人员找到了我，说是某条 UPDATE 语句执行需要 零点几秒，这个速度他们不能接受。不管怎样，首先看一下 SQL 是怎样的：

update t set name='a' where id = 1 

数据量 100万，id 是 主键

二、问题排查

2.1 首先排除下执行计划问题

理论上来说走的是主键扫描。那么，首先怀疑一下是不是执行计划出错，走了全表扫。虽然可能性很低，但还是先排除掉这个原因

explain update t set name = 'a' where id = 1
+----+-------------+------------+------------+-------+---------------+---------+---------+-------+------+----------+-------------+
| id | select_type | table      | partitions | type  | possible_keys | key     | key_len | ref   | rows | filtered | Extra       |
+----+-------------+------------+------------+-------+---------------+---------+---------+-------+------+----------+-------------+
|  1 | UPDATE      | t          | NULL       | range | PRIMARY       | PRIMARY | 8       | const |    1 |   100.00 | Using where |
+----+-------------+------------+------------+-------+---------------+---------+---------+-------+------+----------+-------------+

执行计划看来并没有问题。就算索引高度为4，最多也就是4次IO，这对于SSD磁盘 是完成没有压力的，所以，磁盘是否有问题

2.2 排除下磁盘问题

%util 并不高，甚至 50% 都没有达到。暂时先排除磁盘的原因。所以，问题还是回到数据库层，看一下update一条语句，是在哪个环节慢了

2.3 show profiles 看一下各个环节消耗的情况

--打开profiling

set profiling = 1

--执行SQL

update t set name where id = 1

--查看Profiles

SELECT STATE,
       SUM(DURATION) as total_R,
       ROUND(100 * SUM(DURATION) /
             (SELECT SUM(DURATION)
                FROM INFORMATION_SCHEMA.PROFILING
               WHERE QUERY_ID = 1),
             2) as pct_r,
       count(*) as calls,
       sum(DURATION) / count(*) as "R/Call"
  FROM INFORMATION_SCHEMA.PROFILING
 WHERE QUERY_ID = 1
 GROUP BY STATE
 ORDER BY Total_R DESC;

+--------------------------------+----------+----------+-------+--------------+
| STATE                          | total_R  | pct_r    | calls | R/Call       |
+--------------------------------+----------+----------+-------+--------------+
| query end                      | 1.003655 | 35641.16 |     2 | 0.5018275000 |
| updating                       | 0.001037 |    36.83 |     1 | 0.0010370000 |
| starting                       | 0.000100 |     3.55 |     1 | 0.0001000000 |
| freeing items                  | 0.000084 |     2.98 |     1 | 0.0000840000 |
| Opening tables                 | 0.000078 |     2.77 |     1 | 0.0000780000 |
| System lock                    | 0.000068 |     2.41 |     1 | 0.0000680000 |
| init                           | 0.000042 |     1.49 |     1 | 0.0000420000 |
| Waiting for semi-sync ACK from | 0.000042 |     1.49 |     1 | 0.0000420000 |
| end                            | 0.000041 |     1.46 |     1 | 0.0000410000 |
| cleaning up                    | 0.000035 |     1.24 |     1 | 0.0000350000 |
| closing tables                 | 0.000027 |     0.96 |     1 | 0.0000270000 |
| checking permissions           | 0.000020 |     0.71 |     1 | 0.0000200000 |
+--------------------------------+----------+----------+-------+--------------+

可以看到主要消耗在 query end 上面。

query end是什么状态？ Google 查询了下面这篇博客

http://inetkiller.github.io/2014/05/20/mysql%E8%AF%AD%E5%8F%A5%E6%80%A7%E8%83%BD%E5%88%86%E6%9E%90%E4%B8%8E%E4%BC%98%E5%8C%96/

 里面提到了，他修改了 innodb_flush_log_at_trx_commit = 0 解决了性能问题。但是我并没有去改 innodb_flush_log_at_trx_commit。 因为这篇博客给了我一个启发，从日志上面入手

2.4 怀疑 binlog_group_commit_sync_delay 设置的问题

因为要提高slave的复制性能，我把这个参数 binlog_group_commit_sync_delay 调整到了 1s，跟 update 的执行时间很接近。

binlog_group_commit_sync_delay 参数解释：等待多少时间后才进行组提交

带着疑问我把 binlog_group_commit_sync_delay 设置为 0，再次执行 

update t set name='a' where id = 1

这一次很快，0.03秒 执行完成。问题似乎已经找到了，但我为了更加确认，我在测试库上执行了又复现了一遍。

三、解决办法

问题分析到这里，很明显就是 binlog_group_commit_sync_delay 参数设置的太大的问题，所以把 binlog_group_commit_sync_delay 设置为 0，就解决了。似乎写到这里就应该结束了，呵呵。天真，还没完呢，请看后续

四、binlog_group_commit_sync_delay 带来的其他副作用

开发在这之前告诉我，说最近的 锁 比较频繁。让我帮忙看一下数据库的问题。我上去数据库查了下，发现基本上都是 RECORD LOCK。被阻塞 SQL 也是下面那条语句

update t set name='a' where id = 1

只是 ID 不一样而已。那么，在生产上我是不敢拿 update 再来执行一遍的，所以我改成了 SELECT * FROM t where id =1，嗯，结果很快，0.01 秒就出来了。然后就可以跟开发说，我这SQL执行很快啊，数据库没有问题的。

看到这里是不是发现了什么？

没错，binlog_group_commit_sync_delay 会影响你的 commit 时间，所以，其他 修改同一行的数据也会 被阻塞。具体看以下实验

会话1：

update t set name = 'aaa' where id = 1;
Query OK, 1 row affected (1.01 sec)

会话2：

update t set name = 'aa' where id = 1;
Query OK, 1 row affected (1.65 sec)

会话3：

---TRANSACTION 2396, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 17, OS thread handle 139756413503232, query id 232 localhost root updating
update t set name = 'aa' where id = 1
------- TRX HAS BEEN WAITING 0 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 27 page no 3 n bits 88 index PRIMARY of table `vcyber`.`t` trx id 2396 lock_mode X locks rec but not gap waiting
Record lock, heap no 18 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 00000000095b; asc      [;;
 2: len 7; hex 3b0000002a0447; asc ;   * G;;
 3: len 1; hex 61; asc a;;

看到没有，RECORD LOCK。

binlog_group_commit_sync_delay 对并发的影响就是这么大。各位客官，奉劝一句：binlog_group_commit_sync_delay 这个参数 慎用，用的好了你就是大神，用不好了就跟我一样背锅