故障分析 | 血的教訓-由慢查詢引發的備份等待導致資料庫連線打滿

作者：馬文斌

MySQL愛好者,任職於藍月亮(中國)有限公司。

本文來源：原創投稿

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

背景

早上一大早被拉去開早會，感覺事情不妙，得知是某中臺(發券)資料庫 不能正常提供訪問。出現大量的下面情況 ：

| 55279262 | xxx_app | 192.168.50.143:44623 | xxx_mam | Query | 206 | Waiting for table flush | SELECT count(*) FROM mam_user_coupon_package AS a LEFT JOIN mam_coupon_apply_scope as d on a.coupon_info_id = d.coupon_info_id WHERE 1=1 AND a.usable_flag = 1 AND a.user_id = 102101100050614656 and a.coupon_status in (1) and d.business_code = 30006 AND a.end_time >= '2022-04-25 08:56:49.683'
                                                                                                                  |
| 55278572 | xxx_app | 192.168.50.144:40013 | xxx_mam | Query | 315 | Waiting for table flush | SELECT coupon_user_code,last_update_time,operator_name,operator_id,create_time,creator_name,creator_id,del_flag,user_id,coupon_status,coupon_info_id,start_time,end_time,use_time,activate_time,activate_end_time,coupon_type,coupon_info_type,act_id,usable_flag FROM mam_user_coupon_package WHERE ( ( end_time <= '2022-04-25 08:55:00.638' and usable_flag = 1 and del_flag = 0 and coupon_status = 1 ) ) limit 0,1000

| 55165820 | root | localhost | NULL | Query | 28956 | Waiting for table flush | FLUSH NO_WRITE_TO_BINLOG TABLES |

字面意思是等待表重新整理，但是這只是個查詢，為啥要重新整理表呢，而且是幾百上千個全域性連線進來，一時半會找不到解決方案，只要先救火後分析，那就先把查詢幹掉再說

select concat('kill ', id , ';') from PROCESSLIST where USER='xxx_app' and STATE='Waiting for table flush' ;

後面發現不行啊，早上不斷有連線請求連線進來，這是指標不治本，沒辦法只能用重啟大法，重啟完之後資料庫終於又恢復了往日的靜寧了。

事後分析：

有SQL 與 備份操作衝突導致卡死出現。

220425 01:01:48 [01] Streaming ./xx_ums/ums_channal_authorized.ibd
220425 01:01:48 [01] ...done
220425 01:01:48 >> log scanned up to (425114657787)
220425 01:01:48 Executing FLUSH NO_WRITE_TO_BINLOG TABLES...
220425 01:01:49 >> log scanned up to (425114657787)
……
220425 09:05:52 >> log scanned up to (425114692507)
Error: failed to execute query 'FLUSH NO_WRITE_TO_BINLOG TABLES': 2013 (HY000) Lost connection to MySQL server during query

這裡是部分備份時產生的日誌檔案，關鍵資訊就在這裡，flush table 操作的不記錄到 binlog 裡 ，避免從庫也執行同樣的操作。

於是帶著疑問，1、要麼有長事務沒有提交，2、要麼有大的慢查詢阻塞

備份原理:

備份流程圖大致如下：

1、根據連結資訊做資料庫的連通性和版本檢測
2、讀取資料庫相關的配置資訊（資料和日誌檔案位置等資訊）
3、開啟redo日誌拷貝執行緒，從最新的checkpoint開始順序拷貝redolog到xtrabackup_logfile中
4、開始備份 .ibd ibdata1 undo 等innodb檔案
5、執行FLUSH NO_WRITE_TO_BINLOG TABLES 和  FLUSH TABLES WITH READ LOCK
    1）關閉所有開啟的表，強制關閉所有正在使用的表,不寫入binlog
    2）關閉所有開啟的表，強制關閉所有正在使用的表，並給所有表增加全域性read lock
6、拷貝非innodb表相關檔案資訊
7、讀取binlog pos資訊並寫入xtrabackup_binlog_info檔案
8、執行 FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS
    1)重新整理redo log buffer中的日誌到磁碟檔案，確保redo log copy執行緒拷貝這最後的redolog日誌資料（為什麼說是最後的
    redolog日誌資料，因為在FLUSH TABLES WITH READ LOCK加鎖之後，使用UNLOCK TABLES釋放全域性讀鎖之前，不會再有新
    的請求進來）
    2）為什麼確保所有redo日誌拷貝完整（因為沒有拷貝binlog，如果最後一組提交的事物redo的commit標誌沒有落盤恢復時
    會丟失最後一組事物)
9、停止redolog日誌拷貝執行緒
10、執行UNLOCK TABLES釋放表鎖
11、收尾生成backup-my.cnf和xtrabackup_info等檔案，備份完成。

可以看到我們備份的時候是卡在這一步：

FLUSH NO_WRITE_TO_BINLOG TABLES

1）關閉所有開啟的表，強制關閉所有正在使用的表,不寫入binlog

ok，非常清晰，我們從2個方面入手，寫 | 讀

場景1:模擬未提交的寫事務是否阻塞備份

備份輸出的日誌：

220425 15:13:08 [01] Copying ./db1/db.opt to /data/backup//2022-04-25_15-12-25/db1/db.opt
220425 15:13:08 [01]        ...done
220425 15:13:08 [01] Copying ./db1/tb1.frm to /data/backup//2022-04-25_15-12-25/db1/tb1.frm
220425 15:13:08 [01]        ...done
220425 15:13:08 Finished backing up non-InnoDB tables and files
220425 15:13:08 [00] Writing xtrabackup_binlog_info
220425 15:13:08 [00]        ...done
220425 15:13:08 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
xtrabackup: The latest check point (for incremental): '2447317'
xtrabackup: Stopping log copying thread.
.220425 15:13:08 >> log scanned up to (2447326)

220425 15:13:08 Executing UNLOCK TABLES
220425 15:13:08 All tables unlocked
220425 15:13:08 [00] Copying ib_buffer_pool to /data/backup//2022-04-25_15-12-25/ib_buffer_pool
220425 15:13:08 [00]        ...done
220425 15:13:08 Backup created in directory '/data/backup//2022-04-25_15-12-25'
MySQL binlog position: filename 'mysql-bin.000003', position '1032', GTID of the last change '74fd0ba9-c45b-11ec-97a4-525400abe2c0:1-8'
220425 15:13:08 [00] Writing backup-my.cnf
220425 15:13:08 [00]        ...done
220425 15:13:08 [00] Writing xtrabackup_info
220425 15:13:08 [00]        ...done
xtrabackup: Transaction log of lsn (2447317) to (2447326) was copied.
220425 15:13:09 completed OK!

結論：這個沒提交的寫事務是不會阻塞備份

場景2:模擬事務中的慢查詢是否阻塞備份

我們可以看到，直到sql執行超時，也就是意味著表關閉了，備份才成功。

結論：事務中的慢查詢會阻塞備份

場景3：模擬不帶事務慢查詢是否阻塞備份

我們可以看到，直到sql執行超時，也就是意味著表關閉了，備份拿到了備份鎖，備份才成功。關於備份鎖的資料請檢視這裡:https://www.percona.com/doc/p...

結論：不帶事務的慢查詢也會阻塞備份

FLUSH TABLES

FLUSH NO_WRITE_TO_BINLOG TABLES = FLUSH TABLES ，只不過這種flush tables 的動作是不會寫入到binlog檔案中，而flush tables 是需要獲取鎖。官方檔案這樣描述flush tables

The FLUSH statement has several variant forms that clear or reload various internal caches, flush tables, or acquire locks.
By default, the server writes FLUSH statements to the binary log so that they replicate to replicas. To suppress logging, specify the optional NO_WRITE_TO_BINLOG keyword or its alias LOCAL.

FLUSH TABLES flushes tables, and, depending on the variant used, acquires locks. Any TABLES variant used in a FLUSH statement must be the only option used. FLUSH TABLE is a synonym for FLUSH TABLES.

Closes all open tables, forces all tables in use to be closed, and flushes the query cache and prepared statement cache. FLUSH TABLES also removes all query results from the query cache, like the RESET QUERY CACHE statement. For information about query caching and prepared statement caching

大概意思就是：關閉所有開啟的表，強制關閉所有正在使用的表，並重新整理查詢快取和準備好的語句快取。FLUSH TABLES還會從查詢快取中刪除所有查詢結果，例如 RESET QUERY CACHE語句。有關查詢快取和準備好的語句快取的資訊

反推生產環境

檢查慢查詢

Oh my god，在32.197伺服器的慢查詢中搜尋到一個執行了10幾個小時的慢查詢

# Time: 2022-04-25T09:12:53.416049+08:00
# User@Host: BlueMoon[BlueMoon] @  [192.168.50.144]  Id: 55128898
# Query_time: 38910.325000  Lock_time: 0.000328 Rows_sent: 0  Rows_examined: 14637241
SET timestamp=1650849173;
SELECT
        d.coupon_master_code
FROM
        mam_coupon_activity_interact a
        LEFT JOIN mam_coupon_send_log b ON a.id = b.interact_id
        LEFT JOIN mam_user_coupon_package c ON c.coupon_user_code = b.coupon_user_code
        left join
        mam_coupon_info  d on c.coupon_info_id = d.id
WHERE
        a.interact_type = 3
GROUP BY
        d.coupon_master_code;

38910秒=10.8 小時，快11個鐘了， Time: 2022-04-25T09:12:53 ，往前推38910秒，也就是 2022-04-24 22:24:23 開始執行這個sql。

為什麼會這麼慢，我們看下執行計

表結構如下：

mysql> show create table mam_coupon_send_log \G
*************************** 1. row ***************************
       Table: mam_coupon_send_log
Create Table: CREATE TABLE `mam_coupon_send_log` (
  `id` int(10) NOT NULL AUTO_INCREMENT COMMENT '主鍵',
  `last_update_time` datetime DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '最後更新時間',
  `operator_name` varchar(32) COLLATE utf8mb4_unicode_ci DEFAULT NULL COMMENT '操作人名稱',
  `operator_id` int(11) DEFAULT NULL COMMENT '操作人編號',
  `create_time` datetime DEFAULT CURRENT_TIMESTAMP COMMENT '建立時間',
  `creator_name` varchar(32) COLLATE utf8mb4_unicode_ci DEFAULT NULL COMMENT '建立人名稱',
  `creator_id` int(11) DEFAULT NULL COMMENT '建立人編號',
  `del_flag` tinyint(1) DEFAULT '0' COMMENT '是否刪除（0：否，1：是）',
  `shop_order_id` bigint(20) DEFAULT NULL COMMENT '訂單編號',
  `activity_code` bigint(20) DEFAULT NULL COMMENT '活動編號',
  `coupon_user_code` bigint(20) DEFAULT NULL COMMENT '使用者券編號',
  `user_id` bigint(20) DEFAULT NULL COMMENT '領券人id',
  `mensend_id` int(11) DEFAULT NULL COMMENT '人工發券id',
  `interact_id` bigint(20) DEFAULT NULL COMMENT '互動贈券id',
  `send_type` tinyint(1) DEFAULT NULL COMMENT '發券型別(1人工發券2積分兌券3買單贈券4資料遷移5券轉增6券轉換7營銷互動)',
  `act_id` int(11) DEFAULT NULL COMMENT '活動id',
  `integral_record_id` bigint(20) DEFAULT NULL COMMENT '積分兌換記錄表id',
  `interact_detail_id` bigint(20) DEFAULT NULL COMMENT '互動贈券明細id',
  PRIMARY KEY (`id`) USING BTREE,
  KEY `idx_coupon_use_code` (`coupon_user_code`) USING BTREE COMMENT '卡券包編碼索引',
  KEY `idx_shop_order_id_send_type` (`shop_order_id`,`send_type`) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=551413 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci ROW_FORMAT=DYNAMIC COMMENT='使用者券傳送日誌表'

建議對interact_id 欄位加索引

alter table mam_coupon_send_log add index idx_interact_id(interact_id);

而我們那點備份是從晚上1點開始備份，也就是說這個備份一直在等待這個查詢結束,符合場景3:

檢查資料庫的sql超時是否設定

mysql> show variables like '%exec%';
+----------------------------------+--------+
| Variable_name                    | Value  |
+----------------------------------+--------+
| gtid_executed_compression_period | 1000   |
| max_execution_time               | 0      |
| rbr_exec_mode                    | STRICT |
| slave_exec_mode                  | STRICT |
+----------------------------------+--------+

。。。。。居然沒有設定sql查詢超時時間

建議設定sql超時時間

set global max_execution_time = 120000;
120秒超時

反推備份優化

設定超時時間

https://www.percona.com/doc/p...

--ftwrl-wait-timeout=SECONDS
This option specifies time in seconds that innobackupex should wait for queries that would block FLUSH TABLES WITH READ LOCK before running it. If there are still such queries when the timeout expires, innobackupex terminates with an error. Default is 0, in which case innobackupex does not wait for queries to complete and starts FLUSH TABLES WITH READ LOCK immediately. Where supported (Percona Server 5.6+) xtrabackup will automatically use Backup Locks as a lightweight alternative to FLUSH TABLES WITH READ LOCK to copy non-InnoDB data to avoid blocking DML queries that modify InnoDB tables.

--kill-long-queries-timeout=SECONDS
This option specifies the number of seconds innobackupex waits between starting FLUSH TABLES WITH READ LOCK and killing those queries that block it. Default is 0 seconds, which means innobackupex will not attempt to kill any queries. In order to use this option xtrabackup user should have PROCESS and SUPER privileges. Where supported (Percona Server 5.6+) xtrabackup will automatically use Backup Locks as a lightweight alternative to FLUSH TABLES WITH READ LOCK to copy non-InnoDB data to avoid blocking DML queries that modify InnoDB tables.

/usr/bin/innobackupex --defaults-file=/etc/my.cnf --user=bigdata_admin --password=123456 --socket=/mysqlData/data/mysql.sock --port=3306 --ftwrl-wait-timeout=5 --kill-long-queries-timeout=5 /data/backup/

總結

1.業務層面：需要定期優化慢查詢，業務庫的增刪改查操作儘量優化到<0.2秒

2.資料庫層面：設定慢查詢執行超時時間，超過了一定時間強制kill掉，比如查過20分鐘，對於OLTP業務，如果一個 sql 20分鐘沒有執行完，那就不是 OLTP ，而是 OLAP 業務 ,應該放在大資料層處理或優化程式碼或sql

set global max_execution_time = 1200000;

3.備份層面:增加鎖等待的超時時間
--ftwrl-wait-timeout=5 --kill-long-queries-timeout=5

由於時間倉促，可能有很多細節沒有考慮到，後續再優化。