My Thoughts on MySQL

Category Archives: MySQL 5.7

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:

Lock wait timeout error

1

2

mysql>UPDATEworld.CitySETPopulation=Population+999WHEREID=130;

ERROR1205(HY000):Lockwaittimeoutexceeded;tryrestartingtransaction

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):

Connection 1:

Test case - Connection 1

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

Connection1>START TRANSACTION;

QueryOK,0rowsaffected(0.00sec)

Connection1>UPDATEworld.CitySETPopulation=Population+1WHEREID=130;

QueryOK,1rowaffected(0.00sec)

Rowsmatched:1Changed:1Warnings:0

Connection1>UPDATEworld.CitySETPopulation=Population+1WHEREID=131;

QueryOK,1rowaffected(0.00sec)

Rowsmatched:1Changed:1Warnings:0

Connection1>UPDATEworld.CitySETPopulation=Population+1WHEREID=132;

QueryOK,1rowaffected(0.00sec)

Rowsmatched:1Changed:1Warnings:0

Connection1>UPDATEworld.CitySETPopulation=Population+1WHEREID=133;

QueryOK,1rowaffected(0.00sec)

Rowsmatched:1Changed:1Warnings:0

Connection 2 (blocks for innodb_lock_wait_timeout seconds):

Test case - Connection 2

1

Connection2>UPDATEworld.CitySETPopulation=Population+999WHEREID=130;

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

sys.innodb_lock_waits

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

28

29

30

31

32

33

34

35

36

37

38

39

40

41

42

43

44

45

46

47

48

Connection3>SELECT*FROMsys.innodb_lock_waits\G

***************************1.row***************************

wait_started:2017-04-1509: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-1509:54:53

waiting_trx_age:00:00:03

waiting_trx_rows_locked:1

waiting_trx_rows_modified:0

waiting_pid:5

waiting_query:UPDATEworld.CitySETPopulati...opulation+999

WHEREID=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-1509:54:46

blocking_trx_age:00:00:10

blocking_trx_rows_locked:4

blocking_trx_rows_modified:4

sql_kill_blocking_query:KILL QUERY3

sql_kill_blocking_connection:KILL3

1rowinset,3warnings(0.00sec)

Connection3>SHOWWARNINGS\G

***************************1.row***************************

Level:Warning

Code:1681

Message:'INFORMATION_SCHEMA.INNODB_LOCK_WAITS'isdeprecated

andwillberemovedinafuturerelease.

***************************2.row***************************

Level:Warning

Code:1681

Message:'INFORMATION_SCHEMA.INNODB_LOCKS'isdeprecatedand

willberemovedinafuturerelease.

***************************3.row***************************

Level:Warning

Code:1681

Message:'INFORMATION_SCHEMA.INNODB_LOCKS'isdeprecatedand

willberemovedinafuturerelease.

3rowsinset(0.00sec)

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:

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:

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:

Enabling transaction monitoring

1

2

3

4

5

6

7

8

9

10

11

mysql>UPDATEperformance_schema.setup_consumers

SETENABLED='YES'

WHERENAME='events_transactions_current';

QueryOK,1rowaffected(0.00sec)

Rowsmatched:1Changed:1Warnings:0

mysql>UPDATEperformance_schema.setup_instruments

SETENABLED='YES'

WHERENAME='transaction';

QueryOK,1rowaffected(0.00sec)

Rowsmatched:1Changed:1Warnings:0

Note: 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:

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:

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.

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):