Technology sharing | MySQL show processlist time is negative

Time:2020-11-10

Author: Gao Peng
At the end of the article, there is his book “deep understanding of MySQL master-slave principle 32 lectures”, in-depth and thorough understanding of MySQL master-slave, gtid related technical knowledge.

1、 Source of the problem

This is a question a friend asked me. The question is as follows: in MTS, the worker thread sees that time is negative, as follows:

Technology sharing | MySQL show processlist time is negative

2、 About time in show processlist

In fact, most of the information in show processlist comes from functionsmysqld_list_processesThat is to say, every time you execute show processlist, you need to execute this function to fill in. For the time value, it comes from the following information:

Percona:
time_t now= my_time(0);
protocol->store_long ((thd_info->start_time > now) ? 0 :  (longlong) (now - thd_info->start_time));
Official version:
time_t now= my_time(0);
protocol->store_long ((longlong) (now - thd_info->start_time));

We can notice that this output value is optimized in percona’s version, that is, if a negative number appears, it will be displayed as 0. However, this is not done in the official version, and negative numbers may appear.

3、 Interpretation and testing of calculation methods

Now let’s take a look at this simple calculation formula. In fact, now is the current time of the serverthd_info->start_timeWhere is the value of. The actual time comes from the functionTHD::set_timeHowever, it should be noted that this function will be overloaded in the following three ways:

Heavy load 1

inlinevoid 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);
...
}

Heavy load 2

 inlinevoid set_time(conststruct timeval *t)
 {
    start_time= user_time= *t;
    start_utime= utime_after_lock= my_micro_time();
...
}

Heavy load 3

void set_time(QUERY_START_TIME_INFO *time_info)
{
    start_time= time_info->start_time;
    start_utime= time_info->start_utime;
}

In fact, there is a start_ Utime, if start is set_ Utime then start_ Time will be specified as start_ Utime, and will start be modified in overload 1_ Time, this is more important. Well, three ways have been mentioned. Let’s look at the possibility of time calculation as follows.

1. Execute the order
If the main library executes common commands, it will call overload 1 and set start when the command is initiated_ Time is the time when the command starts to execute, as follows:

Stack:
#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

As you can see, this function has no arguments, so start_ Time will be set to the current time, and the calculation formula of that time is now – thdinfo – > start_ Time is equal to (server current time – the time the command started executing).

2. Single SQL thread and worker thread from the library

In fact, both single SQL thread and worker thread execute event. Here, start_ Time will be set to the timestamp time (query event / DML event) in the event header. This time is actually the time when the master database command is initiated. As follows:

Stack:
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

Stack:
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

We see that an argument is passed in here. Let’s take a look at the code as follows:

thd->set_time(&(common_header->when))

This is actually the line. This is the overload 3 we mentioned earlier, so set the post start_ Utime and start_ Time will be set, even if overload 1 is called, the calculation method of that time will not be changednow-thd_info->start_timeIt is equal to (the current time of the slave database server – the time in the event header), but you should know that the time in the event header actually comes from the time when the master database command is initiated. In this case, if the time of the slave database server is less than that of the master database server, the result of time may be negative. Of course, after the percona version is optimized, the negative number will be displayed as 0. If the time of the slave database server is greater than that of the master database server, the time may be larger. Because my test environment is percona, in order to achieve obvious results, let’s test the situation where the worker thread time is very large, as follows:

Main database:
[[email protected] test]# date
FriNov101:40:54 CST 2019

From library:
[[email protected] log]# date
TueNov1915:58:37 CST 2019

The main database randomly makes a command, and then observes as follows:

Technology sharing | MySQL show processlist time is negative

3. Set timestamp

If you specify timestamp manually, it will also affect the calculation result of time, because start_ Utime and start_ Time will be set as follows:

mysql> set timestamp=1572540000

Stack:
#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

We see that the arguments are brought in. Let’s look at the line of code as follows:

 thd->set_time(&tmp);

This is overload 2, so set the start_ Utime and start_ Time will be set, even if overload 1 is called, it will not change. The implication is that after setting timestamp, time will not be updated even if other commands are executed. The calculation method of time now – thdinfo > starttime is equal to (server current time – set timestamp time). In this case, time exceptions may occur, such as large or negative numbers (percona is 0), as follows:

Technology sharing | MySQL show processlist time is negative

4. Idle

If our session is idle, thennow-thd_info->start_timeIn the formula, now gets bigger and bigger, butthd_info->start_timeBut it doesn’t change, so the time keeps increasing and will not change until the next command arrives.

4、 Extension

Here, I want to explain that if it is opened from the librarylog_slave_updatesIn this case, the slave database records will record the events from the master database. However, how to value the timestamp of these events and the exit of query event?

Value of timestamp of event

In fact, I’ve already said that because of start_ Time will be set to the timestamp time (query event / DML event) in the event header. When Evnet is recorded, this time is basically the same as that of the main database, as follows:

Technology sharing | MySQL show processlist time is negative

Obviously, we will find that the time stamp of these events is not the local time, but the time of the main database.

Query event’s exit

Let’s take a look at the calculation of this time

ulonglong micro_ end_ time= my_ micro_ Time(); // get the time query event here
  my_micro_time_to_timeval(micro_end_time, &end_time);

  exec_ time= end_ time.tv_ sec - thd_ arg->start_ time.tv_ Sec; // time is calculated here

I believe thatthd_arg->start_timeIt is no longer strange, it is the time of the master database command. As I said in my series of in-depth understanding of master-slave principle, for the exit of query event, in the row format binlog, the DML statement will be the time when the first line of statement is modified. Then we make the following definition (DML statement in row format)::

  • Master: the server time when the first row of data in the main database is modified – the time when this command is initiated in the main database
  • Slave: the server time when the first line of data from the database is modified – the time when the command of the master database is initiated

The difference between them is: (the server time when the first row of data in the slave database is modified – the server time when the first row of data in the master database is modified) similarly, if the time of the slave database is far greater than the time of the master database, then the exception will occur in the execetime, as follows:

Technology sharing | MySQL show processlist time is negative

last:

Time is an indicator that we usually pay attention to. We often use it to indicate how long my statement has been executed. However, if there is an exception, we should be able to understand why. Here I give an incomplete explanation of its calculation method, hoping to be helpful to you. Of course, for the master-slave part or event part, you can refer to my “in-depth understanding of master-slave principle” series.

Recommended Today

Learn promise

Immediate execution of promise let p = new Promise(function(resolve, reject) { console.log (‘create a promise ‘) // it is executed immediately resolve(‘success’) } console.log(‘after new promise’) p.then(function(value) { console.log(value) }) Implementation results: ‘create a promise’ ‘after new promise’ ‘success’ Three states of promise Unfinished state pending, completed state resolved, failed state rejected var p1 = […]