Compared to previous situations like T370760: [toolsdb] ToolsToolsDBReplicationLagIsTooHigh - 2024-07-23 this looks a bit different:

• CPU usage is close to zero, so replication is not CPU-bound
• disk I/O is very low, so replication is not disk-bound
• SHOW ENGINE INNODB STATUS is static, no I/O and it's not creating thousands of row locks as it usually does when replicating this kind of mass-deletes:

---TRANSACTION 145653083611, ACTIVE 8396 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1
MariaDB thread id 12, OS thread handle 139991545382592, query id 14559920 Delete_rows_log_event::ha_delete_row(-1) on table `store_edit`
DELETE FROM `store_edit` WHERE (`store_edit`.`batch_id` = 1867223 AND `store_edit`.`newrevid` < 2075780282)

[...]

--------
FILE I/O
--------
Pending flushes (fsync) log: 0; buffer pool: 0
707083 OS file reads, 8404133 OS file writes, 107788 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s

That transaction eventually completed around 21:00 UTC, replication lag went down quickly for about 1 hour, then replication got stuck on another transaction around 22:00 UTC:

The new stuck transaction is:

|     13 | system user     |           | s55902__xlinkstest_p | Slave_worker |  47698 | Update_rows_log_event::ha_update_row(-1) on table `host` | UPDATE host SET hst_added_count = hst_added_count + 1 WHERE hst_id = 200561 |    0.000 |

That looks like a very simple query, and I can run SELECT * FROM host WHERE hst_id = 200561; with no issues.

I have no idea why the Slave_worker can not complete that update.

Full output of SHOW ENGINE INNODB STATUS:

Full output of SHOW SLAVE STATUS:

Raw binlog from the primary:

I will try to help with this more once I'm done with T386162: Some dewiktionary pageviews fatal "RevisionAccessException: Failed to load data blob from {address} for revision {revision}." but a couple of small things that comes to mind:

• A replica should basically never run into a deadlock or write concurrency latency. Replication is serial and no other script should be able to write to the replica (unless root) at the same time. Please make sure the replica is read only
• The query looks okay to me, it can be disk becoming suddenly slow for look ups
• Or, there are a LOT of updates like that happening.

I will try to debug more.

Thanks @Ladsgroup!

Please make sure the replica is read only

MariaDB [(none)]> SELECT @@read_only;
+-------------+
| @@read_only |
+-------------+
|           1 |
+-------------+

The query looks okay to me, it can be disk becoming suddenly slow for look ups

I also suspected slow disk (especially being Ceph), but IOPS is super low, and I can SELECT that record just fine...
CPU usage is also very low.

there are a LOT of updates like that happening

Possibly, but it's stuck on this single transaction since a few hours...

There must be an explanation, but I can't think of any!

I tried STOP SLAVE; and that was also hanging. I killed all replication threads with KILL 7; KILL 8; ... KILL 19; and in that way replication finally stopped:

MariaDB [(none)]> kill 19;
Query OK, 0 rows affected (0.001 sec)

MariaDB [(none)]> kill 20;
ERROR 1094 (HY000): Unknown thread id: 20
MariaDB [(none)]> SHOW PROCESSLIST;
+--------+-----------------+-----------+------+---------+--------+------------------------+------------------+----------+
| Id     | User            | Host      | db   | Command | Time   | State                  | Info             | Progress |
+--------+-----------------+-----------+------+---------+--------+------------------------+------------------+----------+
|      3 | event_scheduler | localhost | NULL | Daemon  | 157058 | Waiting on empty queue | NULL             |    0.000 |
| 262132 | root            | localhost | NULL | Query   |      0 | starting               | SHOW PROCESSLIST |    0.000 |
+--------+-----------------+-----------+------+---------+--------+------------------------+------------------+----------+
2 rows in set (0.000 sec)

CHECK TABLE and ANALYZE TABLE did not show any issue:

MariaDB [(none)]> CHECK TABLE s55902__xlinkstest_p.host EXTENDED;
+---------------------------+-------+----------+----------+
| Table                     | Op    | Msg_type | Msg_text |
+---------------------------+-------+----------+----------+
| s55902__xlinkstest_p.host | check | status   | OK       |
+---------------------------+-------+----------+----------+
1 row in set (9.550 sec)

MariaDB [(none)]> ANALYZE TABLE s55902__xlinkstest_p.host;
+---------------------------+---------+----------+----------+
| Table                     | Op      | Msg_type | Msg_text |
+---------------------------+---------+----------+----------+
| s55902__xlinkstest_p.host | analyze | status   | OK       |
+---------------------------+---------+----------+----------+
1 row in set (0.009 sec)

I restarted the whole process with sudo systemctl restart mariadb and replication resumed.

Let's see if it breaks again...

This is the journalctl log for the past hour, as I killed threads and restarted mariadb, nothing interesting there:

Replication caught up in about 2 hours, and seems to be working fine.

If the storage is over the network (you mentioned ceph) it's going to be quite a pain to maintain :( Maybe that can change or we should reduce the write volume somehow.

Storage have been over Ceph for a few years and it's mostly worked fine, but I agree we should reduce the write volume. I think the most effective way to do it is T291782: Migrate largest ToolsDB users to Trove.

In the meantime, replication got stuck again after working fine for a few hours:

SHOW PROCESSLIST shows a bunch of inserts on s53430__nppbrowser_p.article_new:

I tried capturing backtraces for the stuck threads:

fnegri@tools-db-5:~$ sudo gdb --batch --eval-command="set print frame-arguments all"  --eval-command="thread apply all bt full" /opt/wmf-mariadb106/bin/mysqld $(pgrep -xn mysqld)  > mariadbd_full_bt_all_threads.txt

Replication is now working again and I don't think the file generated by gdb contains any useful info, it looks like a snapshot of threads after replication resumed, with many idle threads and one thread applying a different transaction.

So either I was very unlucky and ran the gdb command a few seconds after replication resumed, or running the command itself caused the threads to get unstuck, or I'm not understanding how gdb works.

Let's see if replication gets stuck again or not in the next few days.

It did get stuck again, and running the same gdb command got it unstuck again.

SHOW PROCESSLIST before running gdb:

Replication worked from 19:00 UTC on Friday until 03:40 UTC on Saturday, then it got stuck again:

I didn't touch it over the weekend, it is still stuck on this INSERT query:

MariaDB [(none)]> SHOW PROCESSLIST;
|     13 | system user     |           | s55543__xlinks_p | Slave_worker | 114683 | Write_rows_log_event::write_row(-1) on table `revision` | INSERT INTO revision
        (
            rev_db,
            rev_revision,
            rev_user,
  |    0.000 |

Running gdb caused the replication to resume:

fnegri@tools-db-5:~$ sudo gdb --batch --eval-command="set print frame-arguments all"  --eval-command="thread apply all bt full" /opt/wmf-mariadb106/bin/mysqld $(pgrep -xn mysqld)  > mariadbd_full_bt_all_threads_3.txt

But this time it got stuck again after only a few minutes. This is the new stuck query:

|     19 | system user     |           | s51434__mixnmatch_p | Slave_worker |  15843 | Update_rows_log_event::ha_update_row(-1) on table `entry` | UPDATE `entry` SET `q`=99682705,`user`=0,`timestamp`='20250215075942' WHERE `id`=177820721 AND (`q`  |    0.000 |

I'm gonna try upgrading MariaDB to 10.6.20 on the replica.

tools-db-5 is now running MariaDB 10.6.20. I temporarily enabled additional logging (SET GLOBAL log_warnings = 3;), let's see if replication gets stuck again.