MySQL:show processlist Time负数的考虑

欢迎重视我的《深化了解MySQL主从原理 32讲 》,如下:

MySQL:show processlist Time负数的考虑

一、问题来历

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

MySQL:show processlist Time负数的考虑

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

主库随意做一个指令,然后查询如下:

MySQL:show processlist Time负数的考虑

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)如下:

MySQL:show processlist Time负数的考虑

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的时分这个时刻和主库根柢一同,如下:

MySQL:show processlist Time负数的考虑

很显着咱们会发现这些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也会呈现失常如下:

MySQL:show processlist Time负数的考虑

毕竟:

Time是咱们平常重视的一个政策,咱们常常用它来标明我的句子实施了多久,可是假定呈现失常的状况咱们也应该能够了解为什么,这儿我将它的核算方法做了一个不完全的阐明,期望对咱们有帮助。当然关于主从部分或许Event部分能够参看我的《深化了解主从原理》系列。

作者微信:gp_22389860