Deadlock Troubleshooting in Percona Server for MySQL 5.7

Deadlock Troubleshooting MySQL

Disclaimer: the following script only works for Percona Server for MySQL 5.7, and relies on enabling performance schema (PS) instrumentation which can add overhead on high concurrent systems, and is not intended for continuous production usage as it’s a POC (proof of concept).

Introduction

Deadlock Troubleshooting MySQLIn Percona Support, we frequently receive tickets related to deadlocks and even though the deadlock concept is simple, troubleshooting might not be in all cases. 

As explained in How to Deal with MySQL Deadlocks, a deadlock occurs when two or more transactions mutually hold and request for locks, creating a cycle of dependencies. MySQL will detect deadlocks and kill one of the transactions (making it rollback), and the deadlock will be printed in SEIS (show engine innodb status). Limitations of using this approach are that 1) Only one (latest) deadlock will be printed -potentially missing many of the deadlocks that occur if you are not actively checking- (unless enabling innodb_print_all_deadlocks), and 2) only the last executed DML is printed, which might not shed enough light to identify the offending transaction for complex deadlocks.

Using pt-deadlock-logger will overcome the difficulty from number one, as it will log all deadlocks occurring, but what about number two?

For Percona Server for MySQL 5.7, I have developed the following script (that you can find in our support snippets repo) that prints SQL history for two transactions involved in a deadlock, that can help in troubleshooting some complex deadlock cases. Note that most of the time, a deadlock will consist of two transactions, but other times there can be more transactions involved, in which case the script will be partially useful.

Installation

# download script
wget https://raw.githubusercontent.com/percona/support-snippets/master/mysql/deadlock_catcher.sh
chmod a+x deadlock_catcher.sh

# you need to set correct user/password before executing, i.e 
# MYSQL="mysql -u root -psekret"
./deadlock_catcher.sh

Executing the script will show the following prompts:

# the above script will prompt you about enabling the needed instrumentation:
SET GLOBAL innodb_print_all_deadlocks=1
...
Need to enable all statement/ instruments in performance schema, write YES to continue
YES
--------------
UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', timed = 'YES' WHERE NAME LIKE 'statement/%'
...
Need to enable all event_statements/ consumers, write YES to continue
YES
mysql: [Warning] Using a password on the command line interface can be insecure.
--------------
UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE 'events_statements%'

Then, the operating system prompt won’t be returning, as the script will keep running, scanning for deadlocks. (You can execute with “&” to run in the background.)

Note: deadlock_logger script will start logging deadlocks occurring only AFTER the script execution.

Generating a Deadlock

You need to open two sessions and execute the following interleaved:

Tx1:
drop table if exists t1;
create table t1 (id int auto_increment primary key);
begin; select * from t1;

Tx2:
begin; select * from t1;
insert into t1 values (1);

Tx1:
insert into t1 values (2);
insert into t1 values (1);

Tx2:
insert into t1 values (2);
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

Checking “deadlock_logger.sh” output we can see the history of transactions for above threads (you need to read from bottom to the top):

Tx1:
# Adding column names for better readability
# ev.thread_id, ev.EVENT_ID, ev.END_EVENT_ID, ev.EVENT_NAME, ev.SQL_TEXT
42 10 10 statement/sql/insert insert into t1 values (1)
42 9 9 statement/sql/insert insert into t1 values (2)
42 8 8 statement/sql/select select * from t1
42 7 7 statement/sql/begin begin
42 6 6 statement/sql/create_table create table t1 (id int auto_increment primary key)
42 5 5 statement/sql/drop_table drop table if exists t1
42 4 4 statement/sql/select select @@version_comment limit 1
42 3 3 statement/com/Field List NULL
42 2 2 statement/sql/show_tables show tables
42 1 1 statement/sql/show_databases show databases
Tx2:
# Adding column names for better readability
# ev.thread_id, ev.EVENT_ID, ev.END_EVENT_ID, ev.EVENT_NAME, ev.SQL_TEXT
43 8 8 statement/sql/insert insert into t1 values (2)
43 7 7 statement/sql/insert insert into t1 values (1)
43 6 6 statement/sql/select select * from t1
43 5 5 statement/sql/begin begin
43 4 4 statement/sql/select select @@version_comment limit 1
43 3 3 statement/com/Field List NULL
43 2 2 statement/sql/show_tables show tables
43 1 1 statement/sql/show_databases show databases

It can be seen that the entire history transaction is being fetched from Performance Schema tables, which helps identify deadlocks in complex transactions.

Limitations of the Script

  • Currently only works for Percona Server for MySQL 5.7
  • Enabling Performance Schema instrumentation will add some overhead to MySQL
  • The script works by tailing the error.log, so modifying the location or content at runtime can have unexpected results
  • The script relies on “performance_schema.events_statements_history” whose max rows are limited by  performance_schema_events_statements_history_long_size and performance_schema_events_statements_history_size. For high activity servers, the history table might rotate before the deadlock occurs, resulting in a partially incomplete print of statements, instead of printing the entire life of the thread.

Conclusion

Troubleshooting deadlocks can be hard, but after checking the entire history of statements executed for the threads involved in the deadlock, it can be easier to understand why a deadlock happened. Test the script and performance degradation before going to high activity and/or critical production systems!


by Carlos Tutte via Percona Database Performance Blog

Comments