Strange Locking issues while playing back logs via percona playback

Question

Problem while replaying logs

I am in the process of benchmarking a new DB node (specs at the end) and have run across some strange behavior:

As described here i:

• Created a dump (innobackupex ftw)
• I logged all my queries for an hour
• Setup my new db (same my.cnf as the live db only with a higher innodb_buffer_pool_size)
• Started the replay of my slow query log

As per the documentation:

percona-playback --mysql-host=127.0.0.1\
--mysql-user=root --mysql-schema=my_db\
--query-log-file=slow.log

This works fine for about 15 minutes, then I start getting strange locking problems:

Error during query: Lock wait timeout exceeded; try restarting transaction, number of tries 0

I started debugging my current load on the db and found that only one single query was running:

(taken from innodb status)

---TRANSACTION 1C5264768, ACTIVE 44 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 4289, OS thread handle 0x7f7fb0779700, query id 77515 localhost     127.0.0.1 root update
insert into sessions (a, b, c, d, e, e, f, g, h, i, j, k, l, m, n, o, p, q) values (0, 682,
------- TRX HAS BEEN WAITING 44 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 4549 page no 7875876 n bits 104 index `PRIMARY` of table `production`.`sessions` trx id 1C5264768 lock_mode X insert intention waiting
------------------
TABLE LOCK table `production`.`sessions` trx id 1C5264768 lock mode IX
RECORD LOCKS space id 4549 page no 7875876 n bits 104 index `PRIMARY` of table `production`.`sessions` trx id 1C5264768 lock_mode X insert intention waiting
---TRANSACTION 1C526475D, ACTIVE (PREPARED) 452 sec
2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 1722, OS thread handle 0x7f7fb083d700, query id 77311 localhost 127.0.0.1 root
Trx read view will not see trx with id >= 1C526475E, sees < 1C525BA04
TABLE LOCK table `production`.`sessions` trx id 1C526475D lock mode IX
RECORD LOCKS space id 4549 page no 7875876 n bits 104 index `PRIMARY` of table `production`.`sessions` trx id 1C526475D lock_mode X
----------------------------
END OF INNODB MONITOR OUTPUT

And only one table open:

mysql> SHOW OPEN TABLES from production where In_use != 0;
+----------------------+--------------+--------+-------------+
| Database             | Table        | In_use | Name_locked |
+----------------------+--------------+--------+-------------+
| production           | sessions     |      1 |           0 |
+----------------------+--------------+--------+-------------+
1 row in set (0.00 sec)

This situation stays like this for about 3-4 minutes and then suddenly playback continues.

These issues do not happen on the live db: we have some issues with locking but we have never exceeded the innodb_lock_wait_timeout value.

I am most likely missing something obvious but for the life of me i can't figure it out, but why would the replay hang like that or better yet why would mysql remain in this lock state?

The relevant entries in the slow log are from our jee server:

XA START 0xbe681101606ce8d1676630322c7365727665722c5035313337,0x676630322c7365727665722c50353133372c00,0x4a5453;
insert into sessions (a, b, c, d, e, e, f, g, h, i, j, k, l, m, n, o, p, q) values (0, 682, ...);
XA END 0xbe681101606ce8d1676630322c7365727665722c5035313337,0x676630322c7365727665722c50353133372c00,0x4a5453;

Does hibernate's transaction handling have anything to do with the way the lock is generated and not closed?

Server Specs

• Ubuntu 12.04.2 LTS
• percona-server-server-5.5 version 5.5.32-rel31.0-549.precise

Relavent config:

max_connections         = 1500
sort_buffer_size        = 1M
thread_cache_size       = 1000
max_heap_table_size     = 512M
tmp_table_size          = 512M
join_buffer_size        = 67108864
expand_fast_index_creation = ON
open_files_limit        = 65535
table_definition_cache  = 4096
table_open_cache        = 262144
max_allowed_packet      = 16M
thread_stack            = 192K
query_cache_limit       = 1M
query_cache_size        = 512M
thread_concurrency      = 8
query_cache_type        = 1
long_query_time         = 2
log_slave_updates       = 1
expire_logs_days        = 10
max_binlog_size         = 100M

Innodb config:

default_storage_engine   = InnoDB
innodb_file_per_table    = 1
innodb_old_blocks_time   = 1000
innodb_buffer_pool_size  = 163456M
innodb_log_file_size     = 256M
innodb_flush_method      = O_DIRECT
innodb_read_io_threads   = 4
innodb_write_io_threads  = 4
innodb_doublewrite       = FALSE
innodb_flush_log_at_trx_commit = 2

Thanks for any help or experience in this area!

Edit

I have been playing with some of the innodb variables and with the help of innodb_show_verbose_locks have been able to determine a bit more. In this example:

---TRANSACTION 1C52D8AB4, ACTIVE 49 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 18602, OS thread handle 0x7f007a4a0700, query id 624263 localhost 127.0.0.1 root update
INSERT INTO `images` (A,B,C...) VALUES (....)
------- TRX HAS BEEN WAITING 49 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 51 page no 16791 n bits 152 index `PRIMARY` of table `production`.`images` trx id 1C52D8AB4 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

------------------
TABLE LOCK table `production`.`images` trx id 1C52D8AB4 lock mode IX
RECORD LOCKS space id 51 page no 16791 n bits 152 index `PRIMARY` of table `production`.`images` trx id 1C52D8AB4 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

---TRANSACTION 1C52D8AA9, ACTIVE 151 sec
2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 18460, OS thread handle 0x7f007454e700, query id 624243 localhost 127.0.0.1 root
TABLE LOCK table `production`.`images` trx id 1C52D8AA9 lock mode IX
RECORD LOCKS space id 51 page no 16791 n bits 152 index `PRIMARY` of table `production`.`images` trx id 1C52D8AA9 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

Both transaction 1C52D8AA9 and 1C52D8AB4 have an IX lock on address 73757072656d756d which is fine as i gather from this post since innodb uses MGL locking. However the Followup X Locking (seen here: "id 1C52D8AB4 lock_mode X insert intention waiting") is missing.