What is event queue process after IST/SST and how we can optimise it

MySQL & MariaDB Percona Server for MySQL 8.0
1

Hi team,

We are in the process of migrating from 5.7 to 8.0. The v8 cluster is attached as a slave to the v5.7 cluster, which is the master - done via binlog replication. This part works fine.

The “new” part for us is that once a node from the v8 cluster leaves and re-joins there is now an additional step after IST, before transitioning in a synced state. That new step is “Processing event queue”. On a busy cluster this new step may take hours. We have tried looking into what this new process is, but at this stage we cannot identify it in the documentation.

We are investigating this event queue, because it has raised dramatically the time for a re-joiner node to get fully synced. On a busy day, during a 5 minute disconnect of a single node, after rejoining this used to take less than 5 minutes. Now it takes more than 30 minutes.

The examples are taken at a time where there is not much load on the cluster. But under load the event queue takes much, much longer to process.
I cannot attach the full logs due to being a new user apparently. But here are some excerpts:

...........
2024-02-21T07:58:56.850107Z 18 [Note] [MY-000000] [WSREP] Recovered cluster id 884c986a-baba-11ee-bdcd-b2d06fd23cb6
2024-02-21T07:58:57.127213Z 3 [Note] [MY-000000] [Galera] SST received: 884c986a-baba-11ee-bdcd-b2d06fd23cb6:239315263
2024-02-21T07:58:57.127245Z 3 [System] [MY-000000] [WSREP] SST completed
2024-02-21T07:58:57.127262Z 1 [Note] [MY-000000] [Galera]  str_proto_ver_: 3 sst_seqno_: 239315263 cc_seqno: 239354076 req->ist_len(): 79
2024-02-21T07:58:57.127301Z 1 [Note] [MY-000000] [Galera] Installed new state from SST: 884c986a-baba-11ee-bdcd-b2d06fd23cb6:239315263
2024-02-21T07:58:57.298147Z 1 [Note] [MY-000000] [Galera] Receiving IST: 38813 writesets, seqnos 239315264-239354076
2024-02-21T07:58:57.298216Z 0 [Note] [MY-000000] [Galera] ####### IST applying starts with 239315264
2024-02-21T07:58:57.298264Z 0 [Note] [MY-000000] [Galera] ####### IST current seqno initialized to 239315264
2024-02-21T07:58:57.298310Z 0 [Note] [MY-000000] [Galera] Receiving IST...  0.0% (    0/38813 events) complete.
2024-02-21T07:58:57.298320Z 0 [Note] [MY-000000] [Galera] ####### Passing IST CC 239315264, must_apply: 1, preload: false
2024-02-21T07:58:57.298343Z 0 [Note] [MY-000000] [Galera] First IST (CC) event for rebuilding cert index
2024-02-21T07:58:57.298354Z 0 [Note] [MY-000000] [Galera] REPL Protocols: 10 (5)
2024-02-21T07:58:57.298383Z 0 [Note] [MY-000000] [Galera] Service thread queue flushed.
2024-02-21T07:58:57.298422Z 0 [Note] [MY-000000] [Galera] ####### Assign initial position for certification: 884c986a-baba-11ee-bdcd-b2d06fd23cb6:239315263, protocol version: 5
2024-02-21T07:58:57.298437Z 0 [Note] [MY-000000] [Galera] REPL Protocols: 10 (5)
2024-02-21T07:58:57.298446Z 0 [Note] [MY-000000] [Galera] ####### Adjusting cert position: 239315263 -> 239315264
2024-02-21T07:58:57.298461Z 0 [Note] [MY-000000] [Galera] Service thread queue flushed.
2024-02-21T07:58:57.298484Z 0 [Note] [MY-000000] [Galera] Recording CC from ist: 239315264
2024-02-21T07:58:57.298492Z 0 [Note] [MY-000000] [Galera] Lowest cert index boundary for CC from ist: 239315264
2024-02-21T07:58:57.298499Z 0 [Note] [MY-000000] [Galera] Min available from gcache for CC from ist: 232538757
2024-02-21T07:58:57.298551Z 10 [Note] [MY-000000] [Galera] ================================================
View:
  id: 884c986a-baba-11ee-bdcd-b2d06fd23cb6:239315264
  status: primary
  protocol_version: 4
  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
  final: no
  own_index: -1
  members(2):
	0: 19adcc32-d080-11ee-8041-ab710fc5e6cd, prod-galera3-80
	1: ef3f6729-d07a-11ee-91ca-bb6259c1b922, prod-galera1-80
=================================================
2024-02-21T07:58:57.298591Z 10 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
2024-02-21T07:58:58.412310Z 0 [Note] [MY-000000] [Galera] Receiving IST... 10.5% ( 4074/38813 events) complete.
2024-02-21T07:58:59.412751Z 0 [Note] [MY-000000] [Galera] Receiving IST... 17.0% ( 6595/38813 events) complete.
2024-02-21T07:59:00.412757Z 0 [Note] [MY-000000] [Galera] Receiving IST... 33.2% (12874/38813 events) complete.
2024-02-21T07:59:01.412765Z 0 [Note] [MY-000000] [Galera] Receiving IST... 65.8% (25523/38813 events) complete.
2024-02-21T07:59:01.635202Z 0 [Note] [MY-000000] [Galera] IST preload starting at 239353997
2024-02-21T07:59:01.636888Z 0 [Note] [MY-000000] [Galera] ####### Passing IST CC 239354076, must_apply: 1, preload: true
2024-02-21T08:01:02.545661Z 0 [Note] [MY-000000] [Galera] REPL Protocols: 10 (5)
2024-02-21T08:01:02.545709Z 0 [Note] [MY-000000] [Galera] ####### Adjusting cert position: 239354075 -> 239354076
2024-02-21T08:01:02.545745Z 0 [Note] [MY-000000] [Galera] Service thread queue flushed.
2024-02-21T08:01:02.545786Z 0 [Note] [MY-000000] [Galera] Recording CC from ist: 239354076
2024-02-21T08:01:02.545796Z 0 [Note] [MY-000000] [Galera] Lowest cert index boundary for CC from ist: 239353997
2024-02-21T08:01:02.545804Z 0 [Note] [MY-000000] [Galera] Min available from gcache for CC from ist: 232538757
2024-02-21T08:01:02.545847Z 0 [Note] [MY-000000] [Galera] Receiving IST...100.0% (38813/38813 events) complete.
2024-02-21T08:01:02.545846Z 11 [Note] [MY-000000] [Galera] ================================================
............

This is the IST part. Next is the “processing event queue” part, which we are unsure about:

2024-02-21T08:01:02.545887Z 11 [Note] [MY-000000] [WSREP] Server status change initialized -> joined
2024-02-21T08:01:02.545904Z 11 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
2024-02-21T08:01:02.545924Z 11 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
2024-02-21T08:01:02.546229Z 1 [Note] [MY-000000] [Galera] Draining apply monitors after IST up to 239354076
2024-02-21T08:01:02.553212Z 1 [Note] [MY-000000] [Galera] IST received: 884c986a-baba-11ee-bdcd-b2d06fd23cb6:239354076
2024-02-21T08:01:02.555169Z 1 [Note] [MY-000000] [Galera] Recording CC from sst: 239354076
2024-02-21T08:01:02.555187Z 1 [Note] [MY-000000] [Galera] Lowest cert index boundary for CC from sst: 239353997
2024-02-21T08:01:02.555202Z 1 [Note] [MY-000000] [Galera] Min available from gcache for CC from sst: 232538757
2024-02-21T08:01:02.556577Z 0 [Note] [MY-000000] [Galera] 0.3 (prod-galera2-80): State transfer from 1.3 (prod-galera3-80) complete.
2024-02-21T08:01:02.556602Z 0 [Note] [MY-000000] [Galera] SST leaving flow control
2024-02-21T08:01:02.556612Z 0 [Note] [MY-000000] [Galera] Shifting JOINER -> JOINED (TO: 239371214)
2024-02-21T08:01:02.556651Z 0 [Note] [MY-000000] [Galera] Processing event queue:...  0.0% (    0/17422 events) complete.
2024-02-21T08:01:12.578752Z 11 [Note] [MY-000000] [Galera] Processing event queue:... 20.4% ( 3856/18897 events) complete.
2024-02-21T08:01:22.610144Z 16 [Note] [MY-000000] [Galera] Processing event queue:... 37.6% ( 7648/20320 events) complete.
2024-02-21T08:01:32.615734Z 14 [Note] [MY-000000] [Galera] Processing event queue:... 52.5% (11360/21658 events) complete.
2024-02-21T08:01:42.638826Z 12 [Note] [MY-000000] [Galera] Processing event queue:... 64.4% (14720/22865 events) complete.
2024-02-21T08:01:52.650998Z 12 [Note] [MY-000000] [Galera] Processing event queue:... 78.2% (18432/23578 events) complete.
2024-02-21T08:02:02.687191Z 16 [Note] [MY-000000] [Galera] Processing event queue:... 90.8% (22224/24484 events) complete.
2024-02-21T08:02:09.490475Z 0 [Note] [MY-000000] [Galera] Member 0.3 (prod-galera2-80) synced with group.
2024-02-21T08:02:09.490519Z 0 [Note] [MY-000000] [Galera] Processing event queue:...100.0% (25281/25281 events) complete.
2024-02-21T08:02:09.490532Z 0 [Note] [MY-000000] [Galera] Shifting JOINED -> SYNCED (TO: 239378953)
2024-02-21T08:02:10.710334Z 1 [Note] [MY-000000] [Galera] Server prod-galera2-80 synced with group
2024-02-21T08:02:10.710365Z 1 [Note] [MY-000000] [WSREP] Server status change joined -> synced

Is there a name for this new “processing event queue” process?
Where can we read more about it?
Is there anything we can do to optimise its speed?

2

source / replica is the new terminology

While your node is receiving the IST, it is also receiving regular events. These events are queued and processed after the IST is processed. You can increase wsrep_applier_threads to 8 and see if that helps.

There are also performance_schema events that you can watch for that are tied to this event queue to monitor size and locking contention. Perfomance Schema instrumentation - Percona XtraDB Cluster

3

Thank you Matthew for the quick reply!

On a 16 vCPU node (AWS) we already have it configured with 8 applier threads, similar to your suggestion.

To us this seems to be a new thing for the MySQL8 version. In v5.7 a node appears to be rejoining and syncing an order of magnitude faster than in v8.

Do you have any suggestions on where we can read up on this (potentially new?) feature and further if there is anything else we can do to tweak its performance, documentation or straight up suggestions, would be very much appreciated?

Thank you

4

Hi, please note that JOINED → SYNCED catch-up process described above by @matthewb is nothing new in PXC 8.0 (Galera 4). It is the same in PXC 5.7 (Galera 3). The only new thing is displaying the progress in 8.0.
8.0 vs. 5.7

If I understand the problem correctly, despite writing additional progress logs, 5.7 was transitioning to the SYNCED state much faster than 8.0 does under the same workload conditions, right? If that’s the case, please create Jira ticket providing us with the following:

  1. Steps to reproduce (exemplary workload, scenario, etc)
  2. Configuration files for 5.7 and 8.0