MySQL慢日志為何會出現Prepare與Binlog Dump
問題現象
某客戶的RDS資料庫的某個時間段（時間點），慢日志記錄出現大量的Prepare操作以及零星的Binlog Dump操作，如下圖：
Prepare:
Binlog dump:
問題分析
慢日志中出現Prepare分析
MySQL預處理語句
Prepare是MySQL的預處理指令，其在MySQL server實作了請求的預處理，當我們使用MySQL shell client的時候，可以通過如下方式進行請求：
mysql> PREPARE stmt1 FROM 'SELECT SQRT(POW(?,2) + POW(?,2)) AS hypotenuse';
mysql> SET @a = 3;
mysql> SET @b = 4;
mysql> EXECUTE stmt1 USING @a, @b;
+------------+
| hypotenuse |
+------------+
| 5 |
+------------+ 當我們在開發應用程式時，在代碼中使用時，可以通過如下方式請求（下圖為JAVA代碼）：
String selectSql = "select * from alitest where a = ? or b = ?";
PreparedStatement pretest = conn.prepareStatement(selectSql);
pretest.setInt(1, 1);
pretest.setInt(2, 2);
ResultSet res = pretest.executeQuery(); 注意：在使用JAVA時，由于預處理既可以在用戶端實作也可以在SERVER側實作，要使程式使用SERVER側的預處理，需要在建連時打開：useServerPrepStmts=true，即：jdbc:mysql://XXX.XXX.XXX.XXX:3306/alitest?useServerPrepStmts=true
MySQL對預處理請求進行Prepare的函數
從/mysql-5.6.24/sql/sql_prepare.cc源碼檔案中，可以找到進行Prepare的函數：Prepared_statement::prepare()。它的主要作用是 Parse statement text, validate the statement, and prepare it for execution。
MySQL記錄慢日志的函數
從/mysql-5.6.24sql/sql_parse.cc源碼檔案中，可以找到進行慢日志記錄的函數：log_slow_statement(THD *thd)，它的主要作用是Check whether we need to write the current statement to the slow query log。
複現問題
慢日志中出現Prepare，是否是因為Prepared_statement::prepare()函數處理請求過慢超過long_query_time導緻?為了驗證這個猜測，模拟Prepared_statement::prepare()函數處理慢的情況，人工的通過GDB對Prepared_statement::prepare()設定斷點，增加其執行時間，然後通過MySQL shell client 與JAVA代碼分别請求，檢視慢日志的記錄情況。
設定斷點
(gdb) b Prepared_statement::prepare
Breakpoint 1 at 0x7d821e: file /opt/mysql-5.6.24/sql/sql_prepare.cc, line 3358.
MySQL shell client 執行如下指令
mysql> PREPARE stmt1 FROM 'SELECT SQRT(POW(?,2) + POW(?,2)) AS hypotenuse';
(指令阻塞......)
指令阻塞後，等待超過long_query_time的時間，然後在GDB中執行continue繼續運作指令，PREPARE指令執行完成後，檢視慢日志如下：
*************************** 15. row ***************************
start_time: 2020-08-22 18:34:45
user_host: root[root] @ localhost []
query_time: 00:04:56
lock_time: 00:00:00
rows_sent: 0
rows_examined: 0
db:
last_insert_id: 0
insert_id: 0
server_id: 2003306
sql_text: PREPARE stmt1 FROM 'SELECT SQRT(POW(?,2) + POW(?,2)) AS hypotenuse'
thread_id: 171 從慢日志的記錄來看，這不是我們想要的結果。
JAVA執行Prepare請求：
調用JAVA代碼（請記住連接配接時啟用useServerPrepStmts），執行Prepare操作，請求阻塞後，等待超過long_query_time的時間，然後在GDB中執行continue繼續運作指令，JAVA代碼執行完成後，檢視慢日志如下：
************************* 7. row ***************************
start_time: 2020-08-22 18:57:45
user_host: dtstest[dtstest] @ [115.216.4.201]
query_time: 00:00:09
lock_time: 00:00:00
rows_sent: 0
rows_examined: 0
db: alitest
last_insert_id: 0
insert_id: 0
server_id: 2003306
sql_text: Prepare
thread_id: 163 可以看到，Prepare指令被記錄到了慢日志中。
慢日志中出現Binlog dump分析
MySQL的Binlog dump指令
當我們搭建MySQL的從庫時，需要從主庫擷取binlog檔案，而Binlog dump（或者Binlog dump gtid）指令就是用來該功能的。MySQL中有2個關于Binlog dump的函數，分别是com_binlog_dump()與com_binlog_dump_gtid()，後者主要應用于開啟了GTID的複制。可以在/mysql-5.6.24/sql/rpl_master.cc中找到它們。根據之前的猜測，慢日志中出現Binlog dump（或者Binlog dump GTID）是否是因為對應的函數處理慢導緻？
(gdb) b com_binlog_dump
Breakpoint 3 at 0xa12318: file /opt/mysql-5.6.24/sql/rpl_master.cc, line 739.
啟動binlog dump
為了測試友善，直接使用mysqlbinlog程式遠端擷取binlog：
/bin/mysqlbinlog -hxxx.xxx.xxx.xxx -udtstest -p --read-from-remote-server mysqlbin.000004
指令阻塞後，等待超過long_query_time的時間，然後在GDB中執行continue繼續運作指令，mysqlbinlog指令執行完成後，檢視慢日志如下：
************************* 34. row ***************************
start_time: 2020-08-22 20:57:38
user_host: dtstest[dtstest] @ [121.196.185.131]
query_time: 00:00:00
lock_time: 00:00:00
rows_sent: 0
rows_examined: 0
db:
last_insert_id: 0
insert_id: 0
server_id: 2003306
sql_text: Binlog Dump
thread_id: 466 可以看到，Binlog Dump指令被記錄到了慢日志中。
注意：由于Binlog dump屬于admin statement，複現問題時，需要把log_slow_admin_statements設定為ON。慢日志才會記錄admin statements。
問題結論
慢日志中出現Binlog dump、Binlog dump GTID、Prepare指令，是由于對應的請求執行超過long_query_time導緻。出現這種情況，一般意味着系統負載可能較高，尤其是Prepare等指令的出現，需要引起關注。
後記
如果想要更加友善的複現該問題，可以把long_query_time參數設定為0（這樣可以避免通過GDB來手動幹預指令的耗時），然後調用JAVA代碼以及mysqlbinlog程式進行驗證。