MySQL:show processlist Time負數的思考
歡迎關注我的《深入理解MySQL主從原理 32講 》,如下:
如果圖片不能顯示可檢視下面連結:
https://www.jianshu.com/p/d636215d767f
一、問題來源
這是一個朋友問我的一個問題,問題如下,在MTS中Worker執行緒看到Time為負數是怎麼回事,如下:
二、關於show processlist中的Time
實際上show processlist中的資訊基本都來自函式 mysqld_list_processes,也就是說每次執行show processlist 都需要執行這個函式來進行填充。對於Time值來講它來自如下資訊:
Percona :
time_t now= my_time(0);
protocol->store_long ((thd_info->start_time > now) ? 0
: (longlong) (now - thd_info->start_time));
官方版:
time_t now= my_time(0);
protocol->store_long ((longlong) (now - thd_info->start_time));
我們可以注意到在Percona的版本中對這個輸出值做了優化,也就是如果出現負數的時候直接顯示為0,但是官方版中沒有這樣做,可能出現負數。
三、計算方式解讀和測試
現在我們來看看這個簡單的計算公式,實際上now很好理解就是伺服器的當前時間,重點就在於thd_info->start_time的取值來自何處。
實際這個時間來自於函式THD::set_time,但是需要注意的是這個函式會進行過載,有下面三種方式:
過載1
inline void set_time()
{
start_utime= utime_after_lock= my_micro_time();
if (user_time.tv_sec || user_time.tv_usec)
{
start_time= user_time;
}
else
my_micro_time_to_timeval(start_utime, &start_time);
...
}
過載2
inline void set_time(const struct timeval *t)
{
start_time= user_time= *t;
start_utime= utime_after_lock= my_micro_time();
...
}
過載3
void set_time(QUERY_START_TIME_INFO *time_info) { start_time= time_info->start_time; start_utime= time_info->start_utime; }
其實簡單的說就是其中有一個start_utime,如果設定了start_utime那麼start_time將會指定為start_utime,並且在過載1中將會不會修改start_time,這一點比較重要。
好了說了3種方式,我們來看看Time的計算有如下可能。
1、執行命令
如果主庫執行常見的命令都會在命令發起的時候呼叫過載1,設定start_time為命令開始執行的時間如下:
堆疊:
#0 THD::set_time (this=0x7ffe7c000c90) at /mysqldata/percona-server-locks-detail-5.7.22/sql/sql_class.h:3505
#1 0x00000000015c5fe8 in dispatch_command (thd=0x7ffe7c000c90, com_data=0x7fffec03fd70, command=COM_QUERY)
at /mysqldata/percona-server-locks-detail-5.7.22/sql/sql_parse.cc:1247
可以看到這個函式沒有實參,因此start_time會設定為當前時間,那Time的計算公式 now - thd_info->start_time就等於 (伺服器當前時間 - 命令開始執行的時間)。
2、從庫 單Sql執行緒 和 Worker執行緒
其實不管單Sql執行緒還是Worker執行緒都是執行Event的,這裡的start_time將會被設定為Event header中timestamp的時間(query event/dml event),這個時間實際就是主庫命令發起的時間。如下:
堆疊:
query event:
#0 THD::set_time (this=0x7ffe78000950, t=0x7ffe701ec430) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
#1 0x00000000018459ab in Query_log_event::do_apply_event (this=0x7ffe701ec310, rli=0x7ffe7003c050, query_arg=0x7ffe701d88a9 "BEGIN", q_len_arg=5)
at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4714
堆疊:
dml event:
#0 THD::set_time (this=0x7ffe78000950, t=0x7ffe701ed5b8) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
#1 0x000000000185aa6e in Rows_log_event::do_apply_event (this=0x7ffe701ed330, rli=0x7ffe7003c050)
at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:11417
我們看到這裡有一個實參的傳入我們看一下程式碼如下:
thd->set_time(&(common_header->when))
實際上就是這一行,這是我們前面說的過載3,這樣設定後start_utime和start_time都將會設定,即便呼叫過載1也不會更改, 那Time的計算方式 now - thd_info->start_time就等於 (從庫伺服器當前時間 - Event header中的時間),但是要知道 Event header中的時間實際也是來自於主庫命令發起的時間。 既然如此如果從庫伺服器的時間小於主庫伺服器的時間,那麼Time的結果可能是 負數是可能出現的,當然Percona版本做了優化負數將會顯示為0,如果從庫伺服器的時間大於主庫的時間那麼可能看到Time比較大。
因為我的測試環境都是Percona,為了效果明顯,我們來測試一下Worker執行緒Time很大的情況,如下設定:
主庫:
[root@mysqltest2 test]# date
Fri Nov 1 01:40:54 CST 2019
從庫:
[root@gp1 log]# date
Tue Nov 19 15:58:37 CST 2019
主庫隨便做一個命令,然後觀察如下:
3、設定timestamp
如果手動指定timestamp也會影響到Time的計算結果,因為start_utime和start_time都將會設定,如下:
mysql> set timestamp=1572540000
堆疊:
#0 THD::set_time (this=0x7ffe7c000c90, t=0x7fffec03db30) at /mysqldata/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
#1 0x000000000169e509 in update_timestamp (thd=0x7ffe7c000c90, var=0x7ffe7c006860) at /mysqldata/percona-server-locks-detail-5.7.22/sql/sys_vars.cc:4966
#2 0x00000000016b9a3d in Sys_var_session_special_double::session_update (this=0x2e68e20, thd=0x7ffe7c000c90, var=0x7ffe7c006860)
at /mysqldata/percona-server-locks-detail-5.7.22/sql/sys_vars.h:1889
我們看到帶入了實參,我們看看程式碼這一行如下:
thd->set_time(&tmp);
這就是過載2了,這樣設定後start_utime和start_time都將會設定,即便呼叫過載1也不會更改,言外之意就是設定了timestamp後即便執行了其他的命令Time也不會更新。Time的計算方式 now - thd_info->start_time就等於 (伺服器當前時間 - 設定的timestamp時間),這樣的話就可能出現Time出現異常,比如很大或者為負數(Percona為0)如下:
4、空閒情況下
如果我們的會話空閒狀態下那麼now - thd_info->start_time 公式中,now會不斷變大,但是thd_info->start_time卻不會改變,因此Time 會不斷增大,等待到下一次命令到來後才會更改。
四、延伸
這裡我想在說明一下如果從庫開啟了log_slave_updates 的情況下,從庫記錄會記錄來自主庫的Event,但是這些Event的timestamp和Query Event的exetime如何取值呢?
Event的timestamp的取值
其實上面我已經說了,因為 start_time將會被設定為Event header中timestamp的時間(query event/dml event),當記錄Evnet的時候這個時間和主庫基本一致,如下:
很明顯我們會發現這些Event的timestamp不是本地的時間,而是主庫的時間。
Query Event的exetime
我們先來看看這個時間的計算方式:
ulonglong micro_end_time= my_micro_time();//這裡獲取時間 query event
my_micro_time_to_timeval(micro_end_time, &end_time);
exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec;//這裡計算時間
相信對於 thd_arg->start_time而言已經不再陌生,它就是主庫命令發起的時間。我在我的《深入理解主從原理》系列中說過了,對於Query Event的exetime在 row格式binlog下,DML語句將會是第一行語句修改時間的時間,那麼我們做如下定義(row格式 DML語句):
- 主:主庫第一行資料修改完成的伺服器時間 - 主庫本命令發起的時間
- 從:從庫第一行資料修改完成的伺服器時間 - 主庫本命令發起的時間
他們的差值就是:
(從庫第一行資料修改完成的伺服器時間 - 主庫第一行資料修改完成的伺服器時間 )
同樣如果我們從庫的時間遠遠大於主庫的時間,那麼exetime也會出現異常如下:
最後:
Time是我們平時關注的一個指標,我們經常用它來表示我的語句執行了多久,但是如果出現異常的情況我們也應該能夠明白為什麼,這裡我將它的計算方式做了一個不完全的解釋,希望對大家有幫助。當然對於主從部分或者Event部分可以參考我的《深入理解主從原理》系列。
作者微信:gp_22389860
來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/7728585/viewspace-2664813/,如需轉載,請註明出處,否則將追究法律責任。
相關文章
- show processlist time負數的初探
- MySQL 之 show processlist 神器MySql
- MySQL show processlist故障處理MySql
- MySQL8 show processlist 最佳化MySql
- MySQL調優使用者監控之show processlistMySql
- 故障分析 | show processlist 引起的效能問題
- SHOW PROCESSLIST 最多能顯示多長的 SQL?SQL
- 12、MySQL Case-show processlist 狀態一直處於Sending to clientMySqlclient
- MySQL的show engine innodb statusMySql
- MySQL的系統變數max_execution_time小結MySql變數
- MySQL 索引 效能分析 show profilesMySql索引
- MySQL show status 命令詳解MySql
- MySQL高階知識——Show ProfileMySql
- mysql連結很多,批量刪除異常程式processlistMySql
- [MySQL進階之路][No.0002] SHOW SLAVE STATUSMySql
- MySQL調優效能監控之show profileMySql
- MySQL:kill和show命令hang住一列MySql
- mysql檢視儲存過程show procedure status;MySql儲存過程
- MySQL:show slave status 關鍵值和MGRrelay log的清理策略MySql
- Mysql日期(DATE, TIME, DATETIME, TIMESTAMP)型別的比較MySql型別
- MySQL主從複製中的“show slave status”詳細含義MySql
- 負數的右移與左移
- MySQL:5.6 大事務show engine innodb status故障一例MySql
- MySQL: Couldn't execute 'SET OPTION SQL_QUOTE_SHOW_CREATE=1MySql
- mysql show open tables相關知識體系之一MySql
- 負數補碼(16進位制轉10進位制的負數)
- JavaScript show()JavaScript
- show profiles
- MySQL高可用方案的一些思考MySql
- MYSQL connector/.NET 預設的 show variables 引起的執行緒mutex鎖爭用MySql執行緒Mutex
- 對數字孿生的思考
- mysql負載均衡搭建(haproxy)MySql負載
- 負數的二進位制數問題
- mysql資料庫date 、datetime、time、timestamp區別MySql資料庫
- git show 命令Git
- JavaScript show() 方法JavaScript
- python列表中切片的正負數Python
- 統計輸入的數字為正數和負數的個數