A simple MySQL monitor for detecting InnoDB X-Locks

To monitor blocking transactions and lock waits on MySQL I use the following simple script:

root@my-db-master:~[1400]#cat monitor-x-locks.sh
#!/bin/sh
######################
# MySQL Monitoring script
# Use me when you need to log MySQL txns and detect x-locs
#####################
DBPASS=mypass

while true
do
 date +'%Y-%m-%d %H:%M:%S,%3N' >> locks.txt
 date +'%Y-%m-%d %H:%M:%S,%3N' >> lock_waits.txt
 date +'%Y-%m-%d %H:%M:%S,%3N' >> tables.txt
 echo "select * from information_schema.INNODB_LOCK_WAITS " | mysql -u root -p$DBPASS >> lock_waits.txt
 echo "select lock_id,Lock_trx_id,lock_mode,lock_table
        from information_schema.INNODB_LOCKS where lock_mode='X'" | mysql -u root -p$DBPASS >>  tables.txt
 echo "select r.trx_id waiting_trx_id,
       r.trx_mysql_thread_id waiting_thread,
       r.trx_query waiting_query,
       b.trx_id blocking_trx_id,
       b.trx_mysql_thread_id blocking_thread,
       b.trx_query blocking_query
   from information_schema.innodb_lock_waits w
   inner join information_schema.innodb_trx b  on
    b.trx_id = w.blocking_trx_id
   inner join information_schema.innodb_trx r  on
    r.trx_id = w.requesting_trx_id;"  | mysql -u root -p$DBPASS >>  locks.txt
 sleep 1 ;
done

This script creates three files and updates them with a timestamp every second.  Those files are:

locks.txt : shows which locs occurred by showing the transaction ID, thread ID from the blocked transaction and  transaction ID, thread ID from the blocking transaction

tables.txt Shows which transactions have placed an exclusive lock

lock_waits.txt: Shows transactions waiting for a lock over a table

 Use it as follows:

root@my-db-master:~[1402]#./monitor-x-locks.sh &
[1] 23184
root@my-db-master:~[1403]#fg
./monitor-x-locks.sh
^C
root@my-db-master:~[1396]#ls -l
total 60
-rw-r--r--  1 root root   216 Nov  5 20:39 locks.txt
-rw-r--r--  1 root root   216 Nov  5 20:39 lock_waits.txt
-rwxr--r--  1 root root  1230 Nov  5 20:38 monitor-x-locks.sh
-rw-r--r--  1 root root   216 Nov  5 20:39 tables.txt

Digging into MySQL InnoDB Transactions

A week ago I faced a really difficult situation: one of our MySQL innodb databases was slowing down in response times really a lot. With a bit of debugging, I figure out that there were some X-locks (eXclusive locks) that did not allowed some of the later transactions to finish. Here is the procedure I followed:

1. Use MySQL processlist to find out slow operations. The first one show us the slow queries on a specific database:

select * from information_schema.processlist 
              where db='alfresco' and command='Query' order by 'time' desc; 

Since I understood that the specific slow queries are utilizing two tables I also used:

select * from information_schema.processlist 
      where db='alfresco' and info like '%alf_%_assoc%' 

2. Now since we have one idea about heavy MySQL threads, lets take a look to the transactions:
First of all see all transactions that have placed an exclusive lock on one of the tables:
Second find the lock wait transactions

select * from information_schema.INNODB_TRX 
         where trx_id in ( 
             select Lock_trx_id from information_schema.INNODB_LOCKS where lock_mode='X'  )

select * from information_schema.INNODB_TRX where trx_id in (
         select distinct blocking_trx_id 
            from information_schema.INNODB_LOCK_WAITS ) 

3. Finally find the threads along with conflicting transactions with the following query:

SELECT r.trx_id waiting_trx_id,  
       r.trx_mysql_thread_id waiting_thread,
       r.trx_query waiting_query,
       b.trx_id blocking_trx_id, 
       b.trx_mysql_thread_id blocking_thread,
       b.trx_query blocking_query
   FROM       information_schema.innodb_lock_waits w
   INNER JOIN information_schema.innodb_trx b  ON  
    b.trx_id = w.blocking_trx_id
  INNER JOIN information_schema.innodb_trx r  ON  
    r.trx_id = w.requesting_trx_id;

Beware: The thread ID (waiting and blocking) is the ID in the information_schema.processlist

In this case, clearly the transaction with id 194D110F is the blocker!
To inspect the transaction use this query:

select * from information_schema.INNODB_TRX where trx_id='194D110F'

From what we see, there is a transaction running since 19:10:57 with id 194D110F. The query or operation carried out of this transaction is null because it was deleted from the transaction cache since it is very old. To retrieve the information about the SQL statement carried from this transaction we have to use the MySQL binlog.

The transaction 194D110F was observed during a  load test performed on our system. The lock was not released for 2 h.
The locking thread in MySQL was seen as follows from the slow.log:

---TRANSACTION 194D110F, ACTIVE 7431 sec
74 lock struct(s), heap size 14776, 101 row lock(s), undo log entries 64
MySQL thread id 7526, OS thread handle 0x7fd28ec38700, query id 10005877 application-host X.X.44.28 alfresco
Trx read view will not see trx with id >= 194D1110, sees < 194C03CD