Free Blog Themes and Blog Templates

Mysql lock debugging... find the locker.

A common problem for transactional databases to identify what some transactions/thread waiting for. With MYISAM, where we could use table locks only, that is quite easy. For innodb, with row (or rather page) locks it is much harder. So let's see:

Our small example table comes from the Mysql Self Study Guide example database.

mysql> prompt #\u (\R:\m:\s \d)> 
PROMPT set to '\u (\R:\m:\s \d)> '
#atis (14:00:30 world)> show create table City;

 City  | CREATE TABLE `City` (
  `ID` int(11) NOT NULL AUTO_INCREMENT,
  `Name` char(35) NOT NULL DEFAULT '',
  `CountryCode` char(3) NOT NULL DEFAULT '',
  `District` char(20) NOT NULL DEFAULT '',
  `Population` int(11) NOT NULL DEFAULT '0',
  PRIMARY KEY (`ID`)
) ENGINE=MyISAM AUTO_INCREMENT=4080 DEFAULT CHARSET=latin1 |
#atis (14:00:44 world)> lock tables City read;
Query OK, 0 rows affected (0.00 sec)
#jozsi (14:01:03 world)> lock tables City write;
(thread is locked here)
#root (14:01:34 world)> show processlist;
+----+------+-----------+-------+---------+------+--------+------------------------+
| Id | User | Host      | db    | Command | Time | State  | Info                   |
+----+------+-----------+-------+---------+------+--------+------------------------+
| 16 | jozsi | localhost | world | Query   |  102 | Locked | lock tables City write |
| 17 | atis | localhost | world | Sleep   |   122 | NULL   | NULL       |
+----+------+-----------+-------+---------+------+--------+------------------------+
2 rows in set (0.00 sec)

A rarely known feature of mysql is mysqladmin debug. Nice stuff, gives you info mainly of MYISAM engine, an also about locking. (the debug info is dumped into the mysql error log )

lock: 0x7fda84007988: write_wait read
write_wait: 0x7fda840080b0 (16:12);
read      : 0x7fda8800ad70 (17:5);
...
Thread database.table_name          Locked/Waiting        Lock_type

16      world.City                  Waiting - write       High priority write lock
17      world.City                  Locked - read         Read lock without concurrent inserts
...

It seems to be obvious, that thread 17 is the bad guy, so it is the be killed to let the other threads proceed. Unfortunately, for MYISAM, there is no mechanism to detect long waiting threads, so nor the locker is killed, nor the locked one is aborted. For innodb, this problem is solved, so the locked threads are aborted after a innodb_lock_wait_timeout, but identifying the locker is much harder

#atis (15:13:20 world)>alter table City engine=innodb;#atis (15:13:29 world)>set autocommit=0;

#atis (15:14:22 world)>start transaction;


#atis (15:21:40 world)>select * from City where id=1 for update;
+----+-------+-------------+----------+------------+
| ID | Name  | CountryCode | District | Population |
+----+-------+-------------+----------+------------+
|  1 | Kabul | AFG         | Kabol    |    1780000 |
+----+-------+-------------+----------+------------+
1 row in set (0.00 sec)
#jozsi (14:28:03 world)> update City set Population=id where id=1;
(locked)
root@localhost (none)>show processlist;
+----+-------+-----------+-------+---------+------+----------+----------------------------------------------------+
| Id | User  | Host      | db    | Command | Time | State    | Info                                               |
+----+-------+-----------+-------+---------+------+----------+----------------------------------------------------+
|  2 | atis  | localhost | world | Sleep   |  239 |          | NULL                                               |
|  5 | jozsi | localhost | world | Query   |  237 | Updating | update City set Population=Population+1 where id=1 |
...

Let's see the info provided by the mysqladmin debug.

lock: 0x7fb52800ba40: write
write     : 0x7fb52c00b550 (5:6);

Thread database.table_name          Locked/Waiting        Lock_type

5       world.City                  Locked - write        High priority write lock

The locked thread (thread 5) is still visible here, but I can't find the locker (thread 2). A further investigation is required. Fortunately, INNODB provides an engine status info, with a transactional section.

mysql> show innodb status \G
....
---TRANSACTION 0 504327, ACTIVE 20 sec, process no 2405, OS thread id 140416321279760 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 5, query id 75 localhost jozsi Updating
update City set Population=Population+1 where id=1
------- TRX HAS BEEN WAITING 20 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 3335 n bits 248 index `PRIMARY` of table `world`.`City` trx id 0 504327 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;; 1: len 6; hex 00000007aef9; asc       ;; 2: len 7; hex 8000000c4b0110; asc     K  ;; 3: len 30; hex 4b6162756c20202020202020202020202020202020202020202020202020; asc Kabul                         ;...(truncated); 4: len 3; hex 414647; asc AFG;; 5: len 20; hex 4b61626f6c202020202020202020202020202020; asc Kabol               ;; 6: len 4; hex 801b2920; asc   ) ;;

------------------
---TRANSACTION 0 504326, ACTIVE 22 sec, process no 2405, OS thread id 140416321812240
2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 2, query id 74 localhost atis

So we have a page lock, for page 3335, but I have no info of who is holding a exclusive lock on the page. The status should be turned into a debug mode. INNODB provides a somewhat orthodox way for this. We should create a table with a specific name. See in the manual

root@localhost world>create table innodb_lock_monitor (a int) engine=innodb;

After this, the transaction section is gives much more detail.

---TRANSACTION 0 504327, ACTIVE 596 sec, process no 2405, OS thread id 140416321279760 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 5, query id 75 localhost jozsi Updating
update City set Population=Population+1 where id=1
------- TRX HAS BEEN WAITING 596 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 3335 n bits 248 index `PRIMARY` of table `world`.`City` trx id 0 504327 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;; 1: len 6; hex 00000007aef9; asc       ;; 2: len 7; hex 8000000c4b0110; asc     K  ;; 3: len 30; hex 4b6162756c20202020202020202020202020202020202020202020202020; asc Kabul                         ;...(truncated); 4: len 3; hex 414647; asc AFG;; 5: len 20; hex 4b61626f6c202020202020202020202020202020; asc Kabol               ;; 6: len 4; hex 801b2920; asc   ) ;;

------------------
TABLE LOCK table `world`.`City` trx id 0 504327 lock mode IX
RECORD LOCKS space id 0 page no 3335 n bits 248 index `PRIMARY` of table `world`.`City` trx id 0 504327 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;; 1: len 6; hex 00000007aef9; asc       ;; 2: len 7; hex 8000000c4b0110; asc     K  ;; 3: len 30; hex 4b6162756c20202020202020202020202020202020202020202020202020; asc Kabul                         ;...(truncated); 4: len 3; hex 414647; asc AFG;; 5: len 20; hex 4b61626f6c202020202020202020202020202020; asc Kabol               ;; 6: len 4; hex 801b2920; asc   ) ;;

---TRANSACTION 0 504326, ACTIVE 598 sec, process no 2405, OS thread id 140416321812240
2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 2, query id 74 localhost atis
TABLE LOCK table `world`.`City` trx id 0 504326 lock mode IX
RECORD LOCKS space id 0 page no 3335 n bits 248 index `PRIMARY` of table `world`.`City` trx id 0 504326 lock_mode X locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;; 1: len 6; hex 00000007aef9; asc       ;; 2: len 7; hex 8000000c4b0110; asc     K  ;; 3: len 30; hex 4b6162756c20202020202020202020202020202020202020202020202020; asc Kabul                         ;...(truncated); 4: len 3; hex 414647; asc AFG;; 5: len 20; hex 4b61626f6c202020202020202020202020202020; asc Kabol               ;; 6: len 4; hex 801b2920; asc   ) ;;

Well, that seems pretty hard to find the appropriate thread/page number pair. We are missing a tool here. And here comes innotop

________________________________ InnoDB Locks _________________________________
CXN        ID  Type    Waiting  Wait   Active  Mode  DB     Table  Index    Ins
localhost   5  RECORD        1  06:23   19:26  X     world  City   PRIMARY     
localhost   5  TABLE         0  06:23   19:26  IX    world  City               
localhost   5  RECORD        1  06:23   19:26  X     world  City   PRIMARY     
localhost   2  TABLE         0  00:00   19:28  IX    world  City               
localhost   2  RECORD        0  00:00   19:28  X     world  City   PRIMARY    

Well, the output is nice, but still we are missing the page numbers... A patch might be required here. :)

Feedback awaiting moderation

This post has 236 feedbacks awaiting moderation...

Leave a comment


Your email address will not be revealed on this site.

Your URL will be displayed.
(Line breaks become <br />)
(Name, email & website)
(Allow users to contact you through a message form (your email will not be revealed.)
Miami Real Estate Blog Theme
Free Blog Themes and Templates