Bug #108892 MGR Sencondary node don`t appling relay logs
Submitted: 27 Oct 2022 1:47 Modified: 31 Oct 2022 1:13
Reporter: YUANHENG WANG Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:8.0.26 OS:CentOS (CentOS Linux release 7.6.1810)
Assigned to: MySQL Verification Team CPU Architecture:Any

[27 Oct 2022 1:47] YUANHENG WANG
Description:
In the MGR cluster of Sencondary node don`t appling relay logs,and the COUNT_TRANSACTIONS_REMOTE_IN_APPLIER_QUEUE has been growing,but there are no exceptions in the error log.
By command “show master status;”,The Executed_Gtid_Set result is unchanged ;
By Executed_Gtid_Set viewing the corresponding records in the relay_log, we find that the card is stuck in a simple update statement。

Other:
mysql> SELECT * FROM performance_schema.replication_group_members;
+---------------------------+--------------------------------------+-------------+-------------+--------------+-------------+----------------+
| CHANNEL_NAME              | MEMBER_ID                            | MEMBER_HOST | MEMBER_PORT | MEMBER_STATE | MEMBER_ROLE | MEMBER_VERSION |
+---------------------------+--------------------------------------+-------------+-------------+--------------+-------------+----------------+
| group_replication_applier | d4211fd2-4605-11ed-beaa-642fc7be0575 | 10.165.14.6 |        3308 | ONLINE       | PRIMARY     | 8.0.26         |
| group_replication_applier | d42937fd-4605-11ed-af09-642fc7befefd | 10.165.14.7 |        3308 | ONLINE       | SECONDARY   | 8.0.26         |
| group_replication_applier | d434a32d-4605-11ed-983f-642fc7beff65 | 10.165.14.8 |        3308 | ONLINE       | SECONDARY   | 8.0.26         |
+---------------------------+--------------------------------------+-------------+-------------+--------------+-------------+----------------+

mysql> SELECT MEMBER_ID AS id, COUNT_TRANSACTIONS_IN_QUEUE , COUNT_TRANSACTIONS_REMOTE_IN_APPLIER_QUEUE , COUNT_TRANSACTIONS_CHECKED , COUNT_TRANSACTIONS_REMOTE_APPLIED , COUNT_TRANSACTIONS_LOCAL_PROPOSED  FROM performance_schema.replication_group_member_stats;
+--------------------------------------+-----------------------------+--------------------------------------------+----------------------------+-----------------------------------+-----------------------------------+
| id                                   | COUNT_TRANSACTIONS_IN_QUEUE | COUNT_TRANSACTIONS_REMOTE_IN_APPLIER_QUEUE | COUNT_TRANSACTIONS_CHECKED | COUNT_TRANSACTIONS_REMOTE_APPLIED | COUNT_TRANSACTIONS_LOCAL_PROPOSED |
+--------------------------------------+-----------------------------+--------------------------------------------+----------------------------+-----------------------------------+-----------------------------------+
| d4211fd2-4605-11ed-beaa-642fc7be0575 |                           0 |                                          0 |                 2435802678 |                                 1 |                        2435802975 |
| d42937fd-4605-11ed-af09-642fc7befefd |                           0 |                                  288320140 |                 2435803803 |                        2147483663 |                                 0 |
| d434a32d-4605-11ed-983f-642fc7beff65 |                           0 |                                  288320142 |                 2435803803 |                        2147483661 |                                 0 |
+--------------------------------------+-----------------------------+--------------------------------------------+----------------------------+-----------------------------------+-----------------------------------+
3 rows in set (0.00 sec)

In secondary nodes:
mysql> show processlist;
+---------+-----------------+-----------------+------+---------+---------+-----------------------------------------------------+----------------------------------+
| Id      | User            | Host            | db   | Command | Time    | State                                               | Info                             |
+---------+-----------------+-----------------+------+---------+---------+-----------------------------------------------------+----------------------------------+
|       5 | event_scheduler | localhost       | NULL | Daemon  | 1710486 | Waiting on empty queue                              | NULL                             |
|      12 | system user     |                 | NULL | Connect | 1710484 | waiting for handler commit                          | Group replication applier module |
|      15 | system user     |                 | NULL | Query   |  249024 | Waiting for replica workers to process their queues | NULL                             |
|      16 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      17 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      18 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      19 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      20 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      21 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      28 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      29 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      30 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|      31 | system user     |                 | NULL | Query   |  249024 | Waiting for preceding transaction to commit         | NULL                             |
|     107 | fastxmsfinance  | 127.0.0.1:53924 | NULL | Sleep   |       1 |                                                     | NULL                             |
| 3531185 | msfinance       | 127.0.0.1:35420 | NULL | Query   |       0 | init                                                | show processlist                 |
+---------+-----------------+-----------------+------+---------+---------+-----------------------------------------------------+----------------------------------+

Other relevant variables:
mysql> show variables like '%order%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| binlog_order_commits          | ON    |
| replica_preserve_commit_order | ON    |
| slave_preserve_commit_order   | ON    |
+-------------------------------+-------+

At the server level, the mysqld with the highest CPU utilization through perf top is [Mts_submode_logical_clock::get_free_worker], as follows:
   6.85%  [kernel]                    [k] __schedule
   6.57%  mysqld                      [.] Mts_submode_logical_clock::get_free_worker
   6.10%  [kernel]                    [k] sysret_check
   5.30%  [kernel]                    [k] system_call_after_swapgs
   4.36%  [unknown]                   [k] 0x00007fa1245a7d45
   3.99%  [kernel]                    [k] native_sched_clock
   3.30%  [kernel]                    [k] update_curr
   3.26%  [kernel]                    [k] put_prev_task_fair
   3.05%  [kernel]                    [k] pick_next_task_fair
   2.77%  [kernel]                    [k] sys_sched_yield
   2.73%  [kernel]                    [k] intel_pstate_update_util
   2.62%  [kernel]                    [k] _raw_qspin_lock
   2.59%  [kernel]                    [k] _raw_qspin_lock_irq
   2.47%  bash                        [.] 0x000000000003e5c8
   ...

How to repeat:
Our continuous stress test of MGR version 8.0.26 passed sysbench.
The master node stress test command is as follows:
sysbench /usr/share/sysbench/oltp_read_write.lua --mysql-host=10.165.14.6 --mysql-port=3308 --mysql-user='xxxxx' --mysql-password='xxxxxxxxxxx' --mysql-db=sbtest --db-driver=mysql --tables=10  --table-size=1000000  --threads=300  --max-time=1800000000 --report-interval=10 run

The slavenode stress test command is as follows:
sysbench /usr/share/sysbench/oltp_point_select.lua --mysql-host=10.165.14.8 --mysql-port=3308 --mysql-user='xxxxx' --mysql-password='xxxxx' --mysql-db=sbtest --db-driver=mysql --tables=10  --table-size=1000000  --threads=20  --max-time=1800000 --report-interval=10 run

We reproduced this issue after about 6 days of stress testing.
After this problem issue, stop the stress test, COUNT_TRANSACTIONS_REMOTE_IN_APPLIER_QUEUE still does not change, the value is still very large.
[27 Oct 2022 1:48] YUANHENG WANG
In secondary nodes:   
show engine innodb status\G
...
------------
TRANSACTIONS
------------
Trx id counter 4878419587
Purge done for trx's n:o < 4425835995 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421828993875160, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421828993876776, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421828993875968, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421828993874352, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421828993873544, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 4425544340, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 22, OS thread handle 140353693693696, query id 47946174454 Waiting for preceding transaction to commit
---TRANSACTION 4425544339, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 19, OS thread handle 140353694578432, query id 47946174478 Waiting for preceding transaction to commit
---TRANSACTION 4425544338, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 21, OS thread handle 140353693988608, query id 47946174499 Waiting for preceding transaction to commit
---TRANSACTION 4425544337, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 18, OS thread handle 140353694873344, query id 47946174481 Waiting for preceding transaction to commit
---TRANSACTION 4425544336, ACTIVE (PREPARED) 250309 sec
7 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 20, OS thread handle 140353694283520, query id 47946174456 Waiting for preceding transaction to commit
---TRANSACTION 4425544335, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 17, OS thread handle 140353695168256, query id 47946174475 Waiting for preceding transaction to commit
---TRANSACTION 4425544334, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 16, OS thread handle 140353695463168, query id 47946174445 Waiting for preceding transaction to commit
---TRANSACTION 4425544326, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 26, OS thread handle 140352760985344, query id 47946174426 Waiting for preceding transaction to commit
---TRANSACTION 4425544322, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 31, OS thread handle 140352759510784, query id 47946174216 Waiting for preceding transaction to commit
---TRANSACTION 4425544321, ACTIVE (PREPARED) 250309 sec
7 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 25, OS thread handle 140352761280256, query id 47946174164 Waiting for preceding transaction to commit
---TRANSACTION 4425544319, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 23, OS thread handle 140353693398784, query id 47946174198 Waiting for preceding transaction to commit
---TRANSACTION 4425544318, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 28, OS thread handle 140352760395520, query id 47946174172 Waiting for preceding transaction to commit
---TRANSACTION 4425544317, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 30, OS thread handle 140352759805696, query id 47946174151 Waiting for preceding transaction to commit
---TRANSACTION 4425544314, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 29, OS thread handle 140352760100608, query id 47946174168 Waiting for preceding transaction to commit
---TRANSACTION 4425544313, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 27, OS thread handle 140352760690432, query id 47946174220 Waiting for preceding transaction to commit
---TRANSACTION 4425544311, ACTIVE (PREPARED) 250309 sec
8 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 5
MySQL thread id 24, OS thread handle 140353693103872, query id 47946174146 Waiting for preceding transaction to commit
--------

...
[28 Oct 2022 7:13] YUANHENG WANG
When the issue occurs, the execution of "stop group_replication" fails, the error is: ERROR 3095 (HY000) at line 1: The STOP GROUP_REPLICATION command execution is incomplete: The applier thread got the stop signal while it was busy. The applier thread will stop once the current task is complete.
Log Print :[ERROR] [MY-011654] [Repl] Plugin group_replication reported: 'On shutdown there was a timeout on the Group Replication applier termination.'

We suspect that the Mts_submode_logical_clock::get_free_worker function is stuck in an endless loop here, and it can't get the idle worker thread. Checking the worker threads status by showing "engine innodb status\G" is: "Waiting for preceding transaction to commit". So we set the variable slave_preserve_commit_order to off and start the stress test again.
[28 Oct 2022 15:10] MySQL Verification Team
Hi,

I cannot reproduce this with 8.0.31, can you reproduce this with 8.0.31?

thanks
[31 Oct 2022 1:13] YUANHENG WANG
Hi,
We can't follow the version upgrade every time GA is released, and the version currently used on a large scale online is 8.0.26.
You can try to perform a stress test in version 8.0.26, which can be repeated
[31 Oct 2022 3:32] MySQL Verification Team
Hi,

> We can't follow the version upgrade every time GA is released, 
> and the version currently used on a large scale online is 8.0.26.

Noone is asking you to, but if 8.0.26 is affected and 8.0.31 is not affected there is really nothing you can do but upgrade, there is no way to fix a bug without upgrading.

As I said, I'm having issues reproducing the problem. And since you say you can reproduce it I'm asking if you can also reproduce it with 8.0.31. Running a test for 6 days means that there is only a "chance" of reproducing the problem, since you reproduced it twice it makes sense that you try to reproduce on 8.0.31 if I cannot as maybe on my setup it takes 12 days and I'll stop at 11th day as I can't reproduce it.

> You can try to perform a stress test in version 8.0.26, which can be repeated

Yes, I have tried, as a matter of fact I still have the test on 8.0.26 running and I'm not reproducing it yet, this is why I cannot say for sure that 8.0.31 is not affected and that upgrade would solve a problem as if I reproduced with 8.0.26 and not with 8.0.31 I'd be pretty convinced, but since I cannot reproduce with 8.0.26 I cannot assume anything. I still have both 8.0.26 and 8.0.31 running but I will soon have to stop the tests as I cannot wait indefinitely.