經過slow query log能夠查出長時間未提交的事務嗎？用實驗+源碼來揭曉答案

時間 2020-03-18

標籤經過 slow query log 能夠查出長時間未提事務實驗源碼揭曉答案欄目快樂工作简体版

原文原文鏈接

與數據庫打過交道的人，大多都知道：長時間未提交的事務，會致使更多的鎖衝突，並且也會致使主從複製的延時高。html

針對這個問題，我曾經想過，可否經過分析slow query log來定位？mysql

首先，我從官方文檔中看到以下描述：linux

Property	Value
Command-Line Format	`--long-query-time=#`
System Variable	`long_query_time`
Scope	Global, Session
Dynamic	Yes
Type	Numeric
Default Value	`10`
Minimum Value	`0`

If a query takes longer than this many seconds, the server increments the Slow_queries status variable. If the slow query log is enabled, the query is logged to the slow query log file. This value is measured in real time, not CPU time, so a query that is under the threshold on a lightly loaded system might be above the threshold on a heavily loaded one. The minimum and default values of long_query_time are 0 and 10, respectively. The value can be specified to a resolution of microseconds. See Section 5.4.5, 「The Slow Query Log」. git

上述被紅線標示出來的內容，只是說long_query_time參數的值，指的是真實花費的時間，不是CPU時間，並無說明是否包含等待鎖的時間，以及持有鎖的時間；github

另外，請注意"If a query takes ..."這句話，說明slow query log記錄的是以query爲單位，而不是以transaction爲單位。sql

而後，我經過簡單的實驗進行論證：數據庫

實驗前提：
MySQL版本：5.7.12 on Windows 10
long_query_time=0.1
slow_query_log=ON

表信息：
CREATE TABLE `t1` (
`id` INT(11) NOT NULL AUTO_INCREMENT,
`c2` VARCHAR(100) NULL DEFAULT NULL,
PRIMARY KEY (`id`)
)
COLLATE='utf8mb4_general_ci'
ENGINE=InnoDB
AUTO_INCREMENT=196593
;



執行insert into t1 (c2) select c2 from t1;往表裏插入了約10萬條數據。

1.長時間未提交的事務，會不會被記錄？app

--只開一個會話，執行以下SQL：
set autocommit=0;
delete from t1 where id=3;


等待數秒鐘，而後去查看slow_query_log_file參數對應的文件中是否有記錄，
結論是，沒有

2.等待鎖的時間花費的時間超過了long_query_time的閾值，可是DML語句自己沒有超過閾值，會不會被記錄？函數

開啓兩個會話：
會話1:	會話2:
set autocommit=0;工具	set autocommit=0;
delete from t1 where id=3; select sleep(2);
	delete from t1 where id=3;
rollback;
	commit;

結論是：slow query log中，只記錄了會話1執行的select sleep(2)，兩個會話分別執行過的delete from t1 where id=3則沒有被記錄。

3.DML語句超過了閾值，可是回滾了，是否會被記錄？

--只須要開啓一個會話：

set autocommit=0;
insert into t1 (c2) select c2 from t1;

rollback;
/* Affected rows: 98,305  已找到記錄: 0  警告: 0  持續時間 3 queries: 00:03:38 */

結論：被回滾的DML語句，若是超過了閾值，會被記錄到slow query log中

4.同一個事務中的多條語句，部分語句超過了閾值，那麼是記錄全部的語句，仍是超過閾值的那部分語句？

--只須要開啓一個會話：
set autocommit=0;
insert into t1 (c2) select c2 from t1;
insert into t1(c2) values('aaa');

commit;

結論：只有超過了閾值的語句會被記錄，未超過的則不會被記錄

最後，去源碼中追根溯源：

去源碼中搜索long_query_time關鍵字，首先能夠看到sql/sys_vars.cc中有以下相關的定義：

 1 static Sys_var_double Sys_long_query_time(
 2        "long_query_time",
 3        "Log all queries that have taken more than long_query_time seconds "
 4        "to execute to file. The argument will be treated as a decimal value "
 5        "with microsecond precision",
 6        SESSION_VAR(long_query_time_double),
 7        CMD_LINE(REQUIRED_ARG), VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(10),
 8        NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
 9        ON_UPDATE(update_cached_long_query_time));
10 
11 static bool update_cached_long_query_time(sys_var *self, THD *thd,
12                                           enum_var_type type)
13 {
14   if (type == OPT_SESSION)
15     thd->variables.long_query_time=
16       double2ulonglong(thd->variables.long_query_time_double * 1e6);
17   else
18     global_system_variables.long_query_time=
19       double2ulonglong(global_system_variables.long_query_time_double * 1e6);
20   return false;
21 }
22 
23 
24 能夠看到，MySQL使用long_query_time參數的值，來更新thd->variables.long_query_time（會話級）  或 global_system_variables.long_query_time（全局級）變量的值

接着，使用variables.long_query_time關鍵字查找，能夠看到在sql/sql_class.h中有以下定義：

 1   /**
 2    Update server status after execution of a top level statement.
 3 
 4    Currently only checks if a query was slow, and assigns
 5    the status accordingly.
 6    Evaluate the current time, and if it exceeds the long-query-time
 7    setting, mark the query as slow.
 8   */
 9   void update_server_status()
10   {
11     ulonglong end_utime_of_query= current_utime();
12     if (end_utime_of_query > utime_after_lock + variables.long_query_time)
13       server_status|= SERVER_QUERY_WAS_SLOW;
14   }
15 
16 
17 能夠看到，判斷邏輯是if (end_utime_of_query > utime_after_lock + variables.long_query_time)，也就是說，若是query結束的時間 > 鎖等待的時間 + long_query_time變量設置的閾值，就修改server_status爲SERVER_QUERY_WAS_SLOW

那麼，update_server_status()函數在哪裏被調用呢？經過搜索，發如今sql/sql_parse.cc中的dispatch_command()函數會調用update_server_status():

 1 bool dispatch_command(THD *thd, const COM_DATA *com_data,
 2                       enum enum_server_command command)
 3 {
 4 ...省略若干行
 5       /* Finalize server status flags after executing a statement. */
 6       thd->update_server_status();
 7 ...省略若干行
 8       log_slow_statement(thd);
 9 ...省略若干行
10 }
11 
12 能夠看到，在這裏調用了update_server_status()，而後據thd->server_status 是否包含 SERVER_QUERY_WAS_SLOW 標誌，決定是否寫入慢查詢日誌。
13 
14 sql/log.cc中log_slow_statement()函數很簡短：
15 
16 void log_slow_statement(THD *thd)
17 {
18   if (log_slow_applicable(thd))
19     log_slow_do(thd);
20 }
21 
22 其中，在log_slow_applicable()函數中，根據log_slow_admin_statements參數和log_queries_not_using_indexes參數的設置，判斷是否記錄未使用索引的語句和管理語句。
23 而後調用log_slow_do():
24 void log_slow_do(THD *thd)
25 {
26   THD_STAGE_INFO(thd, stage_logging_slow_query);
27   //修改MySQL  Slow_queries狀態值
28   thd->status_var.long_query_count++;
29 
30   //根據rewritten_query變量的值，判斷是否須要改寫語句，好比一些涉及到password的管理語句，則須要把密碼替換成hash值
     //調用query_logger.slow_log_write，將slow query log寫入表，或者日誌文件
31   if (thd->rewritten_query.length())
32     query_logger.slow_log_write(thd,
33                                 thd->rewritten_query.c_ptr_safe(),
34                                 thd->rewritten_query.length());
35   else
36     query_logger.slow_log_write(thd, thd->query().str, thd->query().length);
37 }

最後，若是log_output設置的是FILE，則會調用sql/log.cc的以下函數：(*current_handler++)->log_slow()函數 -> Log_to_file_event_handler::log_slow() -> mysql_slow_log.write_slow()函數，最終調用my_b_write宏，來將slow query log持久化到磁盤文件。

題外話：如何定位或解決長時間未提交的事務呢？

方法有幾種：

一、若是使用的是Percona分支，則可使用innodb_kill_idle_transaction或kill_idle_transaction參數來自動殺掉長時間未提交的事務。參考：https://www.percona.com/doc/percona-server/5.6/management/innodb_kill_idle_trx.html https://www.percona.com/doc/percona-server/5.7/management/innodb_kill_idle_trx.html#kill_idle_transaction

二、若是未使用Percona分支或MariaDB分支, 而使用的是官方原版的話，可使用以下語句找出來，而後手動kill:

SELECT 
  a.trx_id,
  trx_state,
  trx_started,
  b.id AS thread_id,
  b.info,
  b.user,
  b.host,
  b.db,
  b.command,
  b.state 
FROM
  information_schema.`INNODB_TRX` a,
  information_schema.`PROCESSLIST` b 
WHERE a.trx_mysql_thread_id = b.id  and trx_state='RUNNING' and b.COMMAND='sleep'
ORDER BY a.trx_started;

三、上述SQL只能找到是哪一個會話致使的問題，殊不知道執行的是什麼SQL，若是是5.7以上的版本，而且開啓了performance_schema的話，可使用sys視圖，參考：https://www.cnblogs.com/gaogao67/p/10790520.html 例如：

## 查看未提交的事務(3秒內未操做的事務)
SELECT 
p.ID AS conn_id,
P.USER AS login_user,
P.HOST AS login_host,
p.DB AS database_name,
P.TIME AS trx_sleep_seconds,
TIME_TO_SEC(TIMEDIFF(NOW(),T.trx_started)) AS trx_open_seconds,
T.trx_started,
T.trx_isolation_level,
T.trx_tables_locked,
T.trx_rows_locked,
t.trx_state,
p.COMMAND AS process_state,
(
SELECT GROUP_CONCAT(REPLACE(REPLACE(REPLACE(T1.`SQL_TEXT`,'\n',' '),'\r',' '),'\t',' ') SEPARATOR ';
') 
FROM performance_schema.events_statements_history AS T1
INNER JOIN performance_schema.threads AS T2
ON T1.`THREAD_ID`=T2.`THREAD_ID`
WHERE T2.`PROCESSLIST_ID`=P.id
) AS trx_sql_text
FROM `information_schema`.`INNODB_TRX` t
INNER JOIN `information_schema`.`PROCESSLIST` p
ON t.trx_mysql_thread_id=p.id
WHERE t.trx_state='RUNNING'
AND p.COMMAND='Sleep'
AND P.TIME>3
ORDER BY T.trx_started ASC \G