30

Replication Monitoring with the Performance Schema

 5 years ago
source link: https://www.tuicool.com/articles/hit/iaeiMfv
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

The traditional way to monitor replication in MySQL is the SHOW SLAVE STATUS command. However as it will be shown, it has its limitations and in MySQL 5.7 and 8.0 the MySQL developers have started to implement the information as Performance Schema tables. This has several advantages including better monitoring of the replication delay in MySQL 8.0. This blog discusses why SHOW SLAVE STATUS should be replaced with the Performance Schema tables.

The Setup

The replication setup that will be used for the examples in this blog can be seen in the following figure.

QRR773a.png!web Replication Setup with Multi-Source and Chained Replication

There are two source instances (replication masters). Source 1 replicates to the Relay instance (i.e. it acts both as a replica and source in the setup). The Relay instance replicates to the Replica instance which also replicates from Source 2 . That is, the Replica instance uses multi-source replication to replicate from the Source 1Relay chain as well as directly from Source 2 .

This blog will use the Replica instance to demonstrate SHOW SLAVE STATUS and Performance Schema replication tables.

SHOW SLAVE STATUS

The SHOW SLAVE STATUS command has been around since the addition of replication to MySQL. Thus it is familiar to all database administrators who have been working with replication. It is also very simple to use, and it is easy to remember the syntax. So far so good. However, it also has some limitations.

Let’s take a look at how the output of SHOW SLAVE STATUS looks in the setup described above:

*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: replication
                  Master_Port: 3308
                Connect_Retry: 60
              Master_Log_File: binlog.000001
          Read_Master_Log_Pos: 61422958
               Relay_Log_File: relaylog-relay.000005
                Relay_Log_Pos: 59921651
        Relay_Master_Log_File: binlog.000001
             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: sakila.%
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 59921443
              Relay_Log_Space: 61423581
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: Yes
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 49
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: 11
                  Master_UUID: 7616e9d1-c868-11e8-92f0-080027effed8
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set: 81c777c0-c86f-11e8-9031-080027effed8:28-81
            Executed_Gtid_Set: 2165e6e2-c870-11e8-8818-080027effed8:1-39,
81c777c0-c86f-11e8-9031-080027effed8:1-80
                Auto_Position: 1
         Replicate_Rewrite_DB: 
                 Channel_Name: relay
           Master_TLS_Version: 
       Master_public_key_path: 
        Get_master_public_key: 0
*************************** 2. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: replication
                  Master_Port: 3307
                Connect_Retry: 60
              Master_Log_File: binlog.000002
          Read_Master_Log_Pos: 366288
               Relay_Log_File: relaylog-source_2.000005
                Relay_Log_Pos: 181612
        Relay_Master_Log_File: binlog.000002
             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: sakila.%
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 366288
              Relay_Log_Space: 182074
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: Yes
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 0
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: 2
                  Master_UUID: 2165e6e2-c870-11e8-8818-080027effed8
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set: 2165e6e2-c870-11e8-8818-080027effed8:28-39
            Executed_Gtid_Set: 2165e6e2-c870-11e8-8818-080027effed8:1-39,
81c777c0-c86f-11e8-9031-080027effed8:1-80
                Auto_Position: 1
         Replicate_Rewrite_DB: 
                 Channel_Name: source_2
           Master_TLS_Version: 
       Master_public_key_path: 
        Get_master_public_key: 0
2 rows in set (0.22 sec)

The first thought: that’s a lot of lines of output. That is one of the issues – there is no way to limit the output. So summarize some of the issues with SHOW SLAVE STATUS :

  • There is no support for filter conditions or choosing which columns to include, so the output is very verbose. In this case with two replication channels, all available data for both channels are always included.
  • The order of the columns reflects the order they were added rather than how they logically belong together. Over the years many new columns have been added as new features have been added or the feature has been changed from an option configured in my.cnf to an option configured with CHANGE MASTER TO . For example the channel name is the fourth column from the end even if it would be more natural to have it as the first column (as it’s it the “primary key” of the output).
  • For multi-threaded appliers ( replication_slave_workers > 1) there is no information for the individual workers.
  • Information related to the connection (I/O thread) and applier (SQL thread) as well configuration and status are mixed.
  • What does Seconds_behind_master mean? For the source_2 channel (the direct replication from Source 2 it is relatively easy to understand, but for the relay channel is it relative to Source 1 (yes) or to Replica (no)? More about this later.

To look at what can be done to solve these limitations, let’s look at the Performance Schema.

Performance Schema Replication Tables

To overcome these limitations, MySQL 5.7 introduced a series of replication tables in the Performance Schema. These have been extended in MySQL 8.0 to make them even more useful. One of the advantages of using the Performance Schema is that queries are executed as regular SELECT statements with the usual support for choosing columns and manipulating them and to apply a WHERE clause. First, let’s take a look at which replication related tables that are available.

Overview of Tables

As of MySQL 8.0.12 there are 11 replication related tables. The tables are:

  • log_status : This table is new in MySQL 8 and provides information about the binary log, relay log, and InnoDB redo log in a consistent manner (i.e. all values are for the same point in time).
  • Applier:
    • replication_applier_configuration : This table shows the configuration of the applier threads for each replication channel. Currently the only setting is the configured replication delay.
    • replication_applier_filters : The channel specific replication filters including where and when they were configured.
    • replication_applier_global_filters : The global replication filters including how and when they were configured.
    • replication_applier_status : This table shows the replication filters for each replication channel. The information includes the service state, remaining delay, and number of transaction retries.
    • replication_applier_status_by_coordinator : For multi-threaded replicas this table shows the status of the thread that manages the actual worker threads. In MySQL 8 this includes several timestamps to give detailed knowledge of the replication delay.
    • replication_applier_status_by_worker : The status of each worker thread (for single-threaded replication there is one per channel). In MySQL 8 this includes several timestamps to give detailed knowledge of the replication delay.
  • Connection:
    • replication_connection_configuration : The configuration of each of the replication channels.
    • replication_connection_status : The status of the replication channels. In MySQL 8 this includes information about the timestamps showing when the currently queuing transaction was originally committed, when it was committed on the immediate source instance, and when it was written to the relay log. This makes it possible to describe much more accurately what the replication delay is.
  • Group Replication:

The Group Replication tables will not be discussed further.

Since the information from SHOW SLAVE STATUS has been split up into several tables, it can be useful to take a look at how the information map.

Old Versus New

The following table shows how to get from a column in the SHOW SLAVE STATUS output to a table and column in the Performance Schema. The channel name is present in all of the Performance Schema replication tables (it’s the primary key or part of it). The replication filters and rewrite rules are split into two tables. The I/O and SQL thread states can be found in the performance_schema.threads by joining using the THREAD_ID column for the corresponding threads.

SHOW SLAVE STATUS Performance Schema Column Table Column Slave_IO_State threads PROCESSLIST_STATE Master_Host replication_connection_configuration HOST Master_User replication_connection_configuration USER Master_Port replication_connection_configuration PORT Connect_Retry replication_connection_configuration CONNECTION_RETRY_INTERVAL Master_Log_File Read_Master_Log_Pos Relay_Log_File log_status REPLICATION->>'$.channels[*].relay_log_file' Relay_Log_Pos log_status REPLICATION->>'$.channels[*].relay_log_position' Relay_Master_Log_File Slave_IO_Running replication_connection_status SERVICE_STATE Slave_SQL_Running replication_applier_status_by_coordinator SERVICE_STATE Replicate_Do_DB replication_applier_filters
replication_applier_global_filters Replicate_Ignore_DB replication_applier_filters
replication_applier_global_filters Replicate_Do_Table replication_applier_filters
replication_applier_global_filters Replicate_Ignore_Table replication_applier_filters
replication_applier_global_filters Replicate_Wild_Do_Table replication_applier_filters
replication_applier_global_filters Replicate_Wild_Ignore_Table replication_applier_filtersreplication_applier_global_filters Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed replication_connection_configuration SSL_ALLOWED Master_SSL_CA_File replication_connection_configuration SSL_CA_FILE Master_SSL_CA_Path replication_connection_configuration SSL_CA_PATH Master_SSL_Cert replication_connection_configuration SSL_CERTIFICATE Master_SSL_Cipher replication_connection_configuration SSL_CIPHER Master_SSL_Key replication_connection_configuration SSL_KEY Seconds_Behind_Master Master_SSL_Verify_Server_Cert replication_connection_configuration SSL_VERIFY_SERVER_CERTIFICATE Last_IO_Errno replication_connection_status LAST_ERROR_NUMBER Last_IO_Error replication_connection_status LAST_ERROR_MESSAGE Last_SQL_Errno replication_applier_status_by_worker
replication_applier_status_by_coordinator LAST_ERROR_NUMBER Last_SQL_Error replication_applier_status_by_worker
replication_applier_status_by_coordinator LAST_ERROR_MESSAGE Replicate_Ignore_Server_Ids Master_Server_Id Master_UUID replication_connection_status SOURCE_UUID Master_Info_File SQL_Delay replication_applier_configuration DESIRED_DELAY SQL_Remaining_Delay replication_applier_status REMAINING_DELAY Slave_SQL_Running_State threads PROCESSLIST_STATE Master_Retry_Count replication_connection_configuration CONNECTION_RETRY_COUNT Master_Bind replication_connection_configuration NETWORK_INTERFACE Last_IO_Error_Timestamp replication_connection_status LAST_ERROR_TIMESTAMP Last_SQL_Error_Timestamp replication_applier_status_by_worker
replication_applier_status_by_coordinator LAST_ERROR_TIMESTAMP Master_SSL_Crl replication_connection_configuration SSL_CRL_FILE Master_SSL_Crlpath replication_connection_configuration SSL_CRL_PATH Retrieved_Gtid_Set replication_connection_status RECEIVED_TRANSACTION_SET Executed_Gtid_Set Auto_Position replication_connection_configuration AUTO_POSITION Replicate_Rewrite_DB replication_applier_filters
replication_applier_global_filters Channel_Name Master_TLS_Version replication_connection_configuration TLS_VERSION Master_public_key_path replication_connection_configuration PUBLIC_KEY_PATH Get_master_public_key replication_connection_configuration GET_PUBLIC_KEY

As it can be seen, there are a few columns from SHOW SLAVE STATUS that do not have any corresponding tables and columns in the Performance Schema yet. One that probably is familiar to many as the main mean of monitoring the replication lag is the the Seconds_Behind_Master column.  This is no longer needed. It is now possible to get a better value using the timestamp columns in the replication_applier_status_by_coordinator , replication_applier_status_by_worker , and replication_connection_status tables. Talking about that, it is time to see the Performance Schema replication tables in action.

Examples

The rest of the blog shows example outputs each of the replication tables (except the ones related to Group Replication) in the Performance Schema. For some of the tables there is a short discussion following the output. The queries have been executed in rapid succession after the above SHOW SLAVE STATUS output was generated. As the outputs have been generated using separate queries, they do not correspond to the exact same point in time.

log_status

The log_status table shows the replication and engine log data so the data is consistent:

mysql> SELECT SERVER_UUID, JSON_PRETTY(LOCAL) AS LOCAL,
              JSON_PRETTY(REPLICATION) AS REPLICATION,
              STORAGE_ENGINES
         FROM log_status\G
*************************** 1. row ***************************
    SERVER_UUID: 302f0073-c869-11e8-95bb-080027effed8
          LOCAL: {
  "gtid_executed": "2165e6e2-c870-11e8-8818-080027effed8:1-39,\n81c777c0-c86f-11e8-9031-080027effed8:1-80",
  "binary_log_file": "binlog.000002",
  "binary_log_position": 60102708
}
    REPLICATION: {
  "channels": [
    {
      "channel_name": "relay",
      "relay_log_file": "relaylog-relay.000005",
      "relay_log_position": 61423166
    },
    {
      "channel_name": "source_2",
      "relay_log_file": "relaylog-source_2.000005",
      "relay_log_position": 181612
    }
  ]
}
STORAGE_ENGINES: {"InnoDB": {"LSN": 120287720, "LSN_checkpoint": 118919036}}
1 row in set (0.03 sec)

replication_applier_configuration

The replication_applier_configuration table shows the configuration of the applier threads:

mysql> SELECT * FROM replication_applier_configuration;
+--------------+---------------+
| CHANNEL_NAME | DESIRED_DELAY |
+--------------+---------------+
| relay        |             0 |
| source_2     |             0 |
+--------------+---------------+
2 rows in set (0.04 sec)

replication_applier_filters

The replication_applier_filters table shows the channel specific replication filters:

mysql> SELECT * FROM replication_applier_filters\G
*************************** 1. row ***************************
 CHANNEL_NAME: relay
  FILTER_NAME: REPLICATE_WILD_IGNORE_TABLE
  FILTER_RULE: world.%
CONFIGURED_BY: STARTUP_OPTIONS_FOR_CHANNEL
 ACTIVE_SINCE: 2018-10-05 20:49:48.185078
      COUNTER: 0
1 rows in set (0.18 sec)

There is one filter specifically for the relay channel: the channel will ignore changes to tables in the world schema and the filter was set using the the replicate_wild_ignore_table option in the MySQL configuration file.

replication_applier_global_filters

The replication_applier_global_filters table shows the replication filters that are shared for all channels:

mysql> SELECT * FROM replication_applier_global_filters\G
*************************** 1. row ***************************
  FILTER_NAME: REPLICATE_WILD_IGNORE_TABLE
  FILTER_RULE: sakila.%
CONFIGURED_BY: CHANGE_REPLICATION_FILTER
 ACTIVE_SINCE: 2018-10-05 20:48:54.341004
1 row in set (0.02 sec)

There is also one global replication filter. This has been set using the CHANGE REPLICATION FILTER statement.

replication_applier_status

The replication_applier_status table shows the overall status for the applier threads:

mysql> SELECT * FROM replication_applier_status;
+--------------+---------------+-----------------+----------------------------+
| CHANNEL_NAME | SERVICE_STATE | REMAINING_DELAY | COUNT_TRANSACTIONS_RETRIES |
+--------------+---------------+-----------------+----------------------------+
| relay        | ON            |            NULL |                          0 |
| source_2     | ON            |            NULL |                          0 |
+--------------+---------------+-----------------+----------------------------+
2 rows in set (0.05 sec)

replication_applier_status_by_coordinator

The replication_applier_status_by_coordinator table shows the status for the coordinator when multi-threaded appliers has been configured ( slave_parallel_workers > 1):

mysql> SELECT * FROM replication_applier_status_by_coordinator\G
*************************** 1. row ***************************
                                         CHANNEL_NAME: relay
                                            THREAD_ID: 55
                                        SERVICE_STATE: ON
                                    LAST_ERROR_NUMBER: 0
                                   LAST_ERROR_MESSAGE: 
                                 LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                           LAST_PROCESSED_TRANSACTION: 81c777c0-c86f-11e8-9031-080027effed8:81
 LAST_PROCESSED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2018-10-05 21:07:52.286116
LAST_PROCESSED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2018-10-05 21:08:10.692561
    LAST_PROCESSED_TRANSACTION_START_BUFFER_TIMESTAMP: 2018-10-05 21:08:10.843893
      LAST_PROCESSED_TRANSACTION_END_BUFFER_TIMESTAMP: 2018-10-05 21:08:11.142150
                               PROCESSING_TRANSACTION: 
     PROCESSING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
    PROCESSING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
        PROCESSING_TRANSACTION_START_BUFFER_TIMESTAMP: 0000-00-00 00:00:00.000000
*************************** 2. row ***************************
                                         CHANNEL_NAME: source_2
                                            THREAD_ID: 59
                                        SERVICE_STATE: ON
                                    LAST_ERROR_NUMBER: 0
                                   LAST_ERROR_MESSAGE: 
                                 LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                           LAST_PROCESSED_TRANSACTION: 2165e6e2-c870-11e8-8818-080027effed8:39
 LAST_PROCESSED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2018-10-05 20:52:12.422129
LAST_PROCESSED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2018-10-05 20:52:12.422129
    LAST_PROCESSED_TRANSACTION_START_BUFFER_TIMESTAMP: 2018-10-05 20:52:13.010969
      LAST_PROCESSED_TRANSACTION_END_BUFFER_TIMESTAMP: 2018-10-05 20:52:13.519174
                               PROCESSING_TRANSACTION: 
     PROCESSING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
    PROCESSING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
        PROCESSING_TRANSACTION_START_BUFFER_TIMESTAMP: 0000-00-00 00:00:00.000000
2 rows in set (0.06 sec)

This is an example of MySQL 8 has detailed information about the timings were for the various stages of the applied events. For example for the relay channel, it can be seen that for the last processed transaction, it took 18 seconds from the transaction was committed on Source 1 (original commit) until it was committed on Relay (immediate commit), but then it only took around half a second until the coordinate was done processing the transaction (i.e. sending it to a worker). Which brings us to the status by worker.

replication_applier_status_by_worker

The replication_applier_status_by_worker table shows the status for each worker thread:

mysql> SELECT * FROM replication_applier_status_by_worker\G
*************************** 1. row ***************************
                                       CHANNEL_NAME: relay
                                          WORKER_ID: 1
                                          THREAD_ID: 56
                                      SERVICE_STATE: ON
                                  LAST_ERROR_NUMBER: 0
                                 LAST_ERROR_MESSAGE: 
                               LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                           LAST_APPLIED_TRANSACTION: 81c777c0-c86f-11e8-9031-080027effed8:80
 LAST_APPLIED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2018-10-05 21:07:27.721738
LAST_APPLIED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2018-10-05 21:07:50.387138
     LAST_APPLIED_TRANSACTION_START_APPLY_TIMESTAMP: 2018-10-05 21:07:50.526808
       LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP: 2018-10-05 21:08:09.296713
                               APPLYING_TRANSACTION: 81c777c0-c86f-11e8-9031-080027effed8:81
     APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2018-10-05 21:07:52.286116
    APPLYING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2018-10-05 21:08:10.692561
         APPLYING_TRANSACTION_START_APPLY_TIMESTAMP: 2018-10-05 21:08:10.855825
*************************** 2. row ***************************
                                       CHANNEL_NAME: relay
                                          WORKER_ID: 2
                                          THREAD_ID: 57
                                      SERVICE_STATE: ON
                                  LAST_ERROR_NUMBER: 0
                                 LAST_ERROR_MESSAGE: 
                               LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                           LAST_APPLIED_TRANSACTION: 
 LAST_APPLIED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
LAST_APPLIED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
     LAST_APPLIED_TRANSACTION_START_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
       LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
                               APPLYING_TRANSACTION: 
     APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
    APPLYING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
         APPLYING_TRANSACTION_START_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
*************************** 3. row ***************************
                                       CHANNEL_NAME: source_2
                                          WORKER_ID: 1
                                          THREAD_ID: 60
                                      SERVICE_STATE: ON
                                  LAST_ERROR_NUMBER: 0
                                 LAST_ERROR_MESSAGE: 
                               LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                           LAST_APPLIED_TRANSACTION: 2165e6e2-c870-11e8-8818-080027effed8:39
 LAST_APPLIED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2018-10-05 20:52:12.422129
LAST_APPLIED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2018-10-05 20:52:12.422129
     LAST_APPLIED_TRANSACTION_START_APPLY_TIMESTAMP: 2018-10-05 20:52:13.520916
       LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP: 2018-10-05 20:52:14.302957
                               APPLYING_TRANSACTION: 
     APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
    APPLYING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
         APPLYING_TRANSACTION_START_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
*************************** 4. row ***************************
                                       CHANNEL_NAME: source_2
                                          WORKER_ID: 2
                                          THREAD_ID: 61
                                      SERVICE_STATE: ON
                                  LAST_ERROR_NUMBER: 0
                                 LAST_ERROR_MESSAGE: 
                               LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                           LAST_APPLIED_TRANSACTION: 
 LAST_APPLIED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
LAST_APPLIED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
     LAST_APPLIED_TRANSACTION_START_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
       LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
                               APPLYING_TRANSACTION: 
     APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
    APPLYING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
         APPLYING_TRANSACTION_START_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
4 rows in set (0.16 sec)

The timestamps for the relay channel’s workers (only one has been active as it can be seen) can be used to see that the last transaction took around 19 seconds to apply and it was committed also 19 seconds after it committed on the immediate source (the Relay instance).

You can compare this delay of 19 seconds with the 49 seconds claimed by Seconds_Behind_Master in the SHOW SLAVE STATUS output. Why the difference? Seconds_Behind_Master is really the time from the original source started to execute the current transaction until now. So that includes the time it took to execute the transaction not only on Source 1 but also on Relay and the time used until now on Replica .

replication_connection_configuration

The replication_connection_configuration table shows the configuration for each connection to the source of the replication:

mysql> SELECT * FROM replication_connection_configuration\G
*************************** 1. row ***************************
                 CHANNEL_NAME: relay
                         HOST: 127.0.0.1
                         PORT: 3308
                         USER: replication
            NETWORK_INTERFACE: 
                AUTO_POSITION: 1
                  SSL_ALLOWED: YES
                  SSL_CA_FILE: 
                  SSL_CA_PATH: 
              SSL_CERTIFICATE: 
                   SSL_CIPHER: 
                      SSL_KEY: 
SSL_VERIFY_SERVER_CERTIFICATE: NO
                 SSL_CRL_FILE: 
                 SSL_CRL_PATH: 
    CONNECTION_RETRY_INTERVAL: 60
       CONNECTION_RETRY_COUNT: 86400
           HEARTBEAT_INTERVAL: 30.000
                  TLS_VERSION: 
              PUBLIC_KEY_PATH: 
               GET_PUBLIC_KEY: NO
*************************** 2. row ***************************
                 CHANNEL_NAME: source_2
                         HOST: 127.0.0.1
                         PORT: 3307
                         USER: replication
            NETWORK_INTERFACE: 
                AUTO_POSITION: 1
                  SSL_ALLOWED: YES
                  SSL_CA_FILE: 
                  SSL_CA_PATH: 
              SSL_CERTIFICATE: 
                   SSL_CIPHER: 
                      SSL_KEY: 
SSL_VERIFY_SERVER_CERTIFICATE: NO
                 SSL_CRL_FILE: 
                 SSL_CRL_PATH: 
    CONNECTION_RETRY_INTERVAL: 60
       CONNECTION_RETRY_COUNT: 86400
           HEARTBEAT_INTERVAL: 30.000
                  TLS_VERSION: 
              PUBLIC_KEY_PATH: 
               GET_PUBLIC_KEY: NO
2 rows in set (0.01 sec)

replication_connection_status

The replication_connection_status table shows the status of each connection:

mysql> SELECT * FROM replication_connection_status\G
*************************** 1. row ***************************
                                      CHANNEL_NAME: relay
                                        GROUP_NAME: 
                                       SOURCE_UUID: 7616e9d1-c868-11e8-92f0-080027effed8
                                         THREAD_ID: 54
                                     SERVICE_STATE: ON
                         COUNT_RECEIVED_HEARTBEATS: 28
                          LAST_HEARTBEAT_TIMESTAMP: 2018-10-05 21:03:49.684895
                          RECEIVED_TRANSACTION_SET: 81c777c0-c86f-11e8-9031-080027effed8:28-81
                                 LAST_ERROR_NUMBER: 0
                                LAST_ERROR_MESSAGE: 
                              LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                           LAST_QUEUED_TRANSACTION: 81c777c0-c86f-11e8-9031-080027effed8:81
 LAST_QUEUED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2018-10-05 21:07:52.286116
LAST_QUEUED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2018-10-05 21:08:10.692561
     LAST_QUEUED_TRANSACTION_START_QUEUE_TIMESTAMP: 2018-10-05 21:08:10.835992
       LAST_QUEUED_TRANSACTION_END_QUEUE_TIMESTAMP: 2018-10-05 21:08:10.842133
                              QUEUEING_TRANSACTION: 
    QUEUEING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
   QUEUEING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
        QUEUEING_TRANSACTION_START_QUEUE_TIMESTAMP: 0000-00-00 00:00:00.000000
*************************** 2. row ***************************
                                      CHANNEL_NAME: source_2
                                        GROUP_NAME: 
                                       SOURCE_UUID: 2165e6e2-c870-11e8-8818-080027effed8
                                         THREAD_ID: 58
                                     SERVICE_STATE: ON
                         COUNT_RECEIVED_HEARTBEATS: 47
                          LAST_HEARTBEAT_TIMESTAMP: 2018-10-05 21:08:12.589150
                          RECEIVED_TRANSACTION_SET: 2165e6e2-c870-11e8-8818-080027effed8:28-39
                                 LAST_ERROR_NUMBER: 0
                                LAST_ERROR_MESSAGE: 
                              LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                           LAST_QUEUED_TRANSACTION: 2165e6e2-c870-11e8-8818-080027effed8:39
 LAST_QUEUED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2018-10-05 20:52:12.422129
LAST_QUEUED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2018-10-05 20:52:12.422129
     LAST_QUEUED_TRANSACTION_START_QUEUE_TIMESTAMP: 2018-10-05 20:52:12.486156
       LAST_QUEUED_TRANSACTION_END_QUEUE_TIMESTAMP: 2018-10-05 20:52:12.486263
                              QUEUEING_TRANSACTION: 
    QUEUEING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
   QUEUEING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
        QUEUEING_TRANSACTION_START_QUEUE_TIMESTAMP: 0000-00-00 00:00:00.000000
2 rows in set (0.02 sec)

Similar to the applier timestamps, the connection timestamps can be used to check the lag caused by the connection threads fetching the transactions from its source’s binary log and writing it to its own relay log. For the relay channel it took around 0.14 second from the transaction was committed on the immediate source (the Relay instance) until the connection thread started to write the transaction to the relay log ( LAST_QUEUED_TRANSACTION_START_QUEUE_TIMESTAMP ) and then further 0.007 second to complete the write.

Conclusion

The replication related tables in the Performance Schema, particularly the MySQL 8 version of them, provides a very useful way to get information about the replication configuration and status. As a support engineer myself, I look forward to have access to the new timestamp values, when I investigate replication delays.

There is still some work remaining such. For example, it could be useful to know when the transaction started on the original source. That way it is possible to compare the execution time between a source and a replica. However, the current information that is available is already a great improvement.


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK