Replication slave from PXC crashes when deadlock found and corrupts databate / can't resume

[Thomas Roog]

When there is a long reporting query running (old query which takes 15 minutes) causes system lock on the replication SQL thread. Later when it tries to resume it fails with error Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY;

# VERSION installed on the reporting slave
------------------------------------------------------------------------------
  libperconaserverclient18.1 5.6.22-71.0-726.trusty amd64
  percona-server-client-5.6 5.6.22-71.0-726.trusty amd64
  percona-server-common-5.6 5.6.22-71.0-726.trusty amd64
  percona-server-server-5.6 5.6.22-71.0-726.trusty amd64
  percona-toolkit 2.2.12 all
  percona-xtrabackup 2.2.8-5059-1.trusty amd64

# VERSION installed on the galera cluster node acting as a master
------------------------------------------------------------------------------
  percona-nagios-plugins 1.1.4-1 all
  percona-toolkit 2.2.12 all
  percona-xtrabackup 2.2.8-5059-1.trusty amd64
  percona-xtradb-cluster-client-5.6 5.6.21-25.8-938.trusty amd64
  percona-xtradb-cluster-common-5.6 5.6.21-25.8-938.trusty amd64
  percona-xtradb-cluster-galera-3.x 3.8.3390.trusty amd64
  percona-xtradb-cluster-server-5.6 5.6.21-25.8-938.trusty amd64

# ERRORS found in the error log - this is repeatable situation
2015-02-12 04:15:09 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 127371591, Error_code: 1213
2015-02-12 04:20:06 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 128267271, Error_code: 1213
2015-02-12 04:50:09 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 129888400, Error_code: 1213
2015-02-12 05:00:10 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 130810429, Error_code: 1213
2015-02-12 05:26:33 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 133112638, Error_code: 1213
2015-02-12 08:20:13 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 146892566, Error_code: 1213
2015-02-12 08:31:38 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 146892566, Error_code: 1213
2015-02-12 10:17:29 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 154447973, Error_code: 1213
2015-02-12 10:28:24 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 154706056, Error_code: 1213
2015-02-12 10:33:53 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 155019619, Error_code: 1213
2015-02-12 10:34:02 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 155019619, Error_code: 1213
2015-02-12 10:39:20 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 155349705, Error_code: 1213
2015-02-12 11:22:33 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 158088534, Error_code: 1213
2015-02-12 11:26:52 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 158536669, Error_code: 1213
2015-02-12 11:26:54 31165 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 158536669, Error_code: 1213
2015-02-12 12:28:38 31165 [Warning] Aborted connection 490826 to db: 'mygame_report' user: 'root' host: '127.0.0.1' (Got an error reading communication packets)
2015-02-12 13:27:32 31165 [Warning] Slave SQL: Could not execute Write_rows event on table mygame.accountactivity; Lock wait timeout exceeded; try restarting transaction, Error_code: 1205; handler error HA_ERR_LOCK_WAIT_TIMEOUT; the event's master log binlog.000012, end_log_pos 166133301, Error_code: 1205
2015-02-12 13:27:32 31165 [ERROR] Slave SQL: Could not execute Write_rows event on table mygame.state; Duplicate entry '8570235' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log binlog.000012, end_log_pos 166132885, Error_code: 1062
2015-02-12 13:27:32 31165 [Warning] Slave: Duplicate entry '8570235' for key 'PRIMARY' Error_code: 1062
2015-02-12 13:27:32 31165 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped
at log 'binlog.000012' position 166132545

# CONFIG FILE on the galera node acting as master
-----------------------------------------------------------------------------
[MYSQLD]
user=mysql
basedir=/usr/
datadir=/data01/mysql
socket=/var/run/mysqld/mysqld.sock
pid_file=mysqld.pid
port=3306
log_error=/var/log/mysql.log
log_warnings=2
# Use only ipv4 for connections
bind_address=0.0.0.0
#log_output=FILE
### INNODB OPTIONS
innodb_buffer_pool_size=12G
innodb_flush_log_at_trx_commit=2
innodb_file_per_table=1
innodb_data_file_path = ibdata1:100M:autoextend
## You may want to tune the below depending on number of cores and disk sub
#innodb_read_io_threads=4
#innodb_write_io_threads=4
innodb_io_capacity=200
innodb_doublewrite=1
innodb_log_file_size=2G
innodb_log_buffer_size=32M
innodb_buffer_pool_instances=4
innodb_log_files_in_group=2
innodb_thread_concurrency=0
innodb_open_files=2000
#innodb_file_format=barracuda
innodb_flush_method=O_DIRECT
innodb_autoinc_lock_mode=2
## avoid statistics update when doing e.g show tables
innodb_stats_on_metadata=0
default_storage_engine=innodb

## HEAVY WRITING ENVIROMENT ##
innodb_max_dirty_pages_pct = 90

## SPEEDUP ##
## /dev/shm uses virtual memory instead of a persistent storage device
tmpdir=/tmp
back_log=2048

## MYGAME SPECIFIC SETTINGS ##
lower_case_table_names = 1
#autocommit=0
init_connect='SET autocommit=0'

## DEFAULT CHARACTER SET ##
skip-character-set-client-handshake
collation_server=utf8_general_ci
character_set_server=utf8

# REPLICATION SPECIFIC _ GENERAL
#server_id must be unique across all mysql servers participating in replication.
server_id=8
# REPLICATION SPECIFIC
binlog_format=ROW
log_bin=binlog
#relay_log=relay-bin
slave_net_timeout=60
#skip-slave-start=1
#read_only=1
expire_logs_days=7
sync_binlog=0
log_slave_updates=1
#gtid_mode=ON
# allow create users fuctions
log_bin_trust_function_creators=1
#enforce_gtid_consistency=1
# OTHER THINGS, BUFFERS ETC
key_buffer_size = 32M
tmp_table_size = 64M
max_heap_table_size = 64M
## SAFETY ##
max_allowed_packet = 16M
max_connect_errors = 1000000
#sort_buffer_size = 256K
#read_buffer_size = 256K
#read_rnd_buffer_size = 512K
#myisam_sort_buffer_size = 8M
skip_name_resolve
memlock=0
sysdate_is_now=1
max_connections=200
## EXTRA SAFETY ##
symbolic-links=0
thread_cache_size=512
open_files_limit=65535
table_definition_cache=4096
query_cache_type = 0
query_cache_size = 0
table_open_cache=10000
# 5.6 backwards compatibility
explicit_defaults_for_timestamp=1

## SLOW LOG ##
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
log_slow_verbosity = FULL
long_query_time = 10
slow_query_log_use_global_control = long_query_time,log_slow_filter,log_slow_rate_limit,log_slow_verbosity
log_queries_not_using_indexes=1
event_scheduler=0

##
## WSREP options
##

# Full path to wsrep provider library or 'none'
wsrep_provider=/usr/lib/libgalera_smm.so

wsrep_node_address=10.1.160.8
# Provider specific configuration options
wsrep_provider_options="gcache.size=4096M; gmcast.segment=0"

# Logical cluster name. Should be the same for all nodes.
wsrep_cluster_name="my_wsrep_cluster"

# Group communication system handle
wsrep_cluster_address=gcomm://10.1.160.6:4567,10.1.160.8:4567,10.1.160.7:4567

# Human_readable node name (non-unique). Hostname by default.
wsrep_node_name=10.1.160.8

# Address for incoming client connections. Autodetect by default.
#wsrep_node_incoming_address=

# How many threads will process writesets from other nodes
#wsrep_slave_threads=4

# DBUG options for wsrep provider
#wsrep_dbug_option

# Generate fake primary keys for non-PK tables (required for multi-master
# and parallel applying operation)
wsrep_certify_nonPK=1

# Location of the directory with data files. Needed for non-mysqldump
# state snapshot transfers. Defaults to mysql_real_data_home.
#wsrep_data_home_dir=

# Maximum number of rows in write set
wsrep_max_ws_rows=131072

# Maximum size of write set
wsrep_max_ws_size=1073741824

# to enable debug level logging, set this to 1
wsrep_debug=0

# convert locking sessions into transactions
wsrep_convert_LOCK_to_trx=0

# how many times to retry deadlocked autocommits
wsrep_retry_autocommit=1

# change auto_increment_increment and auto_increment_offset automatically
wsrep_auto_increment_control=1

# replicate myisam
wsrep_replicate_myisam=1
# retry autoinc insert, which failed for duplicate key error
wsrep_drupal_282555_workaround=0

# enable "strictly synchronous" semantics for read operations
wsrep_causal_reads=0

# Command to call when node status or cluster membership changes.
# Will be passed all or some of the following options:
# --status - new status of this node
# --uuid - UUID of the cluster
# --primary - whether the component is primary or not ("yes"/"no")
# --members - comma-separated list of members
# --index - index of this node in the list
wsrep_notify_cmd=mywsrep_notify_cmd

##
## WSREP State Transfer options
##

# State Snapshot Transfer method
# ClusterControl currently DOES NOT support wsrep_sst_method=mysqldump
wsrep_sst_method=xtrabackup-v2

# Address on THIS node to receive SST at. DON'T SET IT TO DONOR ADDRESS!!!
# (SST method dependent. Defaults to the first IP of the first interface)
#wsrep_sst_receive_address=

# SST authentication string. This will be used to send SST to joining nodes.
# Depends on SST method. For mysqldump method it is root:<root password>
wsrep_sst_auth=root:password

# Desired SST donor name.
wsrep_sst_donor=10.1.160.7,10.1.160.6

# Protocol version to use
# wsrep_protocol_version=

[MYSQL]
socket=/var/run/mysqld/mysqld.sock
#default_character_set=utf8

[client]
socket=/var/run/mysqld/mysqld.sock
#default_character_set=utf8

[mysqldump]
max_allowed_packet = 16M
socket=/var/run/mysqld/mysqld.sock
#default_character_set=utf8

[MYSQLD_SAFE]
pid_file=mysqld.pid
log_error=/var/log/mysql.log
basedir=/usr/
datadir=/data01/mysql

# CONFIG FILE on the reporting slave
------------------------------------------------------------------------------
[MYSQLD]
user=mysql
basedir=/usr/
datadir=/data01/mysql
socket=/var/run/mysqld/mysqld.sock
pid_file=mysqld.pid
port=3306
log_error=/var/log/mysql.log
log_warnings=2
# Use only ipv4 for connections
bind_address=0.0.0.0
#log_output=FILE
### INNODB OPTIONS
innodb_buffer_pool_size=16G
innodb_flush_log_at_trx_commit=2
innodb_file_per_table=1
innodb_data_file_path = ibdata1:100M:autoextend
## You may want to tune the below depending on number of cores and disk sub
#innodb_read_io_threads=4
#innodb_write_io_threads=4
#innodb_io_capacity=200
#innodb_doublewrite=1
innodb_log_file_size=2G
innodb_log_buffer_size=32M
innodb_buffer_pool_instances=4
innodb_log_files_in_group=2
innodb_thread_concurrency=0
innodb_open_files=2000
#innodb_file_format=barracuda
innodb_flush_method=O_DIRECT
#innodb_autoinc_lock_mode=2
## avoid statistics update when doing e.g show tables
innodb_stats_on_metadata=0
default_storage_engine=innodb

## HEAVY WRITING ENVIROMENT ##
innodb_max_dirty_pages_pct = 90

## SPEEDUP ##
## /dev/shm uses virtual memory instead of a persistent storage device
tmpdir=/data02/tmp
back_log=2048

## MYGAME SPECIFIC SETTINGS ##
lower_case_table_names = 1
#autocommit=0
init_connect='SET autocommit=0'

## DEFAULT CHARACTER SET ##
skip-character-set-client-handshake
collation_server=utf8_general_ci
character_set_server=utf8

# REPLICATION SPECIFIC _ GENERAL
#server_id must be unique across all mysql servers participating in replication.
server_id=9
# REPLICATION SPECIFIC
#binlog_format=ROW
#log_bin=binlog
#relay_log=relay-bin
slave_net_timeout=60
#skip-slave-start=1
innodb_lock_wait_timeout=900
slave_transaction_retries=100000
master_info_repository=TABLE
relay_log_info_repository=TABLE
#read_only=1
#expire_logs_days=7
#sync_binlog=0
#log_slave_updates=1
#gtid_mode=ON
# allow create users fuctions
log_bin_trust_function_creators=1
#enforce_gtid_consistency=1
# OTHER THINGS, BUFFERS ETC
key_buffer_size = 32M
tmp_table_size = 64M
max_heap_table_size = 64M
## SAFETY ##
max_allowed_packet = 16M
max_connect_errors = 1000000
#sort_buffer_size = 256K
#read_buffer_size = 256K
#read_rnd_buffer_size = 512K
#myisam_sort_buffer_size = 8M
skip_name_resolve
#memlock=0
sysdate_is_now=1
max_connections=200
## EXTRA SAFETY ##
symbolic-links=0
thread_cache_size=512
open_files_limit=65535
table_definition_cache=4096
query_cache_type = 0
query_cache_size = 0
table_open_cache=10000
# 5.6 backwards compatibility
explicit_defaults_for_timestamp=1

## SLOW LOG ##
slow_query_log = 0
slow_query_log_file = /var/log/mysql/mysql-slow.log
log_slow_verbosity = FULL
long_query_time = 10
slow_query_log_use_global_control = long_query_time,log_slow_filter,log_slow_rate_limit,log_slow_verbosity
log_queries_not_using_indexes=0
event_scheduler=1

[MYSQL]
socket=/var/run/mysqld/mysqld.sock
#default_character_set=utf8

[client]
socket=/var/run/mysqld/mysqld.sock
#default_character_set=utf8

[mysqldump]
max_allowed_packet = 16M
socket=/var/run/mysqld/mysqld.sock
#default_character_set=utf8

[MYSQLD_SAFE]
pid_file=mysqld.pid
log_error=/var/log/mysql.log
basedir=/usr/
datadir=/data01/mysql

[Thomas Roog (thomas.roog)]

We tried to mitigate this behavior by adding
innodb_lock_wait_timeout=900
slave_transaction_retries=100000
and it was successful until today.

Otherwise any really large query causes system lock on the replication thread and then this can happen.

Found something similar at
https://www.kickstarter.com/backing-and-hacking/the-day-the-replication-died

and https://bugs.launchpad.net/percona-xtradb-cluster/+bug/1214465, but we have
wsrep_forced_binlog_format=NONE and pt-table-checksum runs twice a day to check galera cluster and replication slaves and it's OK.

This is repeatable error.

[Thomas Roog (thomas.roog)]

The same queries weren't causing dead lock on MySQL 5.5, we started seeing that after migration to MySQL/Percona 5.6. What has changed?

Even now the same happens, but will fit into time, so replication thread won't be stopped (and then data in table corrupted as partially existing..).

Tailing /var/log/mysql.log... 2015-02-12 16:05:27 10298 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 187548409, Error_code: 1213
2015-02-12 16:32:44 10298 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 189937636, Error_code: 1213
2015-02-12 16:50:01 10298 [Warning] Slave SQL: Could not execute Update_rows event on table mygame.playeraccount; Deadlock found when trying to get lock; try restarting transaction, Error_code: 1213; handler error HA_ERR_LOCK_DEADLOCK; the event's master log binlog.000012, end_log_pos 191750248, Error_code: 1213

[Thomas Roog (thomas.roog)]

Queries which are causing dead lock on replication are CREATE TEMPORARY TABLE SELECT * FROM.

[Valerii Kravchuk (valerii-kravchuk)]

Please, send the output of:

show engine innodb status\G

from the slave immediately after the deadlock. It would be useful to check the details.

[Rodrigo (rodri-bernardo)]

Hello there,

I got the same error message:
This is my innodb status:
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2017-03-09 14:41:30 7f026040d700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 0 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 97570 srv_active, 0 srv_shutdown, 18126 srv_idle
srv_master_thread log flush and writes: 115696
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 344389
OS WAIT ARRAY INFO: signal count 437392
Mutex spin waits 1075408, rounds 10292671, OS waits 197701
RW-shared spins 282032, rounds 5294988, OS waits 104907
RW-excl spins 116485, rounds 2223412, OS waits 25415
Spin rounds per wait: 9.57 mutex, 18.77 RW-shared, 19.09 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
2017-03-08 19:09:26 7f02606d8700
*** (1) TRANSACTION:
TRANSACTION 58539970169, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 9 lock struct(s), heap size 1184, 5 row lock(s), undo log entries 4
MySQL thread id 1, OS thread handle 0x7f02b6a2d700, query id 30422585 System lock
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2534440687 page no 90557 n bits 88 index `PRIMARY` of table `ft_prod`.`files` trx id 58539970169 lock_mode X locks rec but not gap waiting
*** (2) TRANSACTION:
TRANSACTION 58539970171, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
MySQL thread id 6628, OS thread handle 0x7f02606d8700, query id 30422588 System lock
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 2534440687 page no 90557 n bits 88 index `PRIMARY` of table `ft_prod`.`files` trx id 58539970171 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2534440685 page no 1072 n bits 128 index `PRIMARY` of table `ft_prod`.`transfers` trx id 58539970171 lock_mode X locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 58561579736
Purge done for trx's n:o < 58561578109 undo n:o < 0 state: running but idle
History list length 852
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 16722, OS thread handle 0x7f026040d700, query id 61116102 stockport.dhcp.dneg.com 10.21.32.238 root init
show engine innodb status
---TRANSACTION 0, not started
MySQL thread id 16508, OS thread handle 0x7f0260552700, query id 61116100 stockport.dhcp.dneg.com 10.21.32.238 root cleaning up
---TRANSACTION 58561578037, not started
MySQL thread id 1, OS thread handle 0x7f02b6a2d700, query id 61106780 committed 2630136305
---TRANSACTION 58561578111, ACTIVE 713 sec
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 14927, OS thread handle 0x7f02606d8700, query id 61107336 wsrep in pre-commit stage
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thre...

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1800

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3263