Why Seconds_Behind_Master is still 0 when MySQL synchronization delay occurs

Problem Description

The user performed an alter operation on the primary database, which lasted for about an hour. After the operation is completed, the slave database finds that there is a synchronization delay, but the Seconds_Behind_Master indicator in the monitoring chart shows 0, and the delay distance of the binlog is constantly increasing.

Principle Analysis

Since we are analyzing the delay time, we naturally start with how to calculate the delay. For convenience, the source code of the official version 5.7.31 is quoted here for reading. Find the code for calculating the delay time:

./sql/rpl_slave.cc

bool show_slave_status_send_data(THD *thd, Master_info *mi,
                                 char* io_gtid_set_buffer,
                                 char* sql_gtid_set_buffer)
......
if ((mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()) &&
        (!strcmp(mi->get_master_log_name(), mi->rli->get_group_master_log_name())))
    {
      if (mi->slave_running == MYSQL_SLAVE_RUN_CONNECT)
        protocol->store(0LL);
      else
        protocol->store_null();
    }
    else
    {
      long time_diff = ((long)(time(0) - mi->rli->last_master_timestamp)
                       - mi->clock_diff_with_master);

      protocol->store((longlong)(mi->rli->last_master_timestamp ?
                                   max(0L, time_diff) : 0));
    }
......

From the calculation method of time_diff, we can find that this delay is basically a time difference, and then the time difference between the master and the slave is calculated. However, there are a lot of if statements, so I will use the comments in the source code file:

  /*
     The pseudo code to compute Seconds_Behind_Master:
     if (SQL thread is running)
     {
       if (SQL thread processed all the available relay log)
       {
         if (IO thread is running)
            print 0;
         else
            print NULL;
       }
        else
          compute Seconds_Behind_Master;
      }
      else
       print NULL;
  */

It can be seen that the calculation of Seconds_Behind_Master is divided into two parts:

• When the SQL thread is normal and all relaylogs are played back, and if the IO thread is normal, then it is directly set to 0.
• When the SQL thread is normal and all relaylogs are played back, if the IO thread is not normal, then set NULL directly.
• When the SQL thread is normal and not all relaylogs have been replayed, the delay time is calculated.
  

Then when calculating the delay time at the end, take a look at the meaning of those variables:

• time(0): current timestamp, in timestamp format.
• last_master_timestamp: The time when this event is executed on the master database, in timestamp format.
• clock_diff_with_master: The time difference between slave and master, obtained when the IO thread starts.
  

It can be seen that when calculating the delay, the value is actually obtained by subtracting the time when the replayed event is executed on the master from the local time of the slave, and then compensating for the time difference between the two. Logically, there is no problem. Since time(0) and clock_diff_with_master have no chance of going wrong most of the time, the problem this time should be with last_master_timestamp.

PS: Although there is no problem most of the time, time(0) takes the local time. Therefore, if there is a problem with the slave's local time, the final value will also be wrong, but it is not within the scope of this case.

Then find the logic of calculating last_master_timestamp when executing the event. Combined with the comments, we can find that ordinary replication and parallel replication use different calculation methods. The first is ordinary replication, and the calculation time point is before the execution of the event:

./sql/rpl_slave.cc

......
  if (ev)
  {
    enum enum_slave_apply_event_and_update_pos_retval exec_res;

    ptr_ev= &ev;
    /*
      Even if we don't execute this event, we keep the master timestamp,
      so that seconds behind master shows correct delta (there are events
      that are not replayed, so we keep falling behind).

      If it is an artificial event, or a relay log event (IO thread generated
      event) or ev->when is set to 0, or a FD from the master, or a heartbeat
      event with server_id '0' then we don't update the last_master_timestamp.

      In case of parallel execution last_master_timestamp is only updated when
      a job is taken out of GAQ. Thus when last_master_timestamp is 0 (which
      indicates that GAQ is empty, all slave workers are waiting for events from
      the Coordinator), we need to initialize it with a timestamp from the first
      event to be executed in parallel.
    */
    if ((!rli->is_parallel_exec() || rli->last_master_timestamp == 0) &&
         !(ev->is_artificial_event() || ev->is_relay_log_event() ||
          (ev->common_header->when.tv_sec == 0) ||
          ev->get_type_code() == binary_log::FORMAT_DESCRIPTION_EVENT ||
          ev->server_id == 0))
    {
      rli->last_master_timestamp = ev->common_header->when.tv_sec +
                                  (time_t) ev->exec_time;
      DBUG_ASSERT(rli->last_master_timestamp >= 0);
    }
......

The value of last_master_timestamp is the start time of the event plus the execution time. In 5.7, many events did not have the execution time value. 8.0 adds this value to many events, so it can be regarded as a benefit brought by upgrading to 8.0.

The calculation method of parallel replication is as follows:

./sql/rpl\_slave.cc

......
  /*
    We need to ensure that this is never called at this point when
    cnt is zero. This value means that the checkpoint information
    will be completely reset.
  */

  /*
    Update the rli->last_master_timestamp for reporting correct Seconds_behind_master.

    If GAQ is empty, set it to zero.
    Else, update it with the timestamp of the first job of the Slave_job_queue
    which was assigned in the Log_event::get_slave_worker() function.
  */
  ts = rli->gaq->empty()
    ? 0
    : reinterpret_cast<Slave_job_group*>(rli->gaq->head_queue())->ts;
  rli->reset_notified_checkpoint(cnt, ts, need_data_lock, true);
  /* end-of "Coordinator::"commit_positions" */

......

In the commit_positions logic of the Coordinator, if the gaq queue is empty, last_master_timestamp is directly set to 0, otherwise the timestamp of the first job in the gaq queue is selected. It should be added that this calculation is not real-time, but intermittent. Before the calculation logic, there is the following logic:

  /*
    Currently, the checkpoint routine is being called by the SQL Thread.
    For that reason, this function is called call from appropriate points
    in the SQL Thread's execution path and the elapsed time is calculated
    Here to check if it is time to execute it.
  */
  set_timespec_nsec(&curr_clock, 0);
  ulonglong diff = diff_timespec(&curr_clock, &rli->last_clock);
  if (!force && diff < period)
  {
    /*
      We do not need to execute the checkpoint now because
      the time elapsed is not enough.
    */
    DBUG_RETURN(FALSE);
  }

That is, within the time interval of this period, it will directly return and will not update the last_master_timestamp. Therefore, sometimes you will find that the value of Seconds_Behind_Master changes from 0 to 1 from time to time in parallel replication.

The operation of the gaq queue is probably similar to the stack push and pop operations, so the transactions left in gaq are always unfinished transactions. Therefore, time calculation is fine from the perspective of general scenarios.

Problem Analysis

The principle analysis briefly explains the logic of the entire calculation. Now let's get back to the question itself. Tencent Cloud Database MySQL has parallel replication enabled by default, so there will be a gaq queue, and the alter operation takes a very long time. Regardless of whether the alter operation will be executed in a group of parallel transactions (most likely, DDL is always a separate transaction group), the gaq queue will eventually be empty, and last_master_timestamp will be set to 0. Referring to the calculation logic of Seconds_Behind_Master, the final time_diff will also be set to 0, so the delay time before the alter operation ends will always be 0. After the alter operation is executed, the gaq queue will be filled with new events and transactions, so the delay may be 0 before, but suddenly jump to a very high value.

Expand

Comparing the differences in the calculation methods between ordinary replication and parallel replication, we can know the following characteristics:

• After enabling parallel replication, the delay time will frequently jump between 0 and 1.
• Alter operations and single large transactions are prone to inaccurate delays in parallel replication scenarios, while ordinary replication does not.
• Since the master-slave time difference is calculated when the IO thread is started, if the slave time deviates during this period, the delay time will also deviate.

To sum up

For rigorous delay judgment, it is better to rely on the GTID gap and the binlog position gap. Judging from the changes in event execution time in 8.0, at least Oracle officials are still working hard. I hope these minor problems can be fixed as soon as possible.

The above is the detailed content of why Seconds_Behind_Master is still 0 when MySQL synchronization delay occurs. For more information about MySQL synchronization delay Seconds_Behind_Master is 0, please pay attention to other related articles on 123WORDPRESS.COM!