Description:
As per mysql documentation for lock_wait_timeout
"The timeout value applies separately for each metadata lock attempt. A given statement can require more than one lock, so it is possible for the statement to block for longer than the lock_wait_timeout value before reporting a timeout error. When lock timeout occurs, ER_LOCK_WAIT_TIMEOUT is reported."
But in the given test for partition table even with one metadata lock, lock_wait_timeout taking twice the time as compared to its current timeout value. example: lock_wait_timeout=5 so for partition table timeout happening after 10 seconds
for the Normal table(without partitioning) it's working fine.
Issue not reproducible with 8.0.19 for the same partition table and test.
How to repeat:
Steps to reproduce:
set global lock_wait_timeout=5;
UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES', TIMED = 'YES'
WHERE NAME = 'wait/lock/metadata/sql/mdl';
exit
start new connections:
connection#1
show variables like 'lock%wait%time%';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| lock_wait_timeout | 5 |
+-------------------+-------+
1 row in set (0.00 sec)
CREATE TABLE `t11` (
`id` bigint(20) NOT NULL AUTO_INCREMENT,
`partition_id` varchar(100) NOT NULL,
PRIMARY KEY (`id`,`partition_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci ROW_FORMAT=DYNAMIC
PARTITION BY LIST COLUMNS(partition_id)
(PARTITION p1 VALUES IN ('p1') ENGINE = InnoDB,
PARTITION p2 VALUES IN ('p2') ENGINE = InnoDB);
> start transaction;
Query OK, 0 rows affected (0.00 sec)
> select * from t11;
connection#2
$ time ./use test -e 'ALTER TABLE t11 add partition(partition p3 values in ("p3"))'
ERROR 1205 (HY000) at line 1: Lock wait timeout exceeded; try restarting transaction
real 0m10.054s
user 0m0.006s
sys 0m0.017s
connection#3
> show processlist;
+----+----------+-----------+------+---------+------+---------------------------------+--------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+----------+-----------+------+---------+------+---------------------------------+--------------------------------------------------------------+
| 5 | msandbox | localhost | test | Sleep | 14 | | NULL |
| 6 | msandbox | localhost | NULL | Query | 0 | starting | show processlist |
| 10 | msandbox | localhost | test | Query | 9 | Waiting for table metadata lock | ALTER TABLE t11 add partition(partition p3 values in ("p3")) |
+----+----------+-----------+------+---------+------+---------------------------------+--------------------------------------------------------------+
3 rows in set (0.00 sec)
> select * from performance_schema.metadata_locks where OBJECT_NAME='t11'\G
*************************** 1. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: test
OBJECT_NAME: t11
OBJECT_INSTANCE_BEGIN: 140619578140208
LOCK_TYPE: SHARED_READ
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 37
OWNER_EVENT_ID: 12
*************************** 2. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: test
OBJECT_NAME: t11
OBJECT_INSTANCE_BEGIN: 140619856388816
LOCK_TYPE: SHARED_UPGRADABLE
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE:
OWNER_THREAD_ID: 41
OWNER_EVENT_ID: 3
*************************** 3. row ***************************
OBJECT_TYPE: TABLE
OBJECT_SCHEMA: test
OBJECT_NAME: t11
OBJECT_INSTANCE_BEGIN: 140619856405168
LOCK_TYPE: EXCLUSIVE
LOCK_DURATION: TRANSACTION
LOCK_STATUS: PENDING
SOURCE:
OWNER_THREAD_ID: 41
OWNER_EVENT_ID: 3
3 rows in set (0.00 sec)
*********************
Case# Table without partitioning
Connection#1
> create table foo (c1 int primary key, c2 char(50));
> start transaction;
> select * from foo;
Empty set (0.00 sec)
Connection#2
$ time ./use test -e 'ALTER TABLE foo add column c3 char(50)'
ERROR 1205 (HY000) at line 1: Lock wait timeout exceeded; try restarting transaction
real 0m5.028s
user 0m0.011s
sys 0m0.003s
Coneection#3
> show processlist;
+----+----------+-----------+------+---------+------+---------------------------------+----------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+----------+-----------+------+---------+------+---------------------------------+----------------------------------------+
| 5 | msandbox | localhost | test | Sleep | 18 | | NULL |
| 6 | msandbox | localhost | NULL | Query | 0 | starting | show processlist |
| 9 | msandbox | localhost | test | Query | 2 | Waiting for table metadata lock | ALTER TABLE foo add column c3 char(50) |
+----+----------+-----------+------+---------+------+---------------------------------+----------------------------------------+
3 rows in set (0.00 sec)
Suggested fix:
lock_wait_timeout should be consistent
Description: As per mysql documentation for lock_wait_timeout "The timeout value applies separately for each metadata lock attempt. A given statement can require more than one lock, so it is possible for the statement to block for longer than the lock_wait_timeout value before reporting a timeout error. When lock timeout occurs, ER_LOCK_WAIT_TIMEOUT is reported." But in the given test for partition table even with one metadata lock, lock_wait_timeout taking twice the time as compared to its current timeout value. example: lock_wait_timeout=5 so for partition table timeout happening after 10 seconds for the Normal table(without partitioning) it's working fine. Issue not reproducible with 8.0.19 for the same partition table and test. How to repeat: Steps to reproduce: set global lock_wait_timeout=5; UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME = 'wait/lock/metadata/sql/mdl'; exit start new connections: connection#1 show variables like 'lock%wait%time%'; +-------------------+-------+ | Variable_name | Value | +-------------------+-------+ | lock_wait_timeout | 5 | +-------------------+-------+ 1 row in set (0.00 sec) CREATE TABLE `t11` ( `id` bigint(20) NOT NULL AUTO_INCREMENT, `partition_id` varchar(100) NOT NULL, PRIMARY KEY (`id`,`partition_id`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci ROW_FORMAT=DYNAMIC PARTITION BY LIST COLUMNS(partition_id) (PARTITION p1 VALUES IN ('p1') ENGINE = InnoDB, PARTITION p2 VALUES IN ('p2') ENGINE = InnoDB); > start transaction; Query OK, 0 rows affected (0.00 sec) > select * from t11; connection#2 $ time ./use test -e 'ALTER TABLE t11 add partition(partition p3 values in ("p3"))' ERROR 1205 (HY000) at line 1: Lock wait timeout exceeded; try restarting transaction real 0m10.054s user 0m0.006s sys 0m0.017s connection#3 > show processlist; +----+----------+-----------+------+---------+------+---------------------------------+--------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+----------+-----------+------+---------+------+---------------------------------+--------------------------------------------------------------+ | 5 | msandbox | localhost | test | Sleep | 14 | | NULL | | 6 | msandbox | localhost | NULL | Query | 0 | starting | show processlist | | 10 | msandbox | localhost | test | Query | 9 | Waiting for table metadata lock | ALTER TABLE t11 add partition(partition p3 values in ("p3")) | +----+----------+-----------+------+---------+------+---------------------------------+--------------------------------------------------------------+ 3 rows in set (0.00 sec) > select * from performance_schema.metadata_locks where OBJECT_NAME='t11'\G *************************** 1. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: test OBJECT_NAME: t11 OBJECT_INSTANCE_BEGIN: 140619578140208 LOCK_TYPE: SHARED_READ LOCK_DURATION: TRANSACTION LOCK_STATUS: GRANTED SOURCE: OWNER_THREAD_ID: 37 OWNER_EVENT_ID: 12 *************************** 2. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: test OBJECT_NAME: t11 OBJECT_INSTANCE_BEGIN: 140619856388816 LOCK_TYPE: SHARED_UPGRADABLE LOCK_DURATION: TRANSACTION LOCK_STATUS: GRANTED SOURCE: OWNER_THREAD_ID: 41 OWNER_EVENT_ID: 3 *************************** 3. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: test OBJECT_NAME: t11 OBJECT_INSTANCE_BEGIN: 140619856405168 LOCK_TYPE: EXCLUSIVE LOCK_DURATION: TRANSACTION LOCK_STATUS: PENDING SOURCE: OWNER_THREAD_ID: 41 OWNER_EVENT_ID: 3 3 rows in set (0.00 sec) ********************* Case# Table without partitioning Connection#1 > create table foo (c1 int primary key, c2 char(50)); > start transaction; > select * from foo; Empty set (0.00 sec) Connection#2 $ time ./use test -e 'ALTER TABLE foo add column c3 char(50)' ERROR 1205 (HY000) at line 1: Lock wait timeout exceeded; try restarting transaction real 0m5.028s user 0m0.011s sys 0m0.003s Coneection#3 > show processlist; +----+----------+-----------+------+---------+------+---------------------------------+----------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+----------+-----------+------+---------+------+---------------------------------+----------------------------------------+ | 5 | msandbox | localhost | test | Sleep | 18 | | NULL | | 6 | msandbox | localhost | NULL | Query | 0 | starting | show processlist | | 9 | msandbox | localhost | test | Query | 2 | Waiting for table metadata lock | ALTER TABLE foo add column c3 char(50) | +----+----------+-----------+------+---------+------+---------------------------------+----------------------------------------+ 3 rows in set (0.00 sec) Suggested fix: lock_wait_timeout should be consistent