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