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 這個參數 慎用，用的好了你就是大神，用不好了就跟我一樣背鍋