如何理解在MTS中Worker線程看到Time為負(fù)數(shù)，針對(duì)這個(gè)問(wèn)題，這篇文章詳細(xì)介紹了相對(duì)應(yīng)的分析和解答，希望可以幫助更多想解決這個(gè)問(wèn)題的小伙伴找到更簡(jiǎn)單易行的方法。

10年積累的成都網(wǎng)站設(shè)計(jì)、成都網(wǎng)站制作、外貿(mào)網(wǎng)站建設(shè)經(jīng)驗(yàn)，可以快速應(yīng)對(duì)客戶對(duì)網(wǎng)站的新想法和需求。提供各種問(wèn)題對(duì)應(yīng)的解決方案。讓選擇我們的客戶得到更好、更有力的網(wǎng)絡(luò)服務(wù)。我雖然不認(rèn)識(shí)你，你也不認(rèn)識(shí)我。但先網(wǎng)站設(shè)計(jì)后付款的網(wǎng)站建設(shè)流程，更有溫泉免費(fèi)網(wǎng)站建設(shè)讓你可以放心的選擇與我們合作。

一、問(wèn)題來(lái)源

這是一個(gè)朋友問(wèn)我的一個(gè)問(wèn)題，問(wèn)題如下，在MTS中Worker線程看到Time為負(fù)數(shù)是怎么回事，如下：

二、關(guān)于show processlist中的Time

實(shí)際上show processlist中的信息基本都來(lái)自函數(shù) mysqld_list_processes，也就是說(shuō)每次執(zhí)行show processlist 都需要執(zhí)行這個(gè)函數(shù)來(lái)進(jìn)行填充。對(duì)于Time值來(lái)講它來(lái)自如下信息：

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的版本中對(duì)這個(gè)輸出值做了優(yōu)化，也就是如果出現(xiàn)負(fù)數(shù)的時(shí)候直接顯示為0，但是官方版中沒(méi)有這樣做，可能出現(xiàn)負(fù)數(shù)。

三、計(jì)算方式解讀和測(cè)試

現(xiàn)在我們來(lái)看看這個(gè)簡(jiǎn)單的計(jì)算公式，實(shí)際上now很好理解就是服務(wù)器的當(dāng)前時(shí)間，重點(diǎn)就在于thd_info->start_time的取值來(lái)自何處。
實(shí)際這個(gè)時(shí)間來(lái)自于函數(shù)THD::set_time，但是需要注意的是這個(gè)函數(shù)會(huì)進(jìn)行重載，有下面三種方式：

重載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;
  }

其實(shí)簡(jiǎn)單的說(shuō)就是其中有一個(gè)start_utime，如果設(shè)置了start_utime那么start_time將會(huì)指定為start_utime，并且在重載1中將會(huì)不會(huì)修改start_time，這一點(diǎn)比較重要。

好了說(shuō)了3種方式，我們來(lái)看看Time的計(jì)算有如下可能。

1、執(zhí)行命令

如果主庫(kù)執(zhí)行常見(jiàn)的命令都會(huì)在命令發(fā)起的時(shí)候調(diào)用重載1，設(shè)置start_time為命令開(kāi)始執(zhí)行的時(shí)間如下：

堆棧：
#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

可以看到這個(gè)函數(shù)沒(méi)有實(shí)參，因此start_time會(huì)設(shè)置為當(dāng)前時(shí)間，那Time的計(jì)算公式 now - thd_info->start_time就等于 （服務(wù)器當(dāng)前時(shí)間 - 命令開(kāi)始執(zhí)行的時(shí)間）。

2、從庫(kù) 單Sql線程 和 Worker線程

其實(shí)不管單Sql線程還是Worker線程都是執(zhí)行Event的，這里的start_time將會(huì)被設(shè)置為Event header中timestamp的時(shí)間（query event/dml event），這個(gè)時(shí)間實(shí)際就是主庫(kù)命令發(fā)起的時(shí)間。如下：

堆棧：
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

我們看到這里有一個(gè)實(shí)參的傳入我們看一下代碼如下：

thd->set_time(&(common_header->when))

實(shí)際上就是這一行，這是我們前面說(shuō)的重載3，這樣設(shè)置后start_utime和start_time都將會(huì)設(shè)置，即便調(diào)用重載1也不會(huì)更改， 那Time的計(jì)算方式 now - thd_info->start_time就等于 （從庫(kù)服務(wù)器當(dāng)前時(shí)間 - Event header中的時(shí)間），但是要知道 Event header中的時(shí)間實(shí)際也是來(lái)自于主庫(kù)命令發(fā)起的時(shí)間。 既然如此如果從庫(kù)服務(wù)器的時(shí)間小于主庫(kù)服務(wù)器的時(shí)間，那么Time的結(jié)果可能是負(fù)數(shù)是可能出現(xiàn)的，當(dāng)然Percona版本做了優(yōu)化負(fù)數(shù)將會(huì)顯示為0，如果從庫(kù)服務(wù)器的時(shí)間大于主庫(kù)的時(shí)間那么可能看到Time比較大。

因?yàn)槲业臏y(cè)試環(huán)境都是Percona，為了效果明顯，我們來(lái)測(cè)試一下Worker線程Time很大的情況，如下設(shè)置：

主庫(kù)：
[root@mysqltest2 test]# date
Fri Nov  1 01:40:54 CST 2019
從庫(kù)：
[root@gp1 log]# date 
Tue Nov 19 15:58:37 CST 2019

主庫(kù)隨便做一個(gè)命令，然后觀察如下：

3、設(shè)置timestamp

如果手動(dòng)指定timestamp也會(huì)影響到Time的計(jì)算結(jié)果，因?yàn)閟tart_utime和start_time都將會(huì)設(shè)置，如下：

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

我們看到帶入了實(shí)參，我們看看代碼這一行如下：

 thd->set_time(&tmp);

這就是重載2了，這樣設(shè)置后start_utime和start_time都將會(huì)設(shè)置，即便調(diào)用重載1也不會(huì)更改，言外之意就是設(shè)置了timestamp后即便執(zhí)行了其他的命令Time也不會(huì)更新。Time的計(jì)算方式 now - thd_info->start_time就等于 （服務(wù)器當(dāng)前時(shí)間 - 設(shè)置的timestamp時(shí)間），這樣的話就可能出現(xiàn)Time出現(xiàn)異常，比如很大或者為負(fù)數(shù)（Percona為0）如下：

4、空閑情況下

如果我們的會(huì)話空閑狀態(tài)下那么now - thd_info->start_time 公式中，now會(huì)不斷變大，但是thd_info->start_time卻不會(huì)改變，因此Time 會(huì)不斷增大，等待到下一次命令到來(lái)后才會(huì)更改。

四、延伸

這里我想在說(shuō)明一下如果從庫(kù)開(kāi)啟了log_slave_updates 的情況下，從庫(kù)記錄會(huì)記錄來(lái)自主庫(kù)的Event，但是這些Event的timestamp和Query Event的exetime如何取值呢？

Event的timestamp的取值

其實(shí)上面我已經(jīng)說(shuō)了，因?yàn)?start_time將會(huì)被設(shè)置為Event header中timestamp的時(shí)間（query event/dml event），當(dāng)記錄Evnet的時(shí)候這個(gè)時(shí)間和主庫(kù)基本一致，如下：

很明顯我們會(huì)發(fā)現(xiàn)這些Event的timestamp不是本地的時(shí)間，而是主庫(kù)的時(shí)間。

Query Event的exetime

我們先來(lái)看看這個(gè)時(shí)間的計(jì)算方式：

  ulonglong micro_end_time= my_micro_time();//這里獲取時(shí)間 query event
  my_micro_time_to_timeval(micro_end_time, &end_time);
  exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec;//這里計(jì)算時(shí)間

相信對(duì)于  thd_arg->start_time而言已經(jīng)不再陌生，它就是主庫(kù)命令發(fā)起的時(shí)間。我在我的《深入理解主從原理》系列中說(shuō)過(guò)了，對(duì)于Query Event的exetime在 row格式binlog下，DML語(yǔ)句將會(huì)是第一行語(yǔ)句修改時(shí)間的時(shí)間，那么我們做如下定義（row格式 DML語(yǔ)句）：

• 主：主庫(kù)第一行數(shù)據(jù)修改完成的服務(wù)器時(shí)間 - 主庫(kù)本命令發(fā)起的時(shí)間

• 從：從庫(kù)第一行數(shù)據(jù)修改完成的服務(wù)器時(shí)間 - 主庫(kù)本命令發(fā)起的時(shí)間

他們的差值就是：
（從庫(kù)第一行數(shù)據(jù)修改完成的服務(wù)器時(shí)間 - 主庫(kù)第一行數(shù)據(jù)修改完成的服務(wù)器時(shí)間 ）

同樣如果我們從庫(kù)的時(shí)間遠(yuǎn)遠(yuǎn)大于主庫(kù)的時(shí)間，那么exetime也會(huì)出現(xiàn)異常如下：

Time是我們平時(shí)關(guān)注的一個(gè)指標(biāo)，我們經(jīng)常用它來(lái)表示我的語(yǔ)句執(zhí)行了多久，但是如果出現(xiàn)異常的情況我們也應(yīng)該能夠明白為什么，這里我將它的計(jì)算方式做了一個(gè)不完全的解釋。

關(guān)于如何理解在MTS中Worker線程看到Time為負(fù)數(shù)問(wèn)題的解答就分享到這里了，希望以上內(nèi)容可以對(duì)大家有一定的幫助，如果你還有很多疑惑沒(méi)有解開(kāi)，可以關(guān)注創(chuàng)新互聯(lián)-成都網(wǎng)站建設(shè)公司行業(yè)資訊頻道了解更多相關(guān)知識(shí)。

網(wǎng)站標(biāo)題：如何理解在MTS中Worker線程看到Time為負(fù)數(shù)-創(chuàng)新互聯(lián)
標(biāo)題網(wǎng)址：http://weahome.cn/article/dgojje.html