开发者社区> xaubllxwtvaqiu> 正文
阿里云
为了无法计算的价值
打开APP
阿里云APP内打开

mysql show processlist Time为负数的思考

简介: mysql show processlist Time为负数的思考
+关注继续查看

一、问题来源

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

image.png


二、关于show processlist中的Time

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

  1. Percona
  2. time_t now= my_time(0);
  3. protocol->store_long ((thd_info->start_time > now) ? 0
  4. : (longlong) (now - thd_info->start_time));
  5. 官方版:
  6. time_t now= my_time(0);
  7. protocol->store_long ((longlong) (now - thd_info->start_time));


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


三、计算方式解读和测试

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

重载1

  1. inline void set_time()
  2. {
  3. start_utime= utime_after_lock= my_micro_time();
  4. if (user_time.tv_sec || user_time.tv_usec)
  5. {
  6. start_time= user_time;
  7. }
  8. else
  9. my_micro_time_to_timeval(start_utime, &start_time);
  10. ...
  11. }

重载2


  1. inline void set_time(const struct timeval *t)

  2. {

  3. start_time= user_time= *t;

  4. start_utime= utime_after_lock= my_micro_time();

  5. ...

  6. }



重载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为命令开始执行的时间如下:

  1. 堆栈:
  2. query event

  3. #0 THD::set_time (this=0x7ffe78000950, t=0x7ffe701ec430) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
  4. #1 0x00000000018459ab in Query_log_event::do_apply_event (this=0x7ffe701ec310, rli=0x7ffe7003c050, query_arg=0x7ffe701d88a9 "BEGIN", q_len_arg=5)
  5. at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4714

  6. 堆栈:
  7. dml event
  8. #0 THD::set_time (this=0x7ffe78000950, t=0x7ffe701ed5b8) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
  9. #1 0x000000000185aa6e in Rows_log_event::do_apply_event (this=0x7ffe701ed330, rli=0x7ffe7003c050)
  10. at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:11417

可以看到这个函数没有实参,因此start_time会设置为当前时间,那Time的计算公式 now - thdinfo->start_time就等于 (服务器当前时间 - 命令开始执行的时间)。

2、从库单Sql线程和Worker线程

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

  1. 堆栈:
  2. query event

  3. #0 THD::set_time (this=0x7ffe78000950, t=0x7ffe701ec430) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
  4. #1 0x00000000018459ab in Query_log_event::do_apply_event (this=0x7ffe701ec310, rli=0x7ffe7003c050, query_arg=0x7ffe701d88a9 "BEGIN", q_len_arg=5)
  5. at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:4714

  6. 堆栈:
  7. dml event
  8. #0 THD::set_time (this=0x7ffe78000950, t=0x7ffe701ed5b8) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
  9. #1 0x000000000185aa6e in Rows_log_event::do_apply_event (this=0x7ffe701ed330, rli=0x7ffe7003c050)
  10. at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/log_event.cc:11417

我们看到这里有一个实参的传入我们看一下代码如下:

  1. 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很大的情况,如下设置:

  1. 主库:
  2. [root@mysqltest2 test]# date
  3. Fri Nov 1 01:40:54 CST 2019

  4. 从库:
  5. [root@gp1 log]# date
  6. Tue Nov 19 15:58:37 CST 2019

主库随便做一个命令,然后观察如下:

image.png

3、设置timestamp

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

  1. mysql> set timestamp=1572540000

  2. 堆栈:
  3. #0 THD::set_time (this=0x7ffe7c000c90, t=0x7fffec03db30) at /mysqldata/percona-server-locks-detail-5.7.22/sql/sql_class.h:3526
  4. #1 0x000000000169e509 in update_timestamp (thd=0x7ffe7c000c90, var=0x7ffe7c006860) at /mysqldata/percona-server-locks-detail-5.7.22/sql/sys_vars.cc:4966
  5. #2 0x00000000016b9a3d in Sys_var_session_special_double::session_update (this=0x2e68e20, thd=0x7ffe7c000c90, var=0x7ffe7c006860)
  6. at /mysqldata/percona-server-locks-detail-5.7.22/sql/sys_vars.h:1889

我们看到带入了实参,我们看看代码这一行如下:

  1. thd->set_time(&tmp);

这就是重载2了,这样设置后start_utime和start_time都将会设置,即便调用重载1也不会更改,言外之意就是设置了timestamp后即便执行了其他的命令Time也不会更新。Time的计算方式 now - thdinfo->starttime就等于 (服务器当前时间 - 设置的timestamp时间),这样的话就可能出现Time出现异常,比如很大或者为负数(Percona为0)如下:

image.png

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

很明显我们会发现这些Event的timestamp不是本地的时间,而是主库的时间。

Query Event的exetime

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

  1. ulonglong micro_end_time= my_micro_time();//这里获取时间 query event
  2. my_micro_time_to_timeval(micro_end_time, &end_time);

  3. 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

最后:Time是我们平时关注的一个指标,我们经常用它来表示我的语句执行了多久,但是如果出现异常的情况我们也应该能够明白为什么,这里我将它的计算方式做了一个不完全的解释,希望对大家有帮助。当然对于主从部分或者Event部分可以参考我的《深入理解主从原理》系列。

            </div>

版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。

相关文章
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
12 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
14 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
6 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
11 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
11 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
14 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
14 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
18 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
13 0
mysql show processlist Time为负数的思考
mysql show processlist Time为负数的思考
34 0
7759
文章
0
问答
文章排行榜
最热
最新
相关电子书
更多
低代码开发师(初级)实战教程
立即下载
阿里巴巴DevOps 最佳实践手册
立即下载
冬季实战营第三期:MySQL数据库进阶实战
立即下载