Shulou(Shulou.com)05/31 Report--

How to understand that Worker threads see negative Time in MTS. In view of this problem, this article introduces the corresponding analysis and solution in detail, hoping to help more partners who want to solve this problem to find a more simple and easy way.

I. the source of the problem

This is a question asked by a friend of mine. The question is as follows: how does the Worker thread see a negative Time in MTS, as follows:

2. About Time in show processlist

In fact, the information in show processlist basically comes from the function mysqld_list_processes, which means that every time you execute show processlist, you need to execute this function to populate it. 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 has been optimized in the Percona version, that is, if a negative number is directly displayed as 0, but not in the official version, a negative number may occur.

III. Interpretation and testing of calculation methods

Now let's take a look at this simple calculation formula. In fact, now is easy to understand is the current time of the server, and the focus is on where the value of thd_info- > start_time comes from.

The actual time comes from the function THD::set_time, but it should be noted that this function is overloaded in the following three ways:

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

Overload 2

Inline void set_time (const struct timeval * t) {start_time= user_time= * t; start_utime= utime_after_lock= my_micro_time ();...}

Overload 3

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

In fact, to put it simply, there is a start_utime. If start_utime is set, then start_time will be specified as start_utime, and it is important whether the start_time will be modified in overload 1.

Now that we've talked about three ways, let's take a look at the following possibilities for Time's calculation.

1. Execute orders

If the master library executes common commands that call overload 1 when the command is initiated, set start_time to the time when the command starts execution 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

You can see that this function has no arguments, so start_time is set to the current time, so the calculation formula now-thd_info- > start_time of Time is equal to (the current time of the server-the time when the command starts to execute).

2. From the library single Sql thread and Worker thread

In fact, no matter whether a single Sql thread or a Worker thread executes Event, the start_time here will be set to the time of timestamp in Event header (query event/dml event), which is actually the time when the main library command was 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 there is an argument passed in here. Let's take a look at the code as follows:

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

This is actually the line, which is the overload 3 we mentioned earlier. After this setting, both start_utime and start_time will be set, and even if overload 1 is called, it will not change, so the calculation method of Time now-thd_info- > start_time is equal to (the current time of the slave server-the time in Event header), but you should know that the time in Event header actually comes from the time when the master database command was initiated. Since this is the case, if the time of the slave server is less than that of the master server, then the result of Time may be negative. Of course, the negative number of the Percona version will be displayed as 0. If the time of the slave server is longer than that of the master server, you may see that the Time is larger.

Because my test environment is Percona, in order to achieve obvious results, let's test the large case of Worker thread Time, as follows:

Master Library: [root@mysqltest2 test] # dateFri Nov 1 01:40:54 CST 2019 Slave Library: [root@gp1 log] # date Tue Nov 19 15:58:37 CST 2019

Make a random command in the main library, and then observe as follows:

3. Set timestamp

If you specify timestamp manually, it will also affect the calculation result of Time, because both 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 argument has been brought in. Let's take a look at the code line as follows:

Thd- > set_time (& tmp)

This is overload 2. After this setting, both start_utime and start_time will be set. Even if overload 1 is called, it will not be changed. The implication is that Time will not be updated even if other commands are executed after timestamp is set. The calculation method of Time: now-thd_info- > start_time is equal to (server current time-set timestamp time). In this case, an exception may occur in Time, such as a large or negative number (Percona is 0):

4. When you are idle

If our session is idle, then in the now-thd_info- > start_time formula, the now will grow, but the thd_info- > start_time will not change, so the Time will grow until the next command arrives.

IV. Extension

Here I would like to explain that if log_slave_updates is enabled in the slave library, the slave record will record the Event from the master library, but how do the timestamp of these Event and the exetime of Query Event be valued?

The value of timestamp of Event

In fact, I have already mentioned above, because start_time will be set to the time (query event/dml event) of timestamp in Event header, which is basically the same as the main library when recording Evnet, as follows:

Obviously we will find that the timestamp of these Event is not the local time, but the time of the main library.

Exetime of Query Event

Let's first take a look at how this time is calculated:

Ulonglong micro_end_time= my_micro_time (); / / get the time query event my_micro_time_to_timeval (micro_end_time, & end_time) here; exec_time= end_time.tv_sec-thd_arg- > start_time.tv_sec;// calculate the time here

I believe that it is no longer new to thd_arg- > start_time, it is the time when the main library command was initiated. As I said in my "in-depth understanding of the Master-Slave principle" series, for Query Event's exetime in row format binlog, the DML statement will be the modification time of the first line of statements, so let's define it as follows (row format DML statement):

Master: the server time when the first row of data in the main database was modified-the time when this command was initiated in the main database

From: the server time when the data was modified from the first row of the library-the time when this command was initiated in the main library

The difference between them is:

(server time for data modification from the first row of the library-server time for data modification for the first row of the main library)

Similarly, if we spend much more time from the library than the main database, the exetime will also have the following exception:

Time is an indicator that we usually pay attention to, and we often use it to indicate how long my statement has been executed, but if there is an exception, we should also be able to understand why. Here I give an incomplete explanation of its calculation.

This is the answer to the question about how to understand how Worker threads see negative Time in MTS. I hope the above content can be of some help to you. If you still have a lot of doubts to be solved, you can follow the industry information channel for more related knowledge.

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.