Easy Execution of Dynamic Queries with the sys Schema

When you write stored procedures in MySQL, you sometimes need to generate queries on the fly, for example as you process the result of another query. This is supported using prepared statements. This blog explores how you can take advantage of the sys schema to simplify the use of dynamic queries.

Executing a query using the sys.execute_prepared_stmt() procedure.
Executing a query using the sys.execute_prepared_stmt() procedure.

The sys schema includes several stored procedures and functions as well as views to make the database administrator’s life easier. One of these is the execute_prepared_stmt() procedure which can be used to execute a query given as a string. An example is:

mysql> CALL sys.execute_prepared_stmt(
    ->     'SELECT * FROM world.city WHERE ID = 130');
+-----+--------+-------------+-----------------+------------+
| ID  | Name   | CountryCode | District        | Population |
+-----+--------+-------------+-----------------+------------+
| 130 | Sydney | AUS         | New South Wales |    3276207 |
+-----+--------+-------------+-----------------+------------+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.01 sec)

Let’s take a step back and look at how it works when you execute a dynamic query in MySQL before looking at a more realistic example.

Dynamic Queries and Prepared Statements

A prepared statement is created by providing the query in a string. Optionally, the query can include placeholders, so you can reuse the prepared statement with different parameters. However, here I will look at queries without placeholders.

You prepare the query with the PREPARE statement. The query can be specified either using a literal string or in a user variable. The above example uses a literal string, but when you work with dynamic queries in a stored procedure, you will assign the query to a user variable.

Once you have prepared the query, you execute it using the EXECUTE statement. If you need to execute the query several times, you can do this without preparing it again, however typically that is not the case with dynamic queries.

Finally, you should tell MySQL that you are done with the prepared statement, so the memory used to store the statement can be freed. If you do not do this, you will end up using more memory than necessary, and you can potentially run out of prepared statements (the maximum number allowed can be configured with max_prepared_stmt_count option). You tell MySQL to forget about the prepared statement with the DEALLOCATE PREPARE statement.

If you combine it all, you have the following sequence of steps to generate and execute the dynamic query:

mysql> SET @sql = CONCAT('SELECT COUNT(*) FROM ',
    ->                   sys.quote_identifier('world'),
    ->                   '.',
    ->                   sys.quote_identifier('city'));
Query OK, 0 rows affected (0.00 sec)

mysql> PREPARE stmt_count FROM @sql;
Query OK, 0 rows affected (0.00 sec)
Statement prepared

mysql> EXECUTE stmt_count;
+----------+
| COUNT(*) |
+----------+
|     4079 |
+----------+
1 row in set (0.01 sec)

mysql> DEALLOCATE PREPARE stmt_count;
Query OK, 0 rows affected (0.00 sec)

In the example, the query is created by concatenating the different parts of the query. The sys.quote_identifier() function is used to quote the schema and table names. Then the query is executed, and finally deallocated.

This is simple enough but can become tedious, if you execute many dynamic queries, and there is always the chance that you forget to include DEALLOCATE PREPARE causing higher memory usage than necessary. That is where sys.execute_prepared_stmt() comes into the picture.

sys.execute_prepared_stmt()

The sys.execute_prepared_stmt() procedure was born when Mark Leith and I were working on the sys schema in preparation to include it into MySQL 5.7. In the end we got tired of the repeated pattern with preparing, executing, and deallocating the statements. So, we decided to create a utility procedure for it.

Building on the above example, consider a stored procedure that takes a schema name as a parameter and goes through all the tables in the schema executing SELECT COUNT(*) to find the number of rows in each table. An example of a procedure that does this is:

DELIMITER $$
CREATE PROCEDURE row_count(IN in_schema varchar(64) CHARSET utf8mb4)
   SQL SECURITY INVOKER
   DETERMINISTIC
   READS SQL DATA
BEGIN
   DECLARE v_table varchar(64) CHARSET utf8mb4;
   DECLARE v_sql varchar(271);
   DECLARE v_done bool DEFAULT FALSE;
   DECLARE c_tables CURSOR FOR
      SELECT TABLE_NAME
        FROM information_schema.TABLES
       WHERE TABLE_SCHEMA = in_schema
             AND TABLE_TYPE = 'BASE TABLE';
   DECLARE CONTINUE HANDLER FOR NOT FOUND SET v_done = TRUE;

   OPEN c_tables;
   c_tables: LOOP
      FETCH c_tables INTO v_table;
      IF v_done THEN
         LEAVE c_tables;
      END IF;

      SET v_sql = CONCAT(
         'SELECT ',
         QUOTE(v_table), ' AS TableName, '
         'COUNT(*) AS RowCount FROM ',
         sys.quote_identifier(in_schema),
         '.',
         sys.quote_identifier(v_table)
      );
      CALL sys.execute_prepared_stmt(v_sql);
   END LOOP;
   CLOSE c_tables;
END$$
DELIMITER ;

The most interesting part of the procedure with respect to this discussion is the loop where the information_schema.TABLES view is queried to get all tables in the provided schema. Once the table name has been fetched into the v_table variable, the query is generated in lines 24 to 31 in a very similar way to the previous example. Then the generated query is executed using sys.execute_prepared_stmt() in line 32.

If you are using dynamic queries, I hope you will find sys.execute_prepared_stmt() useful. Happy coding.

The Format for Timestamps in MySQL Logs

MySQL changed the timestamp format in the log files in MySQL 5.7. Since then, I have a few times seen questions about the new format, and how to change the time zone that is used. Latest in a comment to my blog about log_slow_extra in 8.0.14, where the question was what T and Z in the timestamp (for example 2019-01-31T07:24:06.100447Z) means. In this blog, I will discuss the timestamp format and show you how you can change the time zone used.

Examples of the timestamps from the MySQL error log when restarting MySQL (click to enlarge).

The MySQL 5.7 Change

In MySQL 5.7 it was decided to make two changes to the timestamps affecting the format and time zone:

  • The format was changed to use the ISO 8601 / RFC 3339 format: YYYY-MM-DDThh:mm:ss.uuuuuu plus a tail value to signify the time zone.
  • The time zone used for the timestamps defaults to UTC (in 5.6 it defaulted to system time).

Tip

A couple of useful free resources, if you want to know more about the ISO 8601 / RFC 3339 format is the RFC specification and Wikipedia. The actual ISO 8601 specification can be purchased.

So there are two slightly different ways the timestamps can be displayed. The following two examples are for the default where the timestamp is in UTC and one where it is in UTC+11:00 (Australian Eastern Daylight Time):

2019-03-02T02:53:39.781592Z 0 [System] [MY-010116] [Server] C:\Program Files\MySQL\MySQL Server 8.0\bin\mysqld.exe (mysqld 8.0.15) starting as process 1516

2019-03-02T13:54:17.155810+11:00 0 [System] [MY-010116] [Server] C:\Program Files\MySQL\MySQL Server 8.0\bin\mysqld.exe (mysqld 8.0.15) starting as process 2812

Tip

In MySQL 8.0, you can also change the format itself, e.g. to JSON. See the MySQL reference manual on the error log format for for more information.

Changing the Time Zone

How do you change between the UTC and system time zones? You do that using the log_timestamps option which can take one of two values:

  • UTC: Use UTC as the time zone. This is the default.
  • SYSTEM: Use the same time zone as the operating system.

The option affects both the error log, slow query log, and general query log. The the slow and general query logs, though, it is only the case when logging to a file.

From XKCD comic 1179.

That Do T and Z Mean?

Back to the T and Z in the timestamps – what do they mean? The T is simply used as a separator between the data and time part. Think of it as T for Time. The Z means Zulu – another word for using the UTC time zone. That is:

  • T: Separator between the data and time parts.
  • Z: Zulu – the UTC time zone.

Thanks for reading.

Replication Monitoring with the Performance Schema

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.

Replication Setup with Multi-Source and Chained Replication
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:
  • 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 STATUSPerformance Schema
ColumnTableColumn
Slave_IO_StatethreadsPROCESSLIST_STATE
Master_Hostreplication_connection_configurationHOST
Master_Userreplication_connection_configurationUSER
Master_Portreplication_connection_configurationPORT
Connect_Retryreplication_connection_configurationCONNECTION_RETRY_INTERVAL
Master_Log_File
Read_Master_Log_Pos
Relay_Log_Filelog_statusREPLICATION->>'$.channels[*].relay_log_file'
Relay_Log_Poslog_statusREPLICATION->>'$.channels[*].relay_log_position'
Relay_Master_Log_File
Slave_IO_Runningreplication_connection_statusSERVICE_STATE
Slave_SQL_Runningreplication_applier_status_by_coordinatorSERVICE_STATE
Replicate_Do_DBreplication_applier_filters
replication_applier_global_filters
Replicate_Ignore_DBreplication_applier_filters
replication_applier_global_filters
Replicate_Do_Tablereplication_applier_filters
replication_applier_global_filters
Replicate_Ignore_Tablereplication_applier_filters
replication_applier_global_filters
Replicate_Wild_Do_Tablereplication_applier_filters
replication_applier_global_filters
Replicate_Wild_Ignore_Tablereplication_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_Allowedreplication_connection_configurationSSL_ALLOWED
Master_SSL_CA_Filereplication_connection_configurationSSL_CA_FILE
Master_SSL_CA_Pathreplication_connection_configurationSSL_CA_PATH
Master_SSL_Certreplication_connection_configurationSSL_CERTIFICATE
Master_SSL_Cipherreplication_connection_configurationSSL_CIPHER
Master_SSL_Keyreplication_connection_configurationSSL_KEY
Seconds_Behind_Master
Master_SSL_Verify_Server_Certreplication_connection_configurationSSL_VERIFY_SERVER_CERTIFICATE
Last_IO_Errnoreplication_connection_statusLAST_ERROR_NUMBER
Last_IO_Errorreplication_connection_statusLAST_ERROR_MESSAGE
Last_SQL_Errnoreplication_applier_status_by_worker
replication_applier_status_by_coordinator
LAST_ERROR_NUMBER
Last_SQL_Errorreplication_applier_status_by_worker
replication_applier_status_by_coordinator
LAST_ERROR_MESSAGE
Replicate_Ignore_Server_Ids
Master_Server_Id
Master_UUIDreplication_connection_statusSOURCE_UUID
Master_Info_File
SQL_Delayreplication_applier_configurationDESIRED_DELAY
SQL_Remaining_Delayreplication_applier_statusREMAINING_DELAY
Slave_SQL_Running_StatethreadsPROCESSLIST_STATE
Master_Retry_Countreplication_connection_configurationCONNECTION_RETRY_COUNT
Master_Bindreplication_connection_configurationNETWORK_INTERFACE
Last_IO_Error_Timestampreplication_connection_statusLAST_ERROR_TIMESTAMP
Last_SQL_Error_Timestampreplication_applier_status_by_worker
replication_applier_status_by_coordinator
LAST_ERROR_TIMESTAMP
Master_SSL_Crlreplication_connection_configurationSSL_CRL_FILE
Master_SSL_Crlpathreplication_connection_configurationSSL_CRL_PATH
Retrieved_Gtid_Setreplication_connection_statusRECEIVED_TRANSACTION_SET
Executed_Gtid_Set
Auto_Positionreplication_connection_configurationAUTO_POSITION
Replicate_Rewrite_DBreplication_applier_filters
replication_applier_global_filters
Channel_Name
Master_TLS_Versionreplication_connection_configurationTLS_VERSION
Master_public_key_pathreplication_connection_configurationPUBLIC_KEY_PATH
Get_master_public_keyreplication_connection_configurationGET_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
                 LAST_APPLIED_TRANSACTION_RETRIES_COUNT: 0
   LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
  LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE: 
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                     APPLYING_TRANSACTION_RETRIES_COUNT: 0
       APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
      APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE: 
    APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
*************************** 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
                 LAST_APPLIED_TRANSACTION_RETRIES_COUNT: 0
   LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
  LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE: 
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                     APPLYING_TRANSACTION_RETRIES_COUNT: 0
       APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
      APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE: 
    APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_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
                 LAST_APPLIED_TRANSACTION_RETRIES_COUNT: 0
   LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
  LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE: 
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                     APPLYING_TRANSACTION_RETRIES_COUNT: 0
       APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
      APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE: 
    APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_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
                 LAST_APPLIED_TRANSACTION_RETRIES_COUNT: 0
   LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
  LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE: 
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
                     APPLYING_TRANSACTION_RETRIES_COUNT: 0
       APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
      APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE: 
    APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_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.

Shutdown and Restart Statements

There are various ways to shutdown MySQL. The traditional cross platform method is to use the shutdown command in the mysqladmin client. One drawback is that it requires shell access; another is that it cannot start MySQL again automatically. There are platform specific options that can perform a restart such as using systemctl on Linux or install MySQL as a service on Microsoft Windows. What I will look at here though is the built in support for stopping and restarting MySQL using SQL statements.

MySQL 5.7 added the SHUTDOWN statement which allows you to shut down MySQL using the MySQL command-line client or MySQL Shell. The command is straight forward to use:

The SHUTDOWN command available in MySQL 5.7 and later.
The SHUTDOWN command available in MySQL 5.7 and later.

You will need the SHUTDOWN privilege to use the statement – this is the same as it required to use mysqladmin to shutdown MySQL. There is one gotcha to be aware of with the SHUTDOWN statement: it only works with the old (traditional) MySQL protocol. If you attempt to use it when connected to MySQL using the new X Protocol, you get the error: ERROR: 3130: Command not supported by pluggable protocols as shown in the next example:

Executing SHUTDOWN when connected through the X Protocol causes error 3130.
Executing SHUTDOWN when connected through the X Protocol causes error 3130.

The RESTART statement, on the other hand, works through both protocols and also requires the SHUTDOWN privilege:

The RESTART command available in MySQL 8.0.
The RESTART command available in MySQL 8.0.

For the restart to work, it is necessary that MySQL has been started in presence of a “monitoring service”. This is the default on Microsoft Windows (to disable the monitoring service start MySQL with --no-monitor). On Linux the monitoring service can for example be systemd or mysqld_safe.

As an example of where the RESTART statement comes in handy is for MySQL Shell’s AdminAPI for administrating a MySQL InnoDB Cluster cluster. MySQL Shell can when connected to MySQL Server 8.0 use the new SET PERSIST syntax to make the required configuration changes and then use the RESTART statement to restart the instance to make non-dynamic configuration changes take effect.

The SHUTDOWN and RESTART statements may not be the most important changes in MySQL 5.7 and 8.0, but they can be handy to know of in some cases.

Overview of the MySQL Server Architecture

Sometimes it can be useful to take a step back and look at the world from a bit larger distance than usual. So in this blog, I will take a look at the high level architecture of MySQL Server.

Information

This is meant as a simplified overview and does not include all details.

Overview of the MySQL Server Architecture
Overview of the MySQL Server Architecture

For the discussion I will be referring to the the following figure that shows some of the features and plugins of MySQL. Orange boxes are available both for the community version and the commercial (enterprise) version, whereas red means the plugin is exclusive for the commercial version. Ellipsoid elements are plugins, whereas square (yes with round corners) elements indicate other features. The figure is based on MySQL 5.7.20 where the audit log can be used to block access to tables.
At the top there are the various connectors and APIs that can be used in the application to connect to MySQL. As the mysql command-line client uses the C API, this is included in this part of the figure as well. There are more connectors and APIs than I could fit into the figure; for the complete list see the documentation index.

The large darkish box represents the server. At the top there is the connection handling where there are two choices: use one thread per connection or use the commercial thread pool plugin. One thread per connection is the original way of handling new connections and as the name implies, it is simply creating a new thread for each new connection. The MySQL Enterprise Thread Pool will limit the overall number of threads by re-using the threads. This leads to better scalability particularly in the case of many connections executing short queries. After the initial thread handling, it is possible to send the connection through the optional Connection-Control plugin which will throttle the connections for an account, when there are multiple attempts to login with the wrong password.

Once the connection has been cleared to move ahead, the query is checked against the Query Cache if it is a SELECT statement, and the Query Cache is enabled. For most workloads the Query Cache will be an overhead that does not justify the potential gain. So, in practice it is recommended to completely disable it.

Note

The Query Cache has been deprecated and is removed in MySQL 8.0.3 and later.

Next is the optional Query Rewrite plugin which allows the DBA to define which queries should be rewritten based on normalized queries like those in the Performance Schema digest summary table. For example, to change the query SELECT 130 to SELECT * FROM world.City WHERE ID = 130 – and the same for all other IDs, the following rule can be used:

INSERT INTO query_rewrite.rewrite_rules (pattern, replacement)
VALUES ('SELECT ?', 'SELECT * FROM world.City WHERE ID = ?');

CALL query_rewrite.flush_rewrite_rules();

This assumes the Query Rewrite plugin has already been installed.

It is not until now that the query actual reaches the parser (this will not happen if the query has a match in the Query Cache). After the parser has processed the query, it is known which schemas, tables, columns, etc. that will be required to answer the query, which means it is also possible to verify whether the user is allowed to use these objects.

After the parser, the MySQL Enterprise Firewall will be invoked if it is installed and enabled. The firewall compares the query’s digest to a whitelist of digests and if the query is in the whitelist. If the query is not in the whitelist it can be recorded or blocked (depending on configuration).

The last plugin is the MySQL Enterprise Audit plugin. In MySQL 5.7.20 and later, the audit log can be used to block access to a schema or a table in addition to log the access. This is the time where the plugin checks whether the access is allowed.

Finally the optimizer will determine the query plan and the query will be executed. The query execution will in almost all cases involve requesting data from or sending data to one of the storage engines. MySQL supports several storage engines through the pluggable storage engine architecture. Nowadays, the main storage engine is InnoDB, but several others exists including the NDBCluster storage engine that is used in MySQL NDB Cluster to execute queries through the SQL nodes (MySQL Server instances).

If You Want to Learn More

One nice way to investigate which order plugins and features are executed is to use the Performance Schema. For example to investigate the above features, enable the following instruments and consumers in the MySQL configuration file (or online executing UPDATE statements):

performance_schema_instrument                              = %=OFF
performance_schema_instrument                              = %alog%=ON
performance_schema_instrument                              = %firewall%=ON
performance_schema_instrument                              = %/Query_cache%=ON
performance_schema_instrument                              = %query cache%=ON
performance_schema_instrument                              = %rewriter%=ON
performance_schema_instrument                              = statement/%=ON
performance_schema_instrument                              = stage/%=ON
performance_schema_consumer_events_statements_history_long = ON
performance_schema_consumer_events_stages_current          = ON
performance_schema_consumer_events_stages_history_long     = ON
performance_schema_consumer_events_waits_current           = ON
performance_schema_consumer_events_waits_history_long      = ON

Then use two connections – one for monitoring and one for executing the query. Disable instrumentation for the monitoring connection:

mysql> CALL sys.ps_setup_disable_thread(CONNECTION_ID());
+-------------------+
| summary           |
+-------------------+
| Disabled 1 thread |
+-------------------+
1 row in set (0.01 sec)

Query OK, 0 rows affected (0.01 sec)

Determine the Performance Schema thread ID for the connection that will be executing queries:

mysql> SELECT THREAD_ID
         FROM performance_schema.threads
        WHERE PROCESSLIST_USER = 'testuser';
+-----------+
| THREAD_ID |
+-----------+
|        30 |
+-----------+
1 row in set (0.07 sec)

This assumes the two connections use different usernames. If that is not the case, then you will need to adjust the above query.

Optionally, to make it easier to find the events just for the test query, truncate all tables in the Performance Schema (this will lose all historical data, so is most appropriate for a test system):

mysql> CALL sys.ps_truncate_all_tables(false);
+---------------------+
| summary             |
+---------------------+
| Truncated 44 tables |
+---------------------+
1 row in set (0.03 sec)

Query OK, 0 rows affected (0.03 sec)

Now execute the query – for example one that gets rewritten by the Query Rewriter plugin using the rule above:

mysql> SELECT 130;
+-----+--------+-------------+-----------------+------------+
| ID  | Name   | CountryCode | District        | Population |
+-----+--------+-------------+-----------------+------------+
| 130 | Sydney | AUS         | New South Wales |    3276207 |
+-----+--------+-------------+-----------------+------------+
1 row in set, 1 warning (0.08 sec)

mysql> SHOW WARNINGS;
+-------+------+-----------------------------------------------------------------------------------------------------+
| Level | Code | Message                                                                                             |
+-------+------+-----------------------------------------------------------------------------------------------------+
| Note  | 1105 | Query 'SELECT 130' rewritten to 'SELECT * FROM world.City WHERE ID = 130' by a query rewrite plugin |
+-------+------+-----------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

Finally, the Performance Schema events can be retrieved:

mysql> (SELECT EVENT_ID, 'Statement' AS Type, EVENT_NAME FROM performance_schema.events_statements_history_long WHERE THREAD_ID = 30)
       UNION
       (SELECT EVENT_ID, 'Stage' AS Type, EVENT_NAME FROM performance_schema.events_stages_history_long WHERE THREAD_ID = 30)
       UNION
       (SELECT EVENT_ID, 'Wait' AS Type, EVENT_NAME FROM performance_schema.events_waits_history_long WHERE THREAD_ID = 30)
       ORDER BY EVENT_ID;
+----------+-----------+--------------------------------------------------------+
| EVENT_ID | Type      | EVENT_NAME                                             |
+----------+-----------+--------------------------------------------------------+
|        1 | Statement | statement/sql/select                                   |
|        2 | Stage     | stage/sql/starting                                     |
|        3 | Wait      | wait/synch/rwlock/rewriter/LOCK_plugin_rewriter_table_ |
|        4 | Wait      | wait/synch/rwlock/firewall/users_lock                  |
|        5 | Stage     | stage/sql/checking permissions                         |
|        6 | Stage     | stage/sql/Opening tables                               |
|        7 | Wait      | wait/synch/mutex/alog/LOCK_reopen                      |
|        8 | Wait      | wait/synch/mutex/alog/LOCK_block                       |
|        9 | Wait      | wait/synch/mutex/alog/LOCK_block                       |
|       10 | Stage     | stage/sql/init                                         |
|       11 | Stage     | stage/sql/System lock                                  |
|       12 | Stage     | stage/sql/optimizing                                   |
|       13 | Stage     | stage/sql/statistics                                   |
|       14 | Stage     | stage/sql/preparing                                    |
|       15 | Stage     | stage/sql/executing                                    |
|       16 | Stage     | stage/sql/Sending data                                 |
|       17 | Stage     | stage/sql/end                                          |
|       18 | Stage     | stage/sql/query end                                    |
|       19 | Stage     | stage/sql/closing tables                               |
|       20 | Stage     | stage/sql/freeing items                                |
|       21 | Stage     | stage/sql/cleaning up                                  |
|       22 | Statement | statement/sql/show_warnings                            |
|       23 | Stage     | stage/sql/starting                                     |
|       24 | Wait      | wait/synch/rwlock/rewriter/LOCK_plugin_rewriter_table_ |
|       25 | Wait      | wait/synch/rwlock/firewall/users_lock                  |
|       26 | Stage     | stage/sql/query end                                    |
|       27 | Stage     | stage/sql/closing tables                               |
|       28 | Stage     | stage/sql/freeing items                                |
|       29 | Stage     | stage/sql/cleaning up                                  |
+----------+-----------+--------------------------------------------------------+
29 rows in set (0.00 sec)

Have fun.

InnoDB Locks Analysis: Why is Blocking Query NULL and How To Find More Information About the Blocking Transaction?

This post was originally published on the MySQL Support Team Blog at https://blogs.oracle.com/mysqlsupport/entry/innodb_locks_analysis_why_is on 14 April 2017.

Consider the scenario that you execute a query. You expect it to be fast – typically subsecond – but now it take not return until after 50 seconds (innodb_lock_wait_timeout seconds) and then it returns with an error:

mysql> UPDATE world.City SET Population = Population + 999 WHERE ID = 130;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

You continue to investigate the issue using the sys.innodb_lock_waits view or the underlying Information Schema tables (INNODB_TRX, INNODB_LOCKS and INNODB_LOCK_WAITS).

Note

The above Information Schema tables with lock and lock waits information have been moved to the Performance Schema in 8.0 as the data_locks and data_lock_waits tables. The sys schema view however works the same.

However, when you query the locks information, the blocking query is returned as NULL. What does that mean and how to proceed from that to get information about the blocking transaction?

Setting Up an Example

Before proceeding, lets set up an example which will be investigated later in the blog. The example can be set up as (do not disconnect Connection 1 when the queries have been executed):

Step 1 – Connection 1:

Connection 1> START TRANSACTION;
Query OK, 0 rows affected (0.00 sec)

Connection 1> UPDATE world.City SET Population = Population + 1 WHERE ID = 130;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Connection 1> UPDATE world.City SET Population = Population + 1 WHERE ID = 131;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Connection 1> UPDATE world.City SET Population = Population + 1 WHERE ID = 132;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Connection 1> UPDATE world.City SET Population = Population + 1 WHERE ID = 133;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Step 2 – Connection 2:

Connection 2> UPDATE world.City SET Population = Population + 999 WHERE ID = 130;

Step 3 – Connection 3:

The following output while Connection 2 is still blokcing from sys.innodb_lock_waits shows that the blocking query is NULL (slightly reformatted):

Connection 3> SELECT * FROM sys.innodb_lock_waits\G
*************************** 1. row ***************************
                wait_started: 2017-04-15 09:54:53
                    wait_age: 00:00:03
               wait_age_secs: 3
                locked_table: `world`.`City`
                locked_index: PRIMARY
                 locked_type: RECORD
              waiting_trx_id: 2827
         waiting_trx_started: 2017-04-15 09:54:53
             waiting_trx_age: 00:00:03
     waiting_trx_rows_locked: 1
   waiting_trx_rows_modified: 0
                 waiting_pid: 5
               waiting_query: UPDATE world.City SET Populati ... opulation + 999
                              WHERE ID = 130
             waiting_lock_id: 2827:24:6:41
           waiting_lock_mode: X
             blocking_trx_id: 2826
                blocking_pid: 3
              blocking_query: NULL
            blocking_lock_id: 2826:24:6:41
          blocking_lock_mode: X
        blocking_trx_started: 2017-04-15 09:54:46
            blocking_trx_age: 00:00:10
    blocking_trx_rows_locked: 4
  blocking_trx_rows_modified: 4
     sql_kill_blocking_query: KILL QUERY 3
sql_kill_blocking_connection: KILL 3
1 row in set, 3 warnings (0.00 sec)

Connection 3> SHOW WARNINGS\G
*************************** 1. row ***************************
  Level: Warning
   Code: 1681 Message: 'INFORMATION_SCHEMA.INNODB_LOCK_WAITS' is deprecated
         and will be removed in a future release.
*************************** 2. row ***************************
  Level: Warning
   Code: 1681 Message: 'INFORMATION_SCHEMA.INNODB_LOCKS' is deprecated and
         will be removed in a future release.
*************************** 3. row ***************************
  Level: Warning
   Code: 1681 Message: 'INFORMATION_SCHEMA.INNODB_LOCKS' is deprecated and
         will be removed in a future release. 3 rows in set (0.00 sec)

The warnings will only occur in the 5.7.14 and later as the InnoDB lock tables being moved to the Performance Schema in MySQL 8.0. It is recommended to use the sys.innodb_lock_waits view as that is updated accordingly in MySQL 8.0.

Investigating Idle Transactions

To investigate idle transactions, you need to use the Performance Schema to get this information. First determine the Performance Schema thread id for the blocking transaction. For this you need the blocking_pid, in the above example:

                blocking_pid: 3

and use this with the The threads Table table like:

Connection 3> SELECT THREAD_ID FROM performance_schema.threads WHERE PROCESSLIST_ID = 3;
+-----------+
| THREAD_ID |
+-----------+
|        28 |
+-----------+
1 row in set (0.00 sec)

For the following queries insert the thread id found above for the THREAD_ID = … where clauses.

To get the latest query executed, use the The events_statements_current Table table or the The session and x$session Views view:

Connection 3> SELECT THREAD_ID, SQL_TEXT
                FROM performance_schema.events_statements_current
               WHERE THREAD_ID = 28;
+-----------+------------------------------------------------------------------+
| THREAD_ID | SQL_TEXT                                                         |
+-----------+------------------------------------------------------------------+
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 133 |
+-----------+------------------------------------------------------------------+
1 row in set (0.00 sec)

or:

Connection 3> SELECT * FROM sys.session WHERE thd_id = 28\G
*************************** 1. row ***************************
                thd_id: 28
               conn_id: 3
                  user: root@localhost
                    db: NULL
               command: Sleep
                 state: NULL
                  time: 447
     current_statement: NULL
     statement_latency: NULL
              progress: NULL
          lock_latency: 117.00 us
         rows_examined: 1
             rows_sent: 0
         rows_affected: 1
            tmp_tables: 0
       tmp_disk_tables: 0
             full_scan: NO
        last_statement: UPDATE world.City SET Population = Population + 1 WHERE ID = 133
last_statement_latency: 321.06 us
        current_memory: 0 bytes
             last_wait: NULL
     last_wait_latency: NULL
                source: NULL
           trx_latency: NULL
             trx_state: ACTIVE
        trx_autocommit: NO
                   pid: 7717
          program_name: mysql
1 row in set (0.08 sec)

In this case this does not explain why the lock is held as the last query update a different row then where the lock issue occurs. However if the events_statements_history consumer is enabled (it is by default in MySQL 5.7 and later), the The events_statements_history Table table will include the last 10 statements (by default) executed for the connection:

Connection 3> SELECT THREAD_ID, SQL_TEXT
                FROM performance_schema.events_statements_history
               WHERE THREAD_ID = 28
               ORDER BY EVENT_ID;
+-----------+------------------------------------------------------------------+
| THREAD_ID | SQL_TEXT                                                         |
+-----------+------------------------------------------------------------------+
|        28 | SELECT DATABASE()                                                |
|        28 | NULL                                                             |
|        28 | show databases                                                   |
|        28 | show tables                                                      |
|        28 | START TRANSACTION                                                |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 130 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 131 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 132 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 133 |
+-----------+------------------------------------------------------------------+
9 rows in set (0.00 sec)

So now the history of the blocking transaction can be seen and it is possible to determine why the locking issue occur.

Note

The history also includes some queries executed before the transaction started. These are not related to the locking issue.

If transaction monitoring is also enabled (only available in MySQL 5.7 and later), it is possible to get more information about the transaction and automatically limit the query of the history to the current transaction. Transaction monitoring is not enabled by default. To enable it, use:

mysql> UPDATE performance_schema.setup_consumers
          SET ENABLED = 'YES'
        WHERE NAME = 'events_transactions_current';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> UPDATE performance_schema.setup_instruments
          SET ENABLED = 'YES'
        WHERE NAME = 'transaction';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Information

This must be done before either of the transactions is started. Only transaction started after the transaction monitoring is enabled will be instrumented.

If the above was enabled before the blocking transaction started, you can get more details about the blocking transaction as:

Connection 3> SELECT *
                FROM performance_schema.events_transactions_current
               WHERE THREAD_ID = 28\G
*************************** 1. row ***************************
                      THREAD_ID: 28
                       EVENT_ID: 12
                   END_EVENT_ID: NULL
                     EVENT_NAME: transaction
                          STATE: ACTIVE
                         TRX_ID: NULL
                           GTID: AUTOMATIC
                  XID_FORMAT_ID: NULL
                      XID_GTRID: NULL
                      XID_BQUAL: NULL
                       XA_STATE: NULL
                         SOURCE: transaction.cc:209
                    TIMER_START: NULL
                      TIMER_END: NULL
                     TIMER_WAIT: NULL
                    ACCESS_MODE: READ WRITE
                ISOLATION_LEVEL: REPEATABLE READ
                     AUTOCOMMIT: NO
           NUMBER_OF_SAVEPOINTS: 0
NUMBER_OF_ROLLBACK_TO_SAVEPOINT: 0
    NUMBER_OF_RELEASE_SAVEPOINT: 0
          OBJECT_INSTANCE_BEGIN: NULL
               NESTING_EVENT_ID: 11
             NESTING_EVENT_TYPE: STATEMENT
1 row in set (0.00 sec)

And to get the statement history of the transaction:

Connection 3> SELECT t.THREAD_ID, s.SQL_TEXT
                FROM performance_schema.events_transactions_current t
                     INNER JOIN performance_schema.events_statements_history s
                             ON s.THREAD_ID = t.THREAD_ID
                            AND s.NESTING_EVENT_ID = t.EVENT_ID
               WHERE t.THREAD_ID = 28
               ORDER BY s.EVENT_ID;
+-----------+------------------------------------------------------------------+
| THREAD_ID | SQL_TEXT                                                         |
+-----------+------------------------------------------------------------------+
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 130 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 131 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 132 |
|        28 | UPDATE world.City SET Population = Population + 1 WHERE ID = 133 |
+-----------+------------------------------------------------------------------+
4 rows in set (0.00 sec)

Who Holds the Metadata Lock? MySQL 5.7.3 Brings Help

In MySQL 5.5 metadata locks were introduced to ensure consistency for some operations that previously could cause problems. For example if a transaction SELECTed from a table and another connection changed the structure of the table before the transaction was committed; in that case the two operations would be written in reverse order to the binary log which could prevent replaying the binary log.

However there was no way to see who held metadata locks. SHOW PROCESSLIST would show who were waiting for metadata locks, and often you could guess who held it, but it wasn’t so always. Consider for example the following:

mysql> SELECT Id, db, Command, Time, State, Info FROM information_schema.PROCESSLIST;
+------+--------------------+---------+------+---------------------------------+-------------------------------------------------------------------------------+
| Id   | db                 | Command | Time | State                           | Info                                                                          |
+------+--------------------+---------+------+---------------------------------+-------------------------------------------------------------------------------+
|    1 | NULL               | Daemon  |    8 | Waiting for next activation     | NULL                                                                          |
|    2 | performance_schema | Query   |    0 | executing                       | SELECT Id, db, Command, Time, State, Info FROM information_schema.PROCESSLIST |
|    3 | world              | Sleep   |   39 |                                 | NULL                                                                          |
|    4 | world              | Query   |   35 | Waiting for table metadata lock | ALTER TABLE City COMMENT='Cities'                                             |
| 1111 | world              | Sleep   |   32 |                                 | NULL                                                                          |
| 1108 | world              | Sleep   |   47 |                                 | NULL                                                                          |
| 1113 | world              | Sleep   |   18 |                                 | NULL                                                                          |
| 1112 | world              | Connect |   23 | Waiting for table metadata lock | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| 1109 | world              | Sleep   |   44 |                                 | NULL                                                                          |
| 1114 | world              | Connect |    8 | Waiting for table metadata lock | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
+------+--------------------+---------+------+---------------------------------+-------------------------------------------------------------------------------+
10 rows in set (0.00 sec)

In this case it happens to be the process with Id = 3 that holds the metadata lock, but that is not obvious from the above output.

In MySQL 5.7.3 this has changed. There is a new Performance Schema table metadata_locks which will tell which metadata locks are held and which are pending. This can be used to answer the question for a case like the one above.

First instrumentation of metadata locks should be enabled. To do that you must enable the wait/lock/metadata/sql/mdl instrument in setup_instruments. Additionally the global_instrumentation consumer must be enabled in setup_consumers.

Currently the wait/lock/metadata/sql/mdl instrument is not enabled by default. I have created a feature request to consider enabling it by default, but obviously whether that will happen also depends on the performance impact. Update: The instrument is enabled by default in MySQL 8.0.

To enable metadata lock instrumentation:

mysql> UPDATE setup_consumers SET ENABLED = 'YES' WHERE NAME = 'global_instrumentation';
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> UPDATE setup_instruments SET ENABLED = 'YES' WHERE NAME = 'wait/lock/metadata/sql/mdl';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Information

The global_instrumentation consumer is enabled by default.

With the metadata lock instrumentation enabled, it is now easy to answer who holds the metadata lock (I’ve excluded the connections own metalocks here as I’m only interested in the metadata lock contention going on between other queries):

mysql> SELECT OBJECT_TYPE, OBJECT_SCHEMA, OBJECT_NAME, LOCK_TYPE, LOCK_STATUS,
    ->        THREAD_ID, PROCESSLIST_ID, PROCESSLIST_INFO
    ->   FROM performance_schema.metadata_locks
    ->        INNER JOIN performance_schema.threads ON THREAD_ID = OWNER_THREAD_ID
    ->  WHERE PROCESSLIST_ID <> CONNECTION_ID();
+-------------+---------------+-------------+---------------------+-------------+-----------+----------------+-------------------------------------------------------------------------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | LOCK_TYPE           | LOCK_STATUS | THREAD_ID | PROCESSLIST_ID | PROCESSLIST_INFO                                                              |
+-------------+---------------+-------------+---------------------+-------------+-----------+----------------+-------------------------------------------------------------------------------+
| TABLE       | world         | City        | SHARED_READ         | GRANTED     |        22 |              3 | NULL                                                                          |
| GLOBAL      | NULL          | NULL        | INTENTION_EXCLUSIVE | GRANTED     |        23 |              4 | ALTER TABLE City COMMENT='Cities'                                             |
| SCHEMA      | world         | NULL        | INTENTION_EXCLUSIVE | GRANTED     |        23 |              4 | ALTER TABLE City COMMENT='Cities'                                             |
| TABLE       | world         | City        | SHARED_UPGRADABLE   | GRANTED     |        23 |              4 | ALTER TABLE City COMMENT='Cities'                                             |
| TABLE       | world         | City        | EXCLUSIVE           | PENDING     |        23 |              4 | ALTER TABLE City COMMENT='Cities'                                             |
| TABLE       | world         | view_city   | SHARED_READ         | GRANTED     |      1185 |           1166 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | City        | SHARED_READ         | PENDING     |      1185 |           1166 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | view_city   | SHARED_READ         | GRANTED     |      1186 |           1167 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | City        | SHARED_READ         | PENDING     |      1186 |           1167 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | view_city   | SHARED_READ         | GRANTED     |      1187 |           1168 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | City        | SHARED_READ         | PENDING     |      1187 |           1168 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | view_city   | SHARED_READ         | GRANTED     |      1188 |           1169 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | City        | SHARED_READ         | PENDING     |      1188 |           1169 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | view_city   | SHARED_READ         | GRANTED     |      1189 |           1170 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | City        | SHARED_READ         | PENDING     |      1189 |           1170 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | view_city   | SHARED_READ         | GRANTED     |      1190 |           1171 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | City        | SHARED_READ         | PENDING     |      1190 |           1171 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | view_city   | SHARED_READ         | GRANTED     |      1191 |           1172 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
| TABLE       | world         | City        | SHARED_READ         | PENDING     |      1191 |           1172 | SELECT COUNT(*) INTO @count FROM view_city WHERE CountryCode = in_CountryCode |
+-------------+---------------+-------------+---------------------+-------------+-----------+----------------+-------------------------------------------------------------------------------+
19 rows in set (0.00 sec)

So in this case there is a metadata lock GRANTED to process list id 3 whereas the other connections have a PENDING lock status for the metadata lock for the City table.