4

I understand there are lots of similar problems and threads but non of those solution helped me. Please read through the thread I will try to give as much information as possible:

I have setup a replication process 3 days ago and after day 1 it is stuck. Replication is multithreaded by default as I am using MySQL 8.0.31. The container has enough space so this is not a space issue.

Stack Information

  • MySQL 8.0.31
  • Kubernetes
  • Implemented via bitnami/helm chart.

show slave status \G;

*************************** 1. row ***************************
               Slave_IO_State: Waiting for source to send event
                  Master_Host: mysql-backend-primary
                  Master_User: replicator
                  Master_Port: 3306
                Connect_Retry: 10
              Master_Log_File: mysql-bin.000057
          Read_Master_Log_Pos: 95082376
               Relay_Log_File: mysql-relay-bin.000011
                Relay_Log_Pos: 39868588
        Relay_Master_Log_File: mysql-bin.000004
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 39868372
              Relay_Log_Space: 5522859222
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 177253
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 424
                  Master_UUID: 071b41fc-90d3-11ed-9d2d-4e20f425bc3e
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Waiting for replica workers to process their queues
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set: 
            Executed_Gtid_Set: 
                Auto_Position: 0
         Replicate_Rewrite_DB: 
                 Channel_Name: 
           Master_TLS_Version: 
       Master_public_key_path: 
        Get_master_public_key: 0
            Network_Namespace: 
1 row in set, 1 warning (0.03 sec)

Notable Points:

Relay_Log_File: mysql-relay-bin.000011
Relay_Log_Pos: 39868588
Relay_Master_Log_File: mysql-bin.000004

All of those 3 values are stuck. Seconds_Behind_Master: 177253 which is almost 48 hours.

show processlist;

+----+-----------------+-----------------+------+---------+--------+-----------------------------------------------------+------------------+
| Id | User            | Host            | db   | Command | Time   | State                                               | Info             |
+----+-----------------+-----------------+------+---------+--------+-----------------------------------------------------+------------------+
|  5 | system user     | connecting host | NULL | Connect |    846 | Waiting for source to send event                    | NULL             |
|  6 | system user     |                 | NULL | Query   |    846 | Waiting for replica workers to process their queues | NULL             |
|  7 | system user     |                 | NULL | Query   | 177455 | Waiting for an event from Coordinator               | NULL             |
|  8 | event_scheduler | localhost       | NULL | Daemon  |    846 | Waiting on empty queue                              | NULL             |
|  9 | system user     |                 | NULL | Connect |    846 | Waiting for an event from Coordinator               | NULL             |
| 11 | system user     |                 | NULL | Connect |    846 | Waiting for an event from Coordinator               | NULL             |
| 13 | system user     |                 | NULL | Connect |    846 | Waiting for an event from Coordinator               | NULL             |
| 15 | root            | localhost       | NULL | Query   |      0 | init                                                | show processlist |
+----+-----------------+-----------------+------+---------+--------+-----------------------------------------------------+------------------+

4 threads are stuck with message Waiting for an event from Coordinator.

My Guess for the problem is, each worker thread is trying to do the transaction in sequence. One transaction is stuck (#7) so all others are waiting for the first one to finish.

SHOW ENGINE INNODB STATUS;

You will get more information here as well.

*************************** 1. row ***************************
  Type: InnoDB
  Name: 
Status: 
=====================================
2023-01-12 13:08:27 139783888148224 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 19 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 257 srv_active, 0 srv_shutdown, 12746 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2414
OS WAIT ARRAY INFO: signal count 2357
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 421692
Purge done for trx's n:o < 421692 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421259917660104, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421259917659296, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421259917658488, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421259917657680, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421259917656872, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421259917656064, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421259917654448, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421259917653640, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421170, ACTIVE 13123 sec
3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1
MySQL thread id 8, OS thread handle 139784416626432, query id 3 Waiting for an event from Coordinator
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
1890 OS file reads, 4568 OS file writes, 3254 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 2 merges
merged operations:
 insert 2, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 5 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 10 buffer(s)
Hash table size 34679, node heap has 17 buffer(s)
Hash table size 34679, node heap has 5 buffer(s)
Hash table size 34679, node heap has 9 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number          506082064
Log buffer assigned up to    506082064
Log buffer completed up to   506082064
Log written up to            506082064
Log flushed up to            506082064
Added dirty pages up to      506082064
Pages flushed up to          506082064
Last checkpoint at           506082064
Log minimum file id is       154
Log maximum file id is       154
1157 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 659708
Buffer pool size   8192
Free buffers       6102
Database pages     2038
Old database pages 732
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 329, not young 42007
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1862, created 176, written 2412
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 2038, unzip_LRU len: 0
I/O sum[10]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=1, Main thread ID=139784441804544 , state=sleeping
Number of rows inserted 1, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 8, updated 593, deleted 8, read 6424
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Notable Point:

See the last transaction in the list?

---TRANSACTION 421170, ACTIVE 13123 sec
3 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1
MySQL thread id 8, OS thread handle 139784416626432, query id 3 Waiting for an event from Coordinator

Log from MySQL Slave Server

2023-01-12T13:21:00.595774Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /tmp/mysqlx.sock
2023-01-12T13:21:00.605842Z 5 [System] [MY-010562] [Repl] Slave I/O thread for channel '': connected to master 'replicator@mysql-backend-primary:3306',replication started in log 'mysql-bin.000057' at position 74086691
2023-01-12T13:21:00.680418Z 5 [Warning] [MY-010445] [Repl] QUERY(COMMIT or ROLLBACK) or XID_LOG_EVENT is not expected in an event stream outside a transaction.
2023-01-12T13:21:00.681242Z 5 [Warning] [MY-010590] [Repl] An unexpected event sequence was detected by the IO thread while queuing the event received from master 'mysql-bin.000057' binary log file, at position 74087325.

Resources

  1. Related read of similar (same?) problem: https://bugs.mysql.com/bug.php?id=73066 but the thread suggests that bug was fixed.

Update

Running STOP SLAVE; command just hangs the command line until I press ctrl + c to exit.

Improve this question
4
  • Try this: STOP SLAVE; START SLAVE;
    – Rick James
    Jan 12 at 21:23
  • @RickJames as I said in the Q, running STOP SLAVE hangs the terminal.
    – Sisir
    Jan 13 at 8:58
  • I have the exact same issue on 8.0.32 when having multiple replication source. Did you ever find a solution ?
    – Odubuc
    Mar 31 at 15:59
  • I have not unfortunately. I have disabled slave since then.
    – Sisir
    Apr 1 at 18:48

0

Reset to default

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.