Description:
Background histogram update is blocked even though no exclusive metadata lock(MDL) is acquired.
For example, the following warning appeared even though there was no exclusive MDL on test.t_upd.
-------
[Warning] [MY-015116] [Server] Background histogram update on test.t_upd: Lock wait timeout exceeded; try restarting transaction
-------
This behavior cause multiple warnings in error log, making readability lower.
I'm not sure what kind of locks blocks background histogram update.
According https://bugs.mysql.com/bug.php?id=116145, the warning can happen when background thread cannot lock table due to preceding exclusive MDL. However I observed the warning even though no exclusive metadata lock(MDL) is acquired, and that is why I created this report.
How to repeat:
# Checking my.cnf, related system variables, and version.
cat /etc/my.cnf
[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
mysql> select version();
+-----------+
| version() |
+-----------+
| 8.4.6 |
+-----------+
1 row in set (0.00 sec)
mysql> show global variables like '%stats%';
+--------------------------------------+---------------+
| Variable_name | Value |
+--------------------------------------+---------------+
| information_schema_stats_expiry | 86400 |
| innodb_stats_auto_recalc | ON |
| innodb_stats_include_delete_marked | OFF |
| innodb_stats_method | nulls_equal |
| innodb_stats_on_metadata | OFF |
| innodb_stats_persistent | ON |
| innodb_stats_persistent_sample_pages | 20 |
| innodb_stats_transient_sample_pages | 8 |
| myisam_stats_method | nulls_unequal |
+--------------------------------------+---------------+
9 rows in set (0.00 sec)
mysql> select @@log_error;
+---------------------+
| @@log_error |
+---------------------+
| /var/log/mysqld.log |
+---------------------+
1 row in set (0.00 sec)
# Preparing schema and tables.
mysql> create database test;
Query OK, 1 row affected (0.00 sec)
mysql> use test;
Database changed
mysql> CREATE TABLE t1 ( i int NOT NULL, PRIMARY KEY (i));
Query OK, 0 rows affected (0.02 sec)
mysql> CREATE TABLE t_upd (i int NOT NULL, value bigint DEFAULT NULL, PRIMARY KEY (i));
Query OK, 0 rows affected (0.02 sec)
# Triggering automatic recalculation of persistent statistics
mysql> insert into t_upd values (1, 1);
Query OK, 1 row affected (0.00 sec)
mysql> select database_name, table_name, index_name, last_update, stat_name from mysql.innodb_index_stats where database_name = 'test' ;
+---------------+------------+------------+---------------------+--------------+
| database_name | table_name | index_name | last_update | stat_name |
+---------------+------------+------------+---------------------+--------------+
| test | t1 | PRIMARY | 2025-09-12 03:19:32 | n_diff_pfx01 |
| test | t1 | PRIMARY | 2025-09-12 03:19:32 | n_leaf_pages |
| test | t1 | PRIMARY | 2025-09-12 03:19:32 | size |
| test | t_upd | PRIMARY | 2025-09-12 03:19:37 | n_diff_pfx01 |
| test | t_upd | PRIMARY | 2025-09-12 03:19:37 | n_leaf_pages |
| test | t_upd | PRIMARY | 2025-09-12 03:19:37 | size |
+---------------+------------+------------+---------------------+--------------+
6 rows in set (0.00 sec)
mysql> update t_upd set value = value + 1 where i = 1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
(Maybe we need to run the above update statement multiple times to trigger automatic recalculation)
mysql> select database_name, table_name, index_name, last_update, stat_name from mysql.innodb_index_stats where database_name = 'test' ;
+---------------+------------+------------+---------------------+--------------+
| database_name | table_name | index_name | last_update | stat_name |
+---------------+------------+------------+---------------------+--------------+
| test | t1 | PRIMARY | 2025-09-12 03:19:32 | n_diff_pfx01 |
| test | t1 | PRIMARY | 2025-09-12 03:19:32 | n_leaf_pages |
| test | t1 | PRIMARY | 2025-09-12 03:19:32 | size |
| test | t_upd | PRIMARY | 2025-09-12 03:20:20 | n_diff_pfx01 |
| test | t_upd | PRIMARY | 2025-09-12 03:20:20 | n_leaf_pages |
| test | t_upd | PRIMARY | 2025-09-12 03:20:20 | size |
+---------------+------------+------------+---------------------+--------------+
6 rows in set (0.00 sec)
-> Statistics of t_upd was updated.
After the above steps, confirmed no warnings were reported in /var/log/mysqld.log.
# Performing some DMLs with exclusive MDL
mysql> lock table t1 write;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into t1 values (1);
Query OK, 1 row affected (0.01 sec)
mysql> delete from t1;
Query OK, 1 row affected (0.00 sec)
mysql> select database_name, table_name, index_name, last_update, stat_name from mysql.innodb_index_stats where database_name = 'test' ;
+---------------+------------+------------+---------------------+--------------+
| database_name | table_name | index_name | last_update | stat_name |
+---------------+------------+------------+---------------------+--------------+
| test | t1 | PRIMARY | 2025-09-12 03:22:14 | n_diff_pfx01 |
| test | t1 | PRIMARY | 2025-09-12 03:22:14 | n_leaf_pages |
| test | t1 | PRIMARY | 2025-09-12 03:22:14 | size |
| test | t_upd | PRIMARY | 2025-09-12 03:20:20 | n_diff_pfx01 |
| test | t_upd | PRIMARY | 2025-09-12 03:20:20 | n_leaf_pages |
| test | t_upd | PRIMARY | 2025-09-12 03:20:20 | size |
+---------------+------------+------------+---------------------+--------------+
6 rows in set (0.00 sec)
-> Statistics of t1 was updated because of DMLs on that table.
After the above steps, background histogram update warning appeared in /var/log/mysqld.log :
-------
2025-09-12T03:22:19.845540Z 0 [Warning] [MY-015116] [Server] Background histogram update on test.t1: Lock wait timeout exceeded; try restarting transaction
-------
According to https://bugs.mysql.com/bug.php?id=116145, I understand the warning above is expected behavior. In this case "lock table t1 write;" prevented background thread from acquiring locks to check the existence of histograms.
# Unlocking table
mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)
mysql> select * from performance_schema.metadata_locks\G
*************************** 1. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: performance_schema
OBJECT_NAME: metadata_locks
COLUMN_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140403623592656
LOCK_TYPE: SHARED_READ
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE: sql_parse.cc:6178
OWNER_THREAD_ID: 42
OWNER_EVENT_ID: 117
*************************** 2. row ***************************
OBJECT_TYPE: SCHEMA
OBJECT_SCHEMA: performance_schema
OBJECT_NAME: NULL
COLUMN_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140403633337808
LOCK_TYPE: INTENTION_EXCLUSIVE
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE: dd_schema.cc:108
OWNER_THREAD_ID: 42
OWNER_EVENT_ID: 117
2 rows in set (0.00 sec)
-> We can see no exclusive MDLs on both t1 and t_upd.
# Performing updates on t_upd
mysql> update t_upd set value = value + 1 where i = 1;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1 Changed: 1 Warnings: 0
(Maybe we need to run the above statement multiple times to trigger automatic recalculation)
mysql> select database_name, table_name, index_name, last_update, stat_name from mysql.innodb_index_stats where database_name = 'test' ;
+---------------+------------+------------+---------------------+--------------+
| database_name | table_name | index_name | last_update | stat_name |
+---------------+------------+------------+---------------------+--------------+
| test | t1 | PRIMARY | 2025-09-12 03:22:14 | n_diff_pfx01 |
| test | t1 | PRIMARY | 2025-09-12 03:22:14 | n_leaf_pages |
| test | t1 | PRIMARY | 2025-09-12 03:22:14 | size |
| test | t_upd | PRIMARY | 2025-09-12 03:25:17 | n_diff_pfx01 |
| test | t_upd | PRIMARY | 2025-09-12 03:25:17 | n_leaf_pages |
| test | t_upd | PRIMARY | 2025-09-12 03:25:17 | size |
+---------------+------------+------------+---------------------+--------------+
6 rows in set (0.00 sec)
-> Statistics of t_upd was updated.
However the following warning was reported in /var/log/mysqld.log, even though no MDLs were acquired on t_upd .
-------
2025-09-12T03:25:17.510648Z 0 [Warning] [MY-015116] [Server] Background histogram update on test.t_upd: Lock wait timeout exceeded; try restarting transaction
-------
Also I observed the same warning against t1, which was already unlocked from the exclusive MDL:
mysql> insert into t1 values (1);
Query OK, 1 row affected (0.01 sec)
mysql> delete from t1;
Query OK, 1 row affected (0.01 sec)
mysql> select database_name, table_name, index_name, last_update, stat_name from mysql.innodb_index_stats where database_name = 'test' ;
+---------------+------------+------------+---------------------+--------------+
| database_name | table_name | index_name | last_update | stat_name |
+---------------+------------+------------+---------------------+--------------+
| test | t1 | PRIMARY | 2025-09-12 03:26:52 | n_diff_pfx01 |
| test | t1 | PRIMARY | 2025-09-12 03:26:52 | n_leaf_pages |
| test | t1 | PRIMARY | 2025-09-12 03:26:52 | size |
| test | t_upd | PRIMARY | 2025-09-12 03:25:17 | n_diff_pfx01 |
| test | t_upd | PRIMARY | 2025-09-12 03:25:17 | n_leaf_pages |
| test | t_upd | PRIMARY | 2025-09-12 03:25:17 | size |
+---------------+------------+------------+---------------------+--------------+
6 rows in set (0.00 sec)
/var/log/mysqld.log:
-------
2025-09-12T03:26:52.390955Z 0 [Warning] [MY-015116] [Server] Background histogram update on test.t1: Lock wait timeout exceeded; try restarting transaction
-------
Suggested fix:
Please fix background threads so that they are not blocked when checking histograms of tables on which no exclusive MDL is acquired.
