STEPS TO REPRODUCE THE ISSUE:

== Set up replication between two MariaDB servers (running on 10.2.38)
== I do not have any other query running on the DB.
== On the "Primary" server, repeatedly flush the binary logs:
I did something like this:
flush binary logs;show binary logs;select now(),sleep(0.25);flush binary logs;show binary logs;select now(),sleep(0.25)... .... .... .... ... ...

== On the "replica" server, repeatedly monitor the seconds behind master by running "show slave status\G"

== I have grepped the output to show only the required details. Pasting a part of it below:

Looking at the binary logs of the "Primary" instance corresponding to "Relay_Master_Log_File" and "Exec_Master_Log_Pos", I can just see that its the starting of the file (immediately after rotation of older file).

MASTER> show binlog events in 'mysql-bin-changelog.000455';

+----------------------------+-----+-------------------+-----------+-------------+------------------------------------------------+

| Log_name                   | Pos | Event_type        | Server_id | End_log_pos | Info                                           |

+----------------------------+-----+-------------------+-----------+-------------+------------------------------------------------+

| mysql-bin-changelog.000455 |   4 | Format_desc       |       123 |         256 | Server ver: 10.2.38-MariaDB-log, Binlog ver: 4 |

| mysql-bin-changelog.000455 | 256 | Gtid_list         |       123 |         299 | [0-123-1]                                      |

| mysql-bin-changelog.000455 | 299 | Binlog_checkpoint |       123 |         352 | mysql-bin-changelog.000454                     |

| mysql-bin-changelog.000455 | 352 | Binlog_checkpoint |       123 |         405 | mysql-bin-changelog.000455                     |

| mysql-bin-changelog.000455 | 405 | Rotate            |       123 |         462 | mysql-bin-changelog.000456;pos=4               |

+----------------------------+-----+-------------------+-----------+-------------+------------------------------------------------+

5 rows in set (0.00 sec)

—
Another important observation is that the "seconds behind master" value keeps increasing.
You can refer the above output itself. Each time wrong value is returned, it is greater than the previous value.

bnestere, could you please verify whether the description fits to the fixed MDEV-16091?

It was possible to reproduce this with 10.2.38 by following the steps in the first comment and using a script to output SHOW SLAVE STATUS\G to a file in an infinite loop until manually killed. Grepping for "Slave_SQL_Running_State: Reading event from the relay log" would sometimes show Seconds_Behind_Master as a value on the order of hundreds or thousands of seconds, and always increasing, as described.

The issue no longer appears in 10.2.42, and testing showed that commit 96de6bf did not have the behavior, while the parent commit 452c9a4 still had the issue.

Re-opening as this was not initially reproducible, but later investigation shows the issue is still present.

Approaches suggested during today’s Replication weekly:

• Deduce the idleness based on the I/O and SQL threads’ positions (e.g., as in the description, GTID_IO_Pos == GTID_Slave_Pos, assuming GTIDs are on)
  • Problem: Positions alone cannot tell what’s “internal” (MDEV-16091) and what’s not.
• Internals skip flagging the non-idle state but do update the timestamp
  • I don’t think it matters, for the next non-internal event will overwrite the timestamp when it flags non-idle anyway.

ParadoxV5 thanks for summarizing!

The second point

Internals skip flagging the non-idle state but do update the timestamp

is a little off of the idea. It should actually be:

• for internal events that come from the master: update both 1) the timestamp and 2) the non-idle state (in such a way that there wouldn't be a spike in SBM (Seconds_Behind_Master in-between these updates).
• for internal events that come from the IO thread (flagged as is_relay_log_event() or is_artificial_event()): neither update the timestamp nor the idle state.

Though this adds even more complexity to the Seconds_Behind_Master calculation . As the code currently sits, we don't update the timestamp for internal events ever, but we do update the idleness. I think the simplest (and probably most consistent solution) would probably be to just not update idleness for internal events either (regardless of source). This would also leave existing behavior alone as to what is actually reported by Seconds_Behind_Master (so users wouldn't start seeing the value updating when it previously hadn't). Note too, the comment

        /*

          Ignore FD's timestamp as it does not reflect the slave execution

          state but likely to reflect a deep past.

...

which re-enforces the idea that the timestamp should be reflective of the slave execution state.

As the code currently sits, we don't update the timestamp for internal events ever, but we do update the idleness.

Of the 3 places that remove the idle state (sql_thread_caught_up= false), except for the one that’s part of error handling (probably unnecessary), the other two are both guarded under event_can_update_last_master_timestamp() together with the timestamp update.
In short: The current code neither updates the timestamp nor the idleness for internal events, as of MDEV-16091. Which is

• for internal events that come from the IO thread (flagged as is_relay_log_event() or is_artificial_event()): neither update the timestamp nor the idle state.

It’s uncomfortable to say, but bnestere, I doubt your analysis is it.

11.4 doesn’t look like having a regression either, and now I’m out of ideas.

The issue description does not reproduce the bug (if there is one).
The Seconds_Behind_Master increase reported is not from a Format Description Event alone, but rather originates from its preceding event (in this case, an INSERT).
With this addition to the provided draft MTR test:

@@ -33,11 +33,23 @@ set debug_sync="now wait_for paused_on_fde";

 set debug_sync="now signal sql_thread_continue";

 --source include/sync_with_master_gtid.inc

+--echo # Pause the upcoming INSERT without needing debug_sync

+LOCK TABLE t1 WRITE NOWAIT;

+--echo # Add a non-format description event

+--connection master

+INSERT INTO t1 VALUES (2);

+

 --echo # Rotate master binary logs to force sql thread to read internal only events

 --connection master

 FLUSH LOGS;

 --connection slave

+--echo # Wait 3s so SBM has a chance to increase..

+--sleep 3

+--echo # Seconds_Behind_Master should not be zero as user events are not up-to-date

+--let $status_items= Seconds_Behind_Master

+--source include/show_slave_status.inc

+UNLOCK TABLES;

 --echo #

 --echo # Skip through format description events from relay log file & master

Seconds_Behind_Master will show (at least) 3 before the pause on the last Format Description Event and (at least) 5 after.
It’s intended that:

• The (new) INSERT starts the increase – that’s part of Seconds_Behind_Master’s responsibilities.
• The Format Description Event does not decrease Seconds_Behind_Master, as the state does not know whether there’re more events to come and should not preëmptively reset it.