Can MySQL log lock waits?

Posted on

Question :

Is it possible to have MySQL log queries or transactions where lock waits occur? One can debug specific application errors generated from lock wait timeout errors from the DB but without the ability to become aware of the occurrences of lock waits that don’t hit the timeout, it seems difficult to anticipate where the next timeout error may be lurking.

Is there a way to have MySQL log these?

Answer :

I have some good news and some bad news.

The good news is that this will work for MySQL. The
bad news is that it won’t work for 5.5. In any case,
I would advise moving to 5.6 anyway, in no small part
due to the vast improvements made to the performance
schema (see below).

I compiled and installed 5.6 (am currently running
5.7 – bit of a bleeding edge type of guy 🙂 ).

After some frustrating Googling &c. and barking
up a forest of wrong trees, I finally came up
with this.

SELECT Table_schema, Table_Name, Column_Name 
FROM Information_Schema.Columns 
Where (Table_Schema = 'information_schema'
or Table_Schema = 'sys') 
AND Column_Name like '%lock%';

But, if you check Result 1 (at end of post), you’ll
see I didn’t have much luck.

But then I remembered Mark Leith’s (Software
Development Senior Manager, Oracle) MySQL
sys schema (and ps_helper). These are available
from here

https://github.com/MarkLeith.

I ran the same SQL as above with

or Table_Schema = ‘sys’

added, and I came up with Result 2 (at end
of post).

Innodb_Wait_Locks looked promising, so I ran a DESC.

mysql> DESC sys.innodb_lock_waits;
+---------------------+---------------------+------+-----+---------+-------+
| Field               | Type                | Null | Key | Default | Extra |
+---------------------+---------------------+------+-----+---------+-------+
| waiting_trx_id      | varchar(18)         | NO   |     |         |       |
| waiting_thread      | bigint(21) unsigned | NO   |     | 0       |       |
| waiting_query       | longtext            | YES  |     | NULL    |       |
| waiting_lock_id     | varchar(81)         | NO   |     |         |       |
| waiting_lock_mode   | varchar(32)         | NO   |     |         |       |
| waiting_lock_type   | varchar(32)         | NO   |     |         |       |
| waiting_lock_table  | varchar(1024)       | NO   |     |         |       |
| waiting_lock_index  | varchar(1024)       | YES  |     | NULL    |       |
| blocking_trx_id     | varchar(18)         | NO   |     |         |       |
| blocking_thread     | bigint(21) unsigned | NO   |     | 0       |       |
| blocking_query      | longtext            | YES  |     | NULL    |       |
| blocking_lock_id    | varchar(81)         | NO   |     |         |       |
| blocking_lock_mode  | varchar(32)         | NO   |     |         |       |
| blocking_lock_type  | varchar(32)         | NO   |     |         |       |
| blocking_lock_table | varchar(1024)       | NO   |     |         |       |
| blocking_lock_index | varchar(1024)       | YES  |     | NULL    |       |
+---------------------+---------------------+------+-----+---------+-------+
16 rows in set (0.00 sec)

So, there you have pretty much all the info you could
want about locks, (I hope!).

No, as to logging these, there doesn’t appear to be a logging function
for this table – many of the p_s tables have accompanying history
tables. I think that there’s a good case for keeping a history of
this one – but you can “roll your own” using MySQL events to
append the contents of this table to a logging table.

Say every one second (or period of your choice) and then check to
see which of your queries are regularlary appearing in the
logging table. It’s perhaps not up to Oracle’s functionality,
but it’s getting there 🙂

Result 1

+--------------------+------------------------+----------------------------+
| Table_schema       | Table_Name             | Column_Name                |
+--------------------+------------------------+----------------------------+
| information_schema | PROFILING              | BLOCK_OPS_IN               |
| information_schema | PROFILING              | BLOCK_OPS_OUT              |
| information_schema | INNODB_LOCKS           | lock_id                    |
| information_schema | INNODB_LOCKS           | lock_trx_id                |
| information_schema | INNODB_LOCKS           | lock_mode                  |
| information_schema | INNODB_LOCKS           | lock_type                  |
| information_schema | INNODB_LOCKS           | lock_table                 |
| information_schema | INNODB_LOCKS           | lock_index                 |
| information_schema | INNODB_LOCKS           | lock_space                 |
| information_schema | INNODB_LOCKS           | lock_page                  |
| information_schema | INNODB_LOCKS           | lock_rec                   |
| information_schema | INNODB_LOCKS           | lock_data                  |
| information_schema | INNODB_TRX             | trx_requested_lock_id      |
| information_schema | INNODB_TRX             | trx_tables_locked          |
| information_schema | INNODB_TRX             | trx_lock_structs           |
| information_schema | INNODB_TRX             | trx_lock_memory_bytes      |
| information_schema | INNODB_TRX             | trx_rows_locked            |
| information_schema | INNODB_TRX             | trx_autocommit_non_locking |
| information_schema | INNODB_LOCK_WAITS      | requested_lock_id          |
| information_schema | INNODB_LOCK_WAITS      | blocking_trx_id            |
| information_schema | INNODB_LOCK_WAITS      | blocking_lock_id           |
| information_schema | INNODB_BUFFER_PAGE_LRU | FREE_PAGE_CLOCK            |
| information_schema | INNODB_BUFFER_PAGE     | BLOCK_ID                   |
| information_schema | INNODB_BUFFER_PAGE     | FREE_PAGE_CLOCK            |
+--------------------+------------------------+----------------------------+
24 rows in set (0.02 sec)

Result 2

+--------------------+-------------------------------------+----------------------------+
| Table_schema       | Table_Name                          | Column_Name                |
+--------------------+-------------------------------------+----------------------------+
| information_schema | PROFILING                           | BLOCK_OPS_IN               |
| information_schema | PROFILING                           | BLOCK_OPS_OUT              |
| information_schema | INNODB_LOCKS                        | lock_id                    |
| information_schema | INNODB_LOCKS                        | lock_trx_id                |
| information_schema | INNODB_LOCKS                        | lock_mode                  |
| information_schema | INNODB_LOCKS                        | lock_type                  |
| information_schema | INNODB_LOCKS                        | lock_table                 |
| information_schema | INNODB_LOCKS                        | lock_index                 |
| information_schema | INNODB_LOCKS                        | lock_space                 |
| information_schema | INNODB_LOCKS                        | lock_page                  |
| information_schema | INNODB_LOCKS                        | lock_rec                   |
| information_schema | INNODB_LOCKS                        | lock_data                  |
| information_schema | INNODB_TRX                          | trx_requested_lock_id      |
| information_schema | INNODB_TRX                          | trx_tables_locked          |
| information_schema | INNODB_TRX                          | trx_lock_structs           |
| information_schema | INNODB_TRX                          | trx_lock_memory_bytes      |
| information_schema | INNODB_TRX                          | trx_rows_locked            |
| information_schema | INNODB_TRX                          | trx_autocommit_non_locking |
| information_schema | INNODB_LOCK_WAITS                   | requested_lock_id          |
| information_schema | INNODB_LOCK_WAITS                   | blocking_trx_id            |
| information_schema | INNODB_LOCK_WAITS                   | blocking_lock_id           |
| information_schema | INNODB_BUFFER_PAGE_LRU              | FREE_PAGE_CLOCK            |
| information_schema | INNODB_BUFFER_PAGE                  | BLOCK_ID                   |
| information_schema | INNODB_BUFFER_PAGE                  | FREE_PAGE_CLOCK            |
| sys                | host_summary_by_statement_latency   | lock_latency               |
| sys                | host_summary_by_statement_type      | lock_latency               |
| sys                | innodb_lock_waits                   | waiting_lock_id            |
| sys                | innodb_lock_waits                   | waiting_lock_mode          |
| sys                | innodb_lock_waits                   | waiting_lock_type          |
| sys                | innodb_lock_waits                   | waiting_lock_table         |
| sys                | innodb_lock_waits                   | waiting_lock_index         |
| sys                | innodb_lock_waits                   | blocking_trx_id            |
| sys                | innodb_lock_waits                   | blocking_thread            |
| sys                | innodb_lock_waits                   | blocking_query             |
| sys                | innodb_lock_waits                   | blocking_lock_id           |
| sys                | innodb_lock_waits                   | blocking_lock_mode         |
| sys                | innodb_lock_waits                   | blocking_lock_type         |
| sys                | innodb_lock_waits                   | blocking_lock_table        |
| sys                | innodb_lock_waits                   | blocking_lock_index        |
| sys                | processlist                         | lock_latency               |
| sys                | statement_analysis                  | lock_latency               |
| sys                | user_summary_by_statement_latency   | lock_latency               |
| sys                | user_summary_by_statement_type      | lock_latency               |
| sys                | x$host_summary_by_statement_latency | lock_latency               |
| sys                | x$host_summary_by_statement_type    | lock_latency               |
| sys                | x$innodb_lock_waits                 | waiting_lock_id            |
| sys                | x$innodb_lock_waits                 | waiting_lock_mode          |
| sys                | x$innodb_lock_waits                 | waiting_lock_type          |
| sys                | x$innodb_lock_waits                 | waiting_lock_table         |
| sys                | x$innodb_lock_waits                 | waiting_lock_index         |
| sys                | x$innodb_lock_waits                 | blocking_trx_id            |
| sys                | x$innodb_lock_waits                 | blocking_thread            |
| sys                | x$innodb_lock_waits                 | blocking_query             |
| sys                | x$innodb_lock_waits                 | blocking_lock_id           |
| sys                | x$innodb_lock_waits                 | blocking_lock_mode         |
| sys                | x$innodb_lock_waits                 | blocking_lock_type         |
| sys                | x$innodb_lock_waits                 | blocking_lock_table        |
| sys                | x$innodb_lock_waits                 | blocking_lock_index        |
| sys                | x$processlist                       | lock_latency               |
| sys                | x$statement_analysis                | lock_latency               |
| sys                | x$user_summary_by_statement_latency | lock_latency               |
| sys                | x$user_summary_by_statement_type    | lock_latency               |
+--------------------+-------------------------------------+----------------------------+
62 rows in set (0.04 sec)

Leave a Reply

Your email address will not be published. Required fields are marked *