Seconds_Behind_Master Spike at Log Rotation on Parallel Replica

When a parallel replica receives a Rotate_log_event or Format_description_event (e.g at rotation time), Seconds_Behind_Master can spike. This is since MDEV-10653, which changed how the parallel replica tracks the idleness of its worker threads, where now, the worker threads can appear busy, when they are in-fact idle.

When displaying Seconds_Behind_Master, the parallel slave has a special condition to override the value to 0 when the slave is idle. On a serial slave, this is simply checking the state of the SQL thread. On the parallel replica, the check also considers the state of the worker threads. If both the SQL thread and all worker threads are idle, then Seconds_Behind_Master is overridden to 0.

This is the code to check for idleness for Seconds_Behind_Master:

        idle= mi->rli.sql_thread_caught_up;

        /*

          The idleness of the SQL thread is needed for the parallel slave

          because events can be ignored before distribution to a worker thread.

          That is, Seconds_Behind_Master should still be calculated and visible

          while the slave is processing ignored events, such as those skipped

          due to slave_skip_counter.

        */

        if (mi->using_parallel() && idle &&

            !rpl_parallel::workers_idle(&mi->rli))

          idle= false;

Since commit 8dad51481b1 (MDEV-10653), the workers_idle() check compares the number of events queued to worker threads vs dequeued (i.e. completed). When the numbers match, the idea is that all worker threads are idle. Here is the code for workers_idle():

  return !rli->last_inuse_relaylog ||

    rli->last_inuse_relaylog->queued_count ==

    rli->last_inuse_relaylog->dequeued_count;

The queued_count variable is incremented at the end of rpl_parallel::do_event(), which is executed by the SQL thread to queue an event to a worker thread. The dequeued_count is incremented when a queued event is completed.

The reason Seconds_Behind_Master spikes is because there is a special condition in rpl_parallel::do_event() which executes {{Format_description_log_event}}s and {{Rotate_log_event}}s immediately by the SQL thread:

  else if (!is_group_event)

  {

    ...

    /*

      Events like ROTATE and FORMAT_DESCRIPTION. Do not run in worker thread.

      Same for events not preceeded by GTID (we should not see those normally,

      but they might be from an old master).

    */

    ...

    err= rpt_handle_event(qev, NULL);

and yet the queued_count is still incremented at the end of the function:

  /*

    Queue the event for processing.

  */

  qev->ir= rli->last_inuse_relaylog;

  ++qev->ir->queued_count;

  cur_thread->enqueue(qev);

This changes the workers_idle() check to incorrectly return as not-idle. This contradicts the behavior on the serial slave, where Format_description and Rotate events don't modify the replicas idleness condition.