Étranges problèmes de verrouillage tout en jouant des journaux via la lecture percona

Question

Problème lors de la relecture des journaux

Je suis en train de comparer un nouveau nœud DB (spécifications à la fin) et j'ai rencontré un comportement étrange:

Comme décrit ici je:

• Créé un dépotoir (innobackupex ftw)
• J'ai enregistré toutes mes requêtes pendant une heure
• Configurez ma nouvelle base innodb_buffer_pool_size)
• A commencé la rediffusion de mon journal de requête lente

Selon la documentation:

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

Cela fonctionne bien pendant environ 15 minutes, puis je commence à avoir d'étranges problèmes de verrouillage:

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

J'ai commencé à déboguer ma charge actuelle sur la base de données et j'ai constaté qu'une seule requête était en cours d'exécution:

(pris à partir de statut inNODB)

---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

Et une seule table ouverte:

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)

Cette situation reste comme ça pendant environ 3-4 minutes, puis la lecture se poursuit soudainement.

Ces problèmes ne se produisent pas sur la DB en direct: nous avons des problèmes avec le verrouillage, mais nous n'avons jamais dépassé le innodb_lock_wait_timeout évaluer.

Il me manque très probablement quelque chose d'évident, mais pour la vie de moi, je ne peux pas le comprendre, mais pourquoi la rediffusion se bloquerait-elle comme ça ou mieux pourtant pourquoi mysql resterait-il dans cet état de verrouillage?

Les entrées pertinentes dans le journal lent proviennent de notre serveur JEE:

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;

La gestion des transactions d'Hibernate a-t-elle quelque chose à voir avec la façon dont le verrou est généré et non fermé?

Spécifications du serveur

• Ubuntu 12.04.2 LTS
• Percona-Server-Server-5.5 version 5.5.32-REL31.0-549.

Configuration relative:

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

Config 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

Merci pour toute aide ou expérience dans ce domaine!

Éditer

J'ai joué avec certaines des variables inNODB et avec l'aide de innodb_show_verbose_locks ont pu déterminer un peu plus. Dans cet exemple:

---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;;

À la fois la transaction 1C52D8AA9 et 1C52D8AB4 Avoir un verrouillage IX sur l'adresse 73757072656d756d ce qui est bien alors que je rassemble ce post Puisque InNODB utilise le verrouillage MGL. Cependant le suivi Verrouillage x (Vu ici: "ID 1C52D8AB4 LOCK_MODE X INSERT INTERNET WATY") est manquant.