如何理解在MTS中Worker线程看到Time为负数，针对这个问题，这篇文章详细介绍了相对应的分析和解答，希望可以帮助更多想解决这个问题的小伙伴找到更简单易行的方法。

这是一个朋友问我的一个问题，问题如下，在MTS中Worker线程看到Time为负数是怎么回事，如下：

实际上show processlist中的信息基本都来自函数 mysqld_list_processes，也就是说每次执行show processlist 都需要执行这个函数来进行填充。对于Time值来讲它来自如下信息：

Percona：time_tnow=my_time(0);protocol->store_long((thd_info->start_time>now)?0:(longlong)(now-thd_info->start_time));官方版：time_tnow=my_time(0);protocol->store_long((longlong)(now-thd_info->start_time));

我们可以注意到在Percona的版本中对这个输出值做了优化，也就是如果出现负数的时候直接显示为0，但是官方版中没有这样做，可能出现负数。

现在我们来看看这个简单的计算公式，实际上now很好理解就是服务器的当前时间，重点就在于thd_info->start_time的取值来自何处。
实际这个时间来自于函数THD::set_time，但是需要注意的是这个函数会进行重载，有下面三种方式：

重载1

inlinevoidset_time(){start_utime=utime_after_lock=my_micro_time();if(user_time.tv_sec||user_time.tv_usec){start_time=user_time;}elsemy_micro_time_to_timeval(start_utime,&start_time);...}

重载2

inlinevoidset_time(conststructtimeval*t){start_time=user_time=*t;start_utime=utime_after_lock=my_micro_time();...}

重载3

voidset_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，设置start_time为命令开始执行的时间如下：

堆栈：#0THD::set_time(this=0x7ffe7c000c90)at/mysqldata/percona-server-locks-detail-5.7.22/sql/sql_class.h:3505#10x00000000015c5fe8indispatch_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就等于 （服务器当前时间 - 命令开始执行的时间）。

其实不管单Sql线程还是Worker线程都是执行Event的，这里的start_time将会被设置为Event header中timestamp的时间（query event/dml event），这个时间实际就是主库命令发起的时间。如下：

堆栈：queryevent：#0THD::set_time(this=0x7ffe78000950,t=0x7ffe701ec430)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526#10x00000000018459abinQuery_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堆栈：dmlevent：#0THD::set_time(this=0x7ffe78000950,t=0x7ffe701ed5b8)at/root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526#10x000000000185aa6einRows_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@mysqltest2test]#dateFriNov101:40:54CST2019从库：[root@gp1log]#dateTueNov1915:58:37CST2019

主库随便做一个命令，然后观察如下：

如果手动指定timestamp也会影响到Time的计算结果，因为start_utime和start_time都将会设置，如下：

mysql>settimestamp=1572540000堆栈：#0THD::set_time(this=0x7ffe7c000c90,t=0x7fffec03db30)at/mysqldata/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526#10x000000000169e509inupdate_timestamp(thd=0x7ffe7c000c90,var=0x7ffe7c006860)at/mysqldata/percona-server-locks-detail-5.7.22/sql/sys_vars.cc:4966#20x00000000016b9a3dinSys_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）如下：

如果我们的会话空闲状态下那么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

我们先来看看这个时间的计算方式：

ulonglongmicro_end_time=my_micro_time();//这里获取时间queryeventmy_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是我们平时关注的一个指标，我们经常用它来表示我的语句执行了多久，但是如果出现异常的情况我们也应该能够明白为什么，这里我将它的计算方式做了一个不完全的解释。

关于如何理解在MTS中Worker线程看到Time为负数问题的解答就分享到这里了，希望以上内容可以对大家有一定的帮助，如果你还有很多疑惑没有解开，可以关注亿速云行业资讯频道了解更多相关知识。