Bug #99206 lock_wait_timeout is taking twice time while adding new partition in table
Submitted: 8 Apr 8:08 Modified: 8 Apr 13:28
Reporter: lalit Choudhary Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Locking Severity:S3 (Non-critical)
Version:5.7.29 OS:Any
Assigned to: CPU Architecture:Any

[8 Apr 8:08] lalit Choudhary
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
[8 Apr 12:46] MySQL Verification Team
Hi Mr. Choudhary,

We will have to analyse whether a solution in 8.0 can be ported back to 5.7. Hence, you will have to wait for a while since we have to analyse whether it is possible or not.
[8 Apr 13:28] MySQL Verification Team
Hi Mr. Choudhary,

Thank you for your report.

I managed to repeat the behaviour for mysql-5.7 only.

Verified as reported.
[9 Apr 13:06] MySQL Verification Team
Just changing a category.