歡迎關注我的《深入理解MySQL主從原理 32講 》，如下：

![image.png](https://upload-images.jianshu.io/upload_images/7398834-0ffa3bdc078cddf4.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)

如果圖片不能顯示可檢視下面連結： 
https://www.jianshu.com/p/d636215d767f

###一、問題來源

這是一個朋友問我的一個問題，問題如下，在MTS中Worker執行緒看到Time為負數是怎麼回事，如下：

![image.png](https://upload-images.jianshu.io/upload_images/7398834-3ee65e492e0f45c8.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)

###二、關於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

```

主庫隨便做一個命令，然後觀察如下：

![image.png](https://upload-images.jianshu.io/upload_images/7398834-cedf7e40f118b81c.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)

#####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）如下：

![image.png](https://upload-images.jianshu.io/upload_images/7398834-0f3484f749c5c776.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)

#####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的時候這個時間和主庫基本一致，如下：

![image.png](https://upload-images.jianshu.io/upload_images/7398834-b354559bcfdb35d0.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)

很明顯我們會發現這些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也會出現異常如下：

![image.png](https://upload-images.jianshu.io/upload_images/7398834-5167aba6ab2d3465.png?imageMogr2/auto-orient/strip%7CimageView2/2/w/1240)

###最後：

Time是我們平時關注的一個指標，我們經常用它來表示我的語句執行了多久，但是如果出現異常的情況我們也應該能夠明白為什麼，這裡我將它的計算方式做了一個不完全的解釋，希望對大家有幫助。當然對於主從部分或者Event部分可以參考我的《深入理解主從原理》系列。

**作者微信：gp_22389860**

MySQL：show processlist Time負數的思考

相關文章