故障分析 | MySQL : slave_compressed_protocol 導致 crash

愛可生雲資料庫發表於2021-12-28
MySqlProtocol

作者：胡呈清

愛可生 DBA 團隊成員，擅長故障分析、效能優化，個人部落格：https://www.jianshu.com/u/a95...，歡迎討論。

本文來源：原創投稿

*愛可生開源社群出品，原創內容未經授權不得隨意使用，轉載請聯絡小編並註明來源。

現象

MySQL版本：8.0.18

create.sql：zabbix 初始化指令碼，包含建表、插入資料語句，10M+大小

一個新客戶，部署了一套我司的資料庫管理平臺，接管進來一主兩從例項，其中一主一從在無錫機房，為半同步複製，另一個從庫在北京機房，為非同步複製。當在主庫上 source create.sql 時，會 crash。但沒接管進平臺前，不會出現 crash。

說明：這裡提到的管理平臺，不會影響理解整篇文章。

排查過程

1. 在測試環境進行復現

為方便排查，需要在可控的環境下進行復現：

  • 與客戶相同的 my.cnf
  • 相同的 MySQL 版本
  • 相同的複製架構
  • 執行相同的 create.sql

確實可以穩定復現 crash，error log 如下：

2020-04-28T17:51:47.441886+08:00 0 [ERROR] [MY-013129] [Server] A message intended for a client cannot be sent there as no client-session is attached. Therefore, we're sending the information to the error-log instead: MY-001158 - Got an error reading communication packets

09:51:47 UTC - mysqld got signal 11 ;

Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.

Thread pointer: 0x0

Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...

stack_bottom = 0 thread_stack 0x46000

2020-04-28T17:51:47.447907+08:00 218 [ERROR] [MY-011161] [Server] Semi-sync master failed on net_flush() before waiting for slave reply.

/opt/mysql/base/8.0.18/bin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x2e) [0x1ed6cce]
/opt/mysql/base/8.0.18/bin/mysqld(handle_fatal_signal+0x323) [0xfb2d23]
/lib64/libpthread.so.0(+0xf5f0) [0x7f3d781a75f0]

The manual page at http://dev.mysql.com/doc/mysq... contains
information that should help you find out what is causing the crash.

2. 排除管理平臺的影響

由於接管到管理平臺才會出現 crash，管理平臺對資料庫最大的操作來自於高可用元件：

  • 延遲檢測（寫操作：每 500ms 寫入一個時間戳）
  • 狀態查詢（讀操作）

所以接下來停用高可用、延遲檢測進行測試，結果如下：

初步結論：延遲檢測關閉後，不會 crash。

3. 延遲檢測影響了什麼，導致 crash？

在測試過程中，發現一個與 crash 伴生的現象：

  • 不停用延遲檢測，會crash，但是執行sql 的效率高一些（毫秒級）：
mysql> source /tmp/insert.sql
Query OK, 1 row affected (0.21 sec)
Query OK, 1 row affected (0.50 sec)
Query OK, 1 row affected (0.03 sec)
Query OK, 1 row affected (0.47 sec)
Query OK, 1 row affected (0.51 sec)
Query OK, 1 row affected (0.02 sec)
  • 而停用高可用檢測，不會crash，每個 sql 執行時間都是 1s 多一點：
mysql> source /tmp/insert.sql                            
Query OK, 1 row affected (0.01 sec)
Query OK, 1 row affected (1.01 sec)
Query OK, 1 row affected (1.01 sec)
Query OK, 1 row affected (1.00 sec)
Query OK, 1 row affected (1.01 sec)
Query OK, 1 row affected (1.01 sec)

這個看起來很像是組提交機制導致的，但是並沒有配置組提交引數：

mysql> show global variables like '%group_commit%';
+-----------------------------------------+-------+
| Variable_name                           | Value |
+-----------------------------------------+-------+
| binlog_group_commit_sync_delay          | 0     |
| binlog_group_commit_sync_no_delay_count | 0     |
+-----------------------------------------+-------+
2 rows in set (0.01 sec)

關閉半同步複製後，此現象也會消失。猜測：是半同步和組提交結合在一起觸發的問題。

4. longblob 大物件

在前面的測試中，每次復現 crash，解析 binlog 檢視最後一個事務都有一個共性：都是對同一張表插入資料：

### INSERT INTO `zabbix`.`images`
### SET
###   @1=108 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=1 /* INT meta=0 nullable=0 is_null=0 */
###   @3='Rackmountable_3U_server_3D_(64)' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @4=

檢視錶結構，發現有 lonngblob 大物件，插入的是圖片，用的是二進位制格式儲存：

CREATE TABLE `images` (
  `imageid` bigint(20) unsigned NOT NULL,
  `imagetype` int(11) NOT NULL DEFAULT '0',
  `name` varchar(64) NOT NULL DEFAULT '0',
  `image` longblob NOT NULL,
  PRIMARY KEY (`imageid`),
  UNIQUE KEY `images_1` (`name`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci;

擷取出 create.sql 中的 images 表的所有 insert 語句，接下來只執行這些 insert 語句，也能復現 crash 的問題：

sed -n '2031,2217p' create.sql > insert.sql

所以 crash 的第2個條件是：插入 longblob 大物件

5. slave_compressed_protocol

前面的分析已經找到 2 個觸發 crash 的條件：

  • 插入資料時，存在 longblob 大物件
  • 半同步複製，並且在 insert longblob 大物件時伴隨有其他外部寫入流量

但是實際上用資料庫管理平臺自帶的標準安裝的同樣版本的 MySQL 環境，並不能復現 crash 問題。區別在於 my.cnf 不同，所以一定還有某個引數作為觸發條件。

經過不斷的測試，每次修改一批引數（注意前面已經定位到跟半同步複製有關，所以一定要同時修改主、從庫的引數），不斷縮小範圍，最終定位到是從庫設定 slave_compressed_protocol=on 的影響。

從庫 slave_compressed_protocol=ON 時，還會導致從庫 slave io thread 一直斷開與主庫的連線，並不斷重連，從庫 error log 報錯如下：

2020-04-29T10:34:42.361584+08:00 1998 [ERROR] [MY-010557] [Repl] Error reading packet from server for channel '': Lost connection to MySQL server during query (server_errno=2013)

2020-04-29T10:34:42.361668+08:00 1998 [Warning] [MY-010897] [Repl] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.

主庫 error log 報如下錯：

2020-04-29T10:23:29.480529+08:00 0 [ERROR] [MY-013129] [Server] A message intended for a client cannot be sent there as no client-session is attached. Therefore, we're sending the information to the error-log instead: MY-001158 - Got an error reading communication packets

2020-04-29T10:23:30.330242+08:00 1950 [ERROR] [MY-011161] [Server] Semi-sync master failed on net_flush() before waiting for slave reply.

相應的，因為從庫 slave io 執行緒不斷重連，可以觀察到主庫的 binlog dump 執行緒會不斷重啟，有時還可以觀察到 2 個：

show processlist;select sleep (1);show processlist;
....
| 2131 | admin | 172.16.21.3:37926 | NULL | Binlog Dump GTID | 3 | Waiting to finalize termination | NULL |
| 2132 | admin | 172.16.21.3:37932 | NULL | Binlog Dump GTID | 1 | Sending binlog event to slave | NULL |
....
+-----------+
| sleep (1) |
+-----------+
| 0         |
+-----------+
...
| 2132 | admin | 172.16.21.3:37932 | NULL | Binlog Dump GTID | 2 | Sending binlog event to slave | NULL |
...

與之相關的bug：
https://jira.percona.com/brow...
https://bugs.mysql.com/bug.ph...

結論

此次 crash 的觸發條件有3個：

  1. 插入 longblob 大物件；
  2. 半同步複製，並且在 insert longblob 大物件時伴隨有其他外部寫流量；
  3. slave_compressed_protocol=on .

為什麼接管到平臺之前沒有發生過 crash？

因為這個庫還沒上線，在執行 create.sql 時沒有其他寫入流量（等同於關閉延遲檢測的效果）。

解決方案

set slave_compressed_protocol=OFF 即可，另外官方文件也說明不要配置此引數，後續版本將會刪除此引數：

As of MySQL 8.0.18, this system variable is deprecated. It will be removed in a future MySQL version.

後續

我司研發大神後面向官方提交了一個bug：https://bugs.mysql.com/bug.ph...。

因為一些安全問題（更具體就不能透露了），這個bug 被官方設定成了私密 bug，截圖如下，不過截止到今天（2021.12.28）官方還是沒有修復：

相關文章