mysql show processlist Time为负数的思考

太过爱你忘了你带给我的痛 2023-06-15 11:04 8阅读 0赞

**导读**：

> 作者：高鹏（网名八怪），《深入理解MySQL主从原理32讲》系列文的作者。

**想阅读八怪源码文章欢迎订阅**

![format_png][]

--------------------

**本文建议横屏观看，效果更佳**

**一、问题来源**

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

![format_png 1][]

**二、关于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 - thdinfo->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

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

![format_png 2][]

**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 - thdinfo->starttime就等于 （服务器当前时间 - 设置的timestamp时间），这样的话就可能出现Time出现异常，比如很大或者为负数（Percona为0）如下：

![format_png 3][]

**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的时候这个时间和主库基本一致，如下：

![format_png 4][]

很明显我们会发现这些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也会出现异常如下：![format_png 5][]  
**最后：**Time是我们平时关注的一个指标，我们经常用它来表示我的语句执行了多久，但是如果出现异常的情况我们也应该能够明白为什么，这里我将它的计算方式做了一个不完全的解释，希望对大家有帮助。当然对于主从部分或者Event部分可以参考我的《深入理解主从原理》系列。

END

--------------------

**识别下方二维码添加作者为好友**

![format_png 6][]

![分割线箭头动态][format_png 7]

扫码加入MySQL技术Q群

**（群号：****650149401）**

![format_png 8][]

点“在看”给我一朵小黄花![format_png 9][]

![format_png 10][]

[format_png]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy83aDRpY0o0aWNzSkJqVlFpYUFvNkxhckN4RHpjY3VEOWVRbWd2akZpYWlhSTBuTHA5bnh0WllFcXhHbGFPanR5MnkxMmhjckx5WHE1MWVpY1R5V0FiSGhjaWJFREEvNjQwP3d4X2ZtdD1wbmc?x-oss-process=image/format,png
[format_png 1]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X3BuZy83aDRpY0o0aWNzSkJqZWtaaWNEaFpGRHNRZkhjbEJMODFsOTY2TUloZERSNlhkNVJRNFpLZnNZOEdpY1E0Q2liWjFCbElURFpiS0hPNFo5aG1CenVUa0tabG5nLzY0MD93eF9mbXQ9cG5n?x-oss-process=image/format,png
[format_png 2]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X3BuZy83aDRpY0o0aWNzSkJqZWtaaWNEaFpGRHNRZkhjbEJMODFsOVFpYkFvM1o4WVJlWWtMa3Y2dFo4Z1UyS1l3b2JwWUJiQWJaVHVKR2N1ampIRkhpYWljaWJWNUlYbFEvNjQwP3d4X2ZtdD1wbmc?x-oss-process=image/format,png
[format_png 3]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X3BuZy83aDRpY0o0aWNzSkJqZWtaaWNEaFpGRHNRZkhjbEJMODFsOXRuQjBrMkVCTEhNaWJoRnV6enp1c2tOTDQ4bDJ1aFBWT3NkMXFFalo1OTBMaGJxdHM0b2lhcjRnLzY0MD93eF9mbXQ9cG5n?x-oss-process=image/format,png
[format_png 4]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X3BuZy83aDRpY0o0aWNzSkJqZWtaaWNEaFpGRHNRZkhjbEJMODFsOVJhNDhsc2tYQVBIdUIzRFlHdTFmRmM4dkdkMnJjdjFBRTRqeUZMWFpYRWliVmlhNEp2Y0wyN3RnLzY0MD93eF9mbXQ9cG5n?x-oss-process=image/format,png
[format_png 5]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X3BuZy83aDRpY0o0aWNzSkJqZWtaaWNEaFpGRHNRZkhjbEJMODFsOTY0U1hicklPUnhvcUNtRW4wNUlSaFdyN0s4OGlhcTBzcG95NFUwYzZkNUZwNjlUdVN5djRHRWcvNjQwP3d4X2ZtdD1wbmc?x-oss-process=image/format,png
[format_png 6]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy83aDRpY0o0aWNzSkJqUHdoR1lzZU1hOVNkY3pSUjZGUDExWlFRYmdpYjA3ZnVQaWFLYTFCWk4xTTlRQ3NHNkw5MnpFOEt1a0VlVjd2aWNCRHV1aWFkUTdWZDczZy82NDA_d3hfZm10PXBuZw?x-oss-process=image/format,png
[format_png 7]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2dpZi83aDRpY0o0aWNzSkJnOUVoVzhhWFlzZ0FpY2xQMWljbFFpY1hVc09Wa0paSlREUUNOSlBjV0tDUXJUcWNUeHFpY0FDZWMwbzBXVWlidlp5T1FRdkVPdlQ1MjVuQXcvNjQwP3d4X2ZtdD1naWY?x-oss-process=image/format,png
[format_png 8]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2pwZy83aDRpY0o0aWNzSkJqZHlLNEFBWDhDcWhuSkluc0szOGlheGpiaWI5NGF4SlA0Y3NXaWJUdDRwNGJuM2p6SFNLY3RHV3AxaWFpYnIxaWFGVUtiMU9rMUJJbFJ3UmpBLzY0MD93eF9mbXQ9anBlZw?x-oss-process=image/format,png
[format_png 9]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X2dpZi83aDRpY0o0aWNzSkJnZUQyQ2pNaWJ0VThQRXROcW5wSGFpY3FKZHlIUFE0VWxBa1Y4aWF6b1BsRDJITEFOaWFZMWNMN2pVOUtuekhiNFVPNGszOThLazBUdDViQS82NDA_d3hfZm10PWdpZg?x-oss-process=image/format,png
[format_png 10]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X3BuZy83aDRpY0o0aWNzSkJnZUQyQ2pNaWJ0VThQRXROcW5wSGFpY3FqSGtXWHBPcGttZG5HMlFXSWxPbjJVeE9KUkNFdDNTVWdGY1FiVTlvNFdHc1p2OTVvRGhZMVEvNjQwP3d4X2ZtdD1wbmc?x-oss-process=image/format,png