MySQL has facilities to monitor locking in real time by using MySQL feature to monitor database server at the low level. It is called Performance Schema. In this post you will learn how to use it in order to monitor and debug MySQL locks. Detailed explanation of Performance Schema is out of scope of this blog post. If you want to learn more please check official documentation: https://dev.mysql.com/doc/refman/5.7/en/performance-schema.html.
Follow this steps:
1. Enable Performance Schema
Check if Performance Schema is already enabled
|
1 |
$ mysqld --verbose --help | grep ^performance-schema | less |
if enabled you should see line like this:
|
1 |
performance-schema TRUE |
or execute this query from mysql client:
|
1 2 3 4 5 6 7 |
mysql> SHOW VARIABLES LIKE "performance_schema"; +--------------------+-------+ | Variable_name | Value | +--------------------+-------+ | performance_schema | ON | +--------------------+-------+ 1 row in set (0.00 sec) |
Enable Performance Schema
If Perforamnce Schema is not enabled, edit my.conf. If you don’t where is MySQL config file execute:
|
1 |
$ mysql --help | grep my.cnf |
and you will see something like this:
|
1 2 |
order of preference, my.cnf, $MYSQL_TCP_PORT, /etc/my.cnf /etc/mysql/my.cnf /usr/etc/my.cnf ~/.my.cnf |
Now edit the file
|
1 |
$ sudo vim /etc/my.cnf |
And add performance_schema=ON under [mysqld] section
|
1 2 |
[mysqld] performance_schema=ON |
Locking information
Locking information can be accessed through metadata_locks table. It is not enabled by default. To enable it put this line performance_schema_instrument = 'wait/lock/metadata/sql/mdl=ON' in your my.conf below the line we added in previous step. Now your my.conf should look something like:
|
1 2 3 |
[mysqld] performance_schema=ON performance_schema_instrument = 'wait/lock/metadata/sql/mdl=ON' |
For more info check: https://dev.mysql.com/doc/refman/5.7/en/metadata-locks-table.html.
Restart the mysql server
CentOS:
|
1 |
$ sudo service mysqld restart |
Ubuntu:
|
1 |
$ sudo restart mysqld |
Check did you correctly set the options:
|
1 |
$ mysqld --verbose --help | grep ^performance-schema | less |
and search for performance_schema and performance_schema_instrument.
See it in action
|
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 |
<?php $host = "localhost"; $db = "DB_NAME"; $user = "DB_USER"; $password = "DB_PASSWORD"; $charset = "utf8mb4"; $pdo = new PDO( "mysql:host=$host;dbname=$db;charset=$charset", $user, $password, array( PDO::ATTR_ERRMODE => PDO::ERRMODE_EXCEPTION, PDO::ATTR_DEFAULT_FETCH_MODE => PDO::FETCH_ASSOC, PDO::ATTR_EMULATE_PREPARES => false )); $stmt = $pdo->query("SELECT GET_LOCK('ztesch', 10) as lck"); $row = $stmt->fetch(); echo "lock granted=($row[lck])\n"; echo "sleep for 30s\n"; sleep(30); echo "done\n"; ?> |
Lock timeout is 10s and script is holding the lock for 30s before terminates and releases the lock. This will give us enough time to see what is going on. Execute the script from cmd line, in parallel, 2-3s apart.
The metadata_locks will show the locks, one GRANTED one PENDING.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
mysql> select * from performance_schema.metadata_locks\G *************************** 1. row *************************** OBJECT_TYPE: USER LEVEL LOCK OBJECT_SCHEMA: NULL OBJECT_NAME: ztesch OBJECT_INSTANCE_BEGIN: 139780046259664 LOCK_TYPE: EXCLUSIVE LOCK_DURATION: EXPLICIT LOCK_STATUS: GRANTED SOURCE: item_func.cc:5532 OWNER_THREAD_ID: 33 OWNER_EVENT_ID: 3 *************************** 2. row *************************** OBJECT_TYPE: USER LEVEL LOCK OBJECT_SCHEMA: NULL OBJECT_NAME: ztesch OBJECT_INSTANCE_BEGIN: 139780113368448 LOCK_TYPE: EXCLUSIVE LOCK_DURATION: EXPLICIT LOCK_STATUS: PENDING SOURCE: item_func.cc:5532 OWNER_THREAD_ID: 34 OWNER_EVENT_ID: 3 |
The problem is – we can’t really match the rows in the metadata_locks table with one of the php scripts which is executed in parallel. OWNER_THREAD_ID, for now, is not useful enough.
Checkout the CONNECTION_ID() . It is one of the MySQL information functions. As the name suggests it returns connection id. The same one which is displayed as:
- ID column of information_schema.processlist table
- Id column of SHOW PROCCESSLIST output
- PROCESSLIST_ID column of information_schema.threads table
But connection id is not present in the output of the metadata_locks table.
First update the test script to output CONNECTION_ID(). Add those line before GET_LOCK() query.
|
1 2 3 |
$stmt = $pdo->query("SELECT CONNECTION_ID() as connid"); $row = $stmt->fetch(); echo "connection_id=($row[connid])\n"; |
New complete test script:
|
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 |
<?php $host = "localhost"; $db = "DB_NAME"; $user = "DB_USER"; $password = "DB_PASSWORD"; $pdo = new PDO( "mysql:host=$host;dbname=$db;charset=$charset", $user, $password, array( PDO::ATTR_ERRMODE => PDO::ERRMODE_EXCEPTION, PDO::ATTR_DEFAULT_FETCH_MODE => PDO::FETCH_ASSOC, PDO::ATTR_EMULATE_PREPARES => false )); $stmt = $pdo->query("SELECT CONNECTION_ID() as connid"); $row = $stmt->fetch(); echo "connection_id=($row[connid])\n"; $stmt = $pdo->query("SELECT GET_LOCK('ztesch', 10) as lck"); $row = $stmt->fetch(); echo "lock granted=($row[lck])\n"; echo "sleep for 30s\n"; sleep(30); echo "done\n"; ?> |
Again, execute the new script from cmd line, in parallel, 2-3s apart.
First script output:
|
1 2 3 4 5 |
[damir@buffy lockdebug]$ php -q lockdebugexample_2.php connection_id=(12) lock granted=(1) sleep for 30s done |
Second script output:
|
1 2 3 4 5 |
[damir@buffy lockdebug]$ php -q lockdebugexample_2.php connection_id=(13) lock granted=(0) sleep for 30s done |
But before scripts terminate execute this sql query in your favorite mysql client:
|
1 2 3 4 5 6 7 8 |
SELECT performance_schema.threads.PROCESSLIST_ID, performance_schema.metadata_locks.* FROM performance_schema.threads, performance_schema.metadata_locks WHERE performance_schema.threads.THREAD_ID = performance_schema.metadata_locks.OWNER_THREAD_ID; |
Result:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 |
*************************** 1. row *************************** PROCESSLIST_ID: 12 OBJECT_TYPE: USER LEVEL LOCK OBJECT_SCHEMA: NULL OBJECT_NAME: ztesch OBJECT_INSTANCE_BEGIN: 139779912042736 LOCK_TYPE: EXCLUSIVE LOCK_DURATION: EXPLICIT LOCK_STATUS: GRANTED SOURCE: item_func.cc:5532 OWNER_THREAD_ID: 50 OWNER_EVENT_ID: 5 *************************** 2. row *************************** PROCESSLIST_ID: 13 OBJECT_TYPE: USER LEVEL LOCK OBJECT_SCHEMA: NULL OBJECT_NAME: ztesch OBJECT_INSTANCE_BEGIN: 139779979151600 LOCK_TYPE: EXCLUSIVE LOCK_DURATION: EXPLICIT LOCK_STATUS: PENDING SOURCE: item_func.cc:5532 OWNER_THREAD_ID: 51 OWNER_EVENT_ID: 5 |
Now we can match the
CONNECTION_ID() from the script output with PROCESSLIST_ID and data from
metadata_locks table.