Percona Server moved to https://jira.percona.com/projects/PS

Slave Slave_SQL_Running_State is System lock

Asked by tuna

The slave show slave status\G,the Slave_SQL_Running_State with System lock state long time,so the slave delay master long.
The MySQL version :
Server version: 5.6.24-72.2-log Percona Server (GPL), Release 72.2, Revision 8d0f85b
The OS version:
2.6.32-573.el6.x86_64 #1 SMP Thu Jul 23 15:44:03 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
CentOS release 6.7 (Final)

The detail info:
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.86.20.118
                  Master_User: repadm
                  Master_Port: 3307
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000112
          Read_Master_Log_Pos: 367255960
               Relay_Log_File: mysqld-relay-bin.000009
                Relay_Log_Pos: 283
        Relay_Master_Log_File: mysql-bin.000111
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 325852257
              Relay_Log_Space: 1115280470
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: 106961
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 201183307
                  Master_UUID: 752af71c-343d-11e6-a781-44a8424976d1
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: System lock
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)

The Master mysql-bin.000111,pos:325852257
mysqlbinlog -vv --base64-output=decode-rows mysql-bin.000111

# at 325852226
#160630 4:28:40 server id 201183307 end_log_pos 325852257 CRC32 0xe7b92a4f Xid = 33476891
COMMIT/*!*/;
# at 325852257
#160630 4:28:40 server id 201183307 end_log_pos 325852334 CRC32 0xa3383798 Query thread_id=842 exec_time=0 error_code=0
SET TIMESTAMP=1467232120/*!*/;
BEGIN
/*!*/;
# at 325852334
#160630 4:28:40 server id 201183307 end_log_pos 325852466 CRC32 0x9d64bbee Table_map: `etcpbiset`.`APP_SET_PARKING_RECORD` mapped to number 646
# at 325852466

The event is null,But the IO is very busy.The read busy.
avg-cpu: %user %nice %system %iowait %steal %idle
           1.88 0.00 0.26 3.24 0.00 94.62

Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 2.67 292.33 3.67 16554.67 50.67 56.10 1.49 5.04 5.05 4.09 2.88 85.37
dm-0 0.00 0.00 0.00 1.67 0.00 13.33 8.00 0.00 1.20 0.00 1.20 0.60 0.10
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-2 0.00 0.00 292.00 4.67 16490.67 37.33 55.71 1.53 5.17 5.06 12.36 2.88 85.40

Stop the mysqld.The IO idle.

00:00:01 DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util
10:04:01 dev8-0 331.62 12607.17 15014.42 83.29 4.55 13.71 2.63 87.06
10:05:01 dev8-0 379.13 11377.95 19910.55 82.53 5.47 14.44 2.70 102.18
10:06:01 dev8-0 292.68 15311.67 4620.32 68.10 11.47 39.20 3.19 93.42
10:07:01 dev8-0 293.58 17473.18 50.17 59.69 1.34 4.56 3.10 91.02
10:08:01 dev8-0 288.85 16830.81 26.25 58.36 1.33 4.59 3.11 89.78
10:09:01 dev8-0 285.79 16806.56 21.56 58.88 1.31 4.58 3.14 89.76
10:10:01 dev8-0 279.98 16444.07 17.44 58.80 1.28 4.58 3.16 88.41
10:11:01 dev8-0 266.40 15688.49 29.99 59.00 1.28 4.81 3.32 88.48
10:12:01 dev8-0 271.95 15748.92 22.24 57.99 1.25 4.60 3.22 87.61
10:13:01 dev8-0 267.19 15615.44 21.80 58.52 1.28 4.79 3.30 88.21
10:14:01 dev8-0 267.53 15639.13 31.65 58.58 1.31 4.90 3.27 87.37
10:15:02 dev8-0 263.01 15900.17 20.18 60.53 1.29 4.92 3.33 87.67
10:16:01 dev8-0 272.59 15508.28 29.30 57.00 1.61 5.90 3.23 87.95
10:17:01 dev8-0 258.53 15278.58 22.09 59.18 1.25 4.83 3.39 87.71

Question information

Language:
English Edit question
Status:
Expired
For:
Percona Server moved to https://jira.percona.com/projects/PS Edit question
Assignee:
No assignee Edit question
Last query:
Last reply:
Revision history for this message
tuna (ant750505) said : 		#1

with exec
Relay_Master_Log_File: mysql-bin.000111
Exec_Master_Log_Pos: 325852257

wait For long time,much more than 10 minutes.

And I found ,I stop the slave wiht longer than 10 minutes ,can not stop slave.
And mysqladmin shutdown the mysqld long time can not stop.

The error log with error info.

Question:
What the IO doing?

Revision history for this message
tuna (ant750505) said : 		#2

With 5 minutes(300 second) sleep
show global status;select sleep(300);show global status;
The diff as:

Bytes_received 45
Bytes_sent 11539
Handler_read_key 12
Handler_read_next 1333695
Handler_read_rnd_next 404
Handler_write 403
Innodb_background_log_sync 300
Innodb_buffer_pool_pages_data -2229
Innodb_buffer_pool_bytes_data -36519936
Innodb_buffer_pool_pages_free 165
Innodb_buffer_pool_pages_made_not_young 1491781
Innodb_buffer_pool_pages_made_young 99714
Innodb_buffer_pool_pages_misc 2064
Innodb_buffer_pool_pages_old -785
Innodb_buffer_pool_read_requests 5049313
Innodb_buffer_pool_reads 105965
Innodb_data_read 1736130560
Innodb_data_reads 105977
Innodb_master_thread_idle_loops 300
Innodb_mem_adaptive_hash 23379968
Innodb_mutex_os_waits 18
Innodb_mutex_spin_rounds 569
Innodb_mutex_spin_waits 45
Innodb_pages_read 105965
Innodb_current_row_locks 105776
Innodb_rows_read 1333695
Innodb_num_open_files 12
Innodb_s_lock_os_waits 4039
Innodb_s_lock_spin_rounds 156634
Innodb_s_lock_spin_waits 5905
Innodb_x_lock_os_waits 11654
Innodb_x_lock_spin_rounds 379236
Innodb_x_lock_spin_waits 12351

Revision history for this message
tuna (ant750505) said : 		#3

Stop slave cost 42 minutes.

[root@10_86_10_245_10.86.10.245 ~]# mysql -S /home/my3307/mysql.sock -e "select now();stop slave;select now();" >/tmp/22.log
[root@10_86_10_245_10.86.10.245 ~]# more /tmp/22.log
now()
2016-07-01 10:30:37
now()
2016-07-01 11:12:37

Revision history for this message
tuna (ant750505) said : 		#4

[root@10_86_10_245_10.86.10.245 my3307]# strace -cfp 25461
Process 25461 attached with 28 threads
^CProcess 25461 detached
Process 25462 detached
Process 25468 detached
Process 25469 detached
Process 25470 detached
Process 25471 detached
Process 25472 detached
Process 25473 detached
Process 25474 detached
Process 25475 detached
Process 25476 detached
Process 25477 detached
Process 25505 detached
Process 25506 detached
Process 25507 detached
Process 25508 detached
Process 25509 detached
Process 25510 detached
Process 25511 detached
Process 25512 detached
Process 25513 detached
Process 25514 detached
Process 25518 detached
Process 25657 detached
Process 26313 detached
Process 30587 detached
Process 38504 detached
Process 38505 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
 55.73 33.859867 13934 2430 io_getevents
 26.91 16.350080 372 43980 8942 futex
 15.41 9.365577 25659 365 select
  1.17 0.711514 13 54350 pread
  0.78 0.473926 94785 5 5 restart_syscall
  0.00 0.000444 0 10930 sched_yield
  0.00 0.000000 0 21 write
  0.00 0.000000 0 14 lseek
  0.00 0.000000 0 7 ftruncate
------ ----------- ----------- --------- --------- ----------------
100.00 60.761408 112102 8947 total

Revision history for this message
tuna (ant750505) said : 		#5

The my.cnf
[client]
default-character-set = utf8
[mysqld]
character-set-server = utf8
collation-server = utf8_bin
basedir = /usr
datadir = /home/my3307
port = 3307
socket = /home/my3307/mysql.sock
open_files_limit = 8192
log_error=alert.log
pid_file=mysqld.pid
transaction-isolation=READ-COMMITTED
interactive_timeout = 7200
wait_timeout = 7200
innodb-status-file
skip-name-resolve
max_allowed_packet = 64M
explicit_defaults_for_timestamp=true
thread_cache_size = 256
expire_logs_days = 14
innodb_buffer_pool_size = 10239036K
sort_buffer_size = 64M
join_buffer_size = 8M
innodb_file_io_threads = 4
innodb_thread_concurrency = 16
innodb_log_buffer_size = 16M
innodb_log_file_size = 300M
innodb_log_files_in_group = 3
innodb_max_dirty_pages_pct = 90
innodb_lock_wait_timeout = 120
innodb_file_per_table
innodb_rollback_on_timeout
innodb_flush_log_at_trx_commit = 1
sync_binlog = 1
innodb_data_file_path = ibdata1:500M;ibdata2:10M:autoextend
binlog_format = MIXED
tmp_table_size = 128M
back_log = 200
max_connections = 1000
log_bin = mysql-bin
log_slave_updates=1
binlog_cache_size = 1M
slow_query_log=1
slow_query_log_file= slow.log
long_query_time = 1
log-output=FILE
general-log=0
general_log_file=general.log
tmpdir=/home/my3307
sql-mode=NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
sha256_password_private_key_path=mykey.pem
sha256_password_public_key_path=mykey.pub
server_id=102453307
master_info_repository="TABLE"
relay_log_info_repository="TABLE"
relay_log_recovery=1
[mysqldump]
quick
max_allowed_packet = 64M

Revision history for this message
tuna (ant750505) said : 		#6

The Error log：

160701 10:03:08 mysqld_safe Starting mysqld daemon with databases from /home/my3307
2016-07-01 10:03:09 0 [Note] /usr/sbin/mysqld (mysqld 5.6.24-72.2-log) starting as process 25461 ...
2016-07-01 10:03:09 25461 [Note] Plugin 'FEDERATED' is disabled.
2016-07-01 10:03:09 25461 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-07-01 10:03:09 25461 [Note] InnoDB: The InnoDB memory heap is disabled
2016-07-01 10:03:09 25461 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-07-01 10:03:09 25461 [Note] InnoDB: Memory barrier is not used
2016-07-01 10:03:09 25461 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-07-01 10:03:09 25461 [Note] InnoDB: Using Linux native AIO
2016-07-01 10:03:09 25461 [Note] InnoDB: Using CPU crc32 instructions
2016-07-01 10:03:09 25461 [Note] InnoDB: Initializing buffer pool, size = 9.8G
2016-07-01 10:03:10 25461 [Note] InnoDB: Completed initialization of buffer pool
2016-07-01 10:03:10 25461 [Note] InnoDB: Highest supported file format is Barracuda.
2016-07-01 10:03:10 25461 [Note] InnoDB: The log sequence numbers 1625988 and 1625988 in ibdata files do not match the log sequence number 109126865480 in the ib_logfiles!
2016-07-01 10:03:10 25461 [Note] InnoDB: Database was not shutdown normally!
2016-07-01 10:03:10 25461 [Note] InnoDB: Starting crash recovery.
2016-07-01 10:03:10 25461 [Note] InnoDB: Reading tablespace information from the .ibd files...
2016-07-01 10:03:16 25461 [Note] InnoDB: Restoring possible half-written data pages
2016-07-01 10:03:16 25461 [Note] InnoDB: from the doublewrite buffer...
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 22 row operations to undo
InnoDB: Trx id counter is 88576
InnoDB: Last MySQL binlog file position 0 48872474, file name mysql-bin.000035
2016-07-01 10:03:17 25461 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2016-07-01 10:03:17 7fc4be2d9700 InnoDB: Rolling back trx with id 88098, 22 rows to undo
2016-07-01 10:03:17 25461 [Note] InnoDB: Waiting for purge to start
2016-07-01 10:03:17 25461 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.24-72.2 started; log sequence number 109126865480
2016-07-01 10:03:17 25461 [Note] Recovering after a crash using mysql-bin
2016-07-01 10:03:17 25461 [Note] InnoDB: Rollback of trx with id 88098 completed
2016-07-01 10:03:17 7fc4be2d9700 InnoDB: Rollback of non-prepared transactions completed
2016-07-01 10:03:18 25461 [Note] Starting crash recovery...
2016-07-01 10:03:18 25461 [Note] Crash recovery finished.
2016-07-01 10:03:18 25461 [Note] RSA private key file not found: /home/my3307//mykey.pem. Some authentication plugins will not work.
2016-07-01 10:03:18 25461 [Note] Server hostname (bind-address): '*'; port: 3307
2016-07-01 10:03:18 25461 [Note] IPv6 is available.
2016-07-01 10:03:18 25461 [Note] - '::' resolves to '::';
2016-07-01 10:03:18 25461 [Note] Server socket created on IP: '::'.
2016-07-01 10:03:19 25461 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=mysqld-relay-bin' to avoid this problem.

Revision history for this message
tuna (ant750505) said : 		#7

mysql> show global variables like '%locking%';
+-----------------------------+-------+
| Variable_name | Value |
 +-----------------------------+-------+
| innodb_locking_fake_changes | ON |
| skip_external_locking | ON |
 +-----------------------------+-------+
2 rows in set (0.00 sec)

Revision history for this message
tuna (ant750505) said : 		#8

mysql> show global status like '%files%';
+-----------------------+-------+
| Variable_name | Value |
 +-----------------------+-------+
| Com_show_profiles | 0 |
| Created_tmp_files | 6 |
| Innodb_num_open_files | 481 |
| Open_files | 22 |
| Opened_files | 229 |
 +-----------------------+-------+
5 rows in set (0.00 sec)

mysql> show global variables like '%files%';
+---------------------------+--------+
| Variable_name | Value |
 +---------------------------+--------+
| character_set_filesystem | binary |
| innodb_log_files_in_group | 3 |
| innodb_open_files | 2000 |
| keep_files_on_create | OFF |
| large_files_support | ON |
| max_binlog_files | 0 |
| max_slowlog_files | 0 |
| open_files_limit | 8192 |
 +---------------------------+--------+
8 rows in set (0.00 sec)

Revision history for this message
tuna (ant750505) said : 		#9

mysql> select * from performance_schema.threads where processlist_state='system lock';
+-----------+----------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+--------------------------------------+------------------+------+--------------+
| THREAD_ID | NAME | TYPE | PROCESSLIST_ID | PROCESSLIST_USER | PROCESSLIST_HOST | PROCESSLIST_DB | PROCESSLIST_COMMAND | PROCESSLIST_TIME | PROCESSLIST_STATE | PROCESSLIST_INFO | PARENT_THREAD_ID | ROLE | INSTRUMENTED |
 +-----------+----------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+--------------------------------------+------------------+------+--------------+
| 1 | thread/sql/main | BACKGROUND | NULL | NULL | NULL | NULL | NULL | 15284 | System lock | INTERNAL DDL LOG RECOVER IN PROGRESS | NULL | NULL | YES |
| 36 | thread/sql/slave_sql | BACKGROUND | NULL | root | localhost | NULL | NULL | 121760 | System lock | NULL | 34 | NULL | YES |
 +-----------+----------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+--------------------------------------+------------------+------+--------------+
2 rows in set (0.21 sec)

Revision history for this message
tuna (ant750505) said : 		#10

I have found For mysql bug.
AS:http://bugs.mysql.com/bug.php?id=72131

Which version fixed the bug.

Revision history for this message
tuna (ant750505) said : 		#11

I have upgrade the MySQL version to 5.6.30,The system lock question still is exists.

Revision history for this message
Launchpad Janitor (janitor) said : 		#12

This question was expired because it remained in the 'Open' state without activity for the last 15 days.