MySQL5.7 SLAVE监控zabbix报警 报错Slave_SQL_Running_State: invalidating query cache entries (table)处理

1，Zabbix报警Slave延迟2万多个操作位

去slave从库上查看运行状态，果然Seconds_Behind_Master: 28810，而且提示Slave_SQL_Running_State: System lock而且这个是变化的，有的时候提示Slave_SQL_Running_State: invalidating query cache entries (table)，而且Seconds_Behind_Master: 29086 不停的增长着：

mysql> show slave status\G *************************** 1. row ***************************                Slave_IO_State: Waiting for master to send event                   Master_Host: 10.249.3.11                   Master_User: repl                   Master_Port: 3317                 Connect_Retry: 60               Master_Log_File: mysql-bin.000027           Read_Master_Log_Pos: 909456416                Relay_Log_File: mysql-relay-bin.000020                 Relay_Log_Pos: 19878093         Relay_Master_Log_File: mysql-bin.000014              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: 19877880               Relay_Log_Space: 14868115381               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: 29090 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: 12001                   Master_UUID: cfc81670-fca1-11e5-926d-0017fa0041c0              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          Replicate_Rewrite_DB:                  Channel_Name:            Master_TLS_Version: 1 row in set (0.00 sec)   mysql>

 

 

 

2，从innodb引擎状态分析

分析没有死锁，也没有异常信息，看来一切正常：

mysql> show engine innodb status\G *************************** 1. row ***************************   Type: InnoDB   Name: Status: ===================================== 2016-06-13 21:48:46 0x7fb1a4f65700 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 45 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 389 srv_active, 0 srv_shutdown, 22 srv_idle srv_master_thread log flush and writes: 411 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 3668625 OS WAIT ARRAY INFO: signal count 2833541 RW-shared spins 0, rounds 89, OS waits 14 RW-excl spins 0, rounds 53132, OS waits 1579 RW-sx spins 38, rounds 1124, OS waits 35 Spin rounds per wait: 89.00 RW-shared, 53132.00 RW-excl, 29.58 RW-sx ------------ TRANSACTIONS ------------ Trx id counter 7963036 Purge done for trx's n:o < 7963035 undo n:o < 0 state: running but idle History list length 1331 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421877794228048, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 7963035, ACTIVE 0 sec mysql tables in use 1, locked 1 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1 MySQL thread id 7, OS thread handle 140400954148608, query id 2760070 System lock -------- 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 thread) I/O thread 2 state: waiting for completed aio requests (read thread) I/O thread 3 state: waiting for completed aio requests (read thread) I/O thread 4 state: waiting for completed aio requests (read thread) I/O thread 5 state: waiting for completed aio requests (read thread) I/O thread 6 state: waiting for completed aio requests (write thread) I/O thread 7 state: waiting for completed aio requests (write thread) I/O thread 8 state: waiting for completed aio requests (write thread) I/O thread 9 state: waiting for completed aio requests (write thread) Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,  ibuf aio reads:, log i/o's:, sync i/o's: Pending flushes (fsync) log: 0; buffer pool: 0 14555 OS file reads, 13496 OS file writes, 5454 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 35.80 writes/s, 16.82 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 0, seg size 2, 0 merges merged operations:  insert 0, delete mark 0, delete 0 discarded operations:  insert 0, delete mark 0, delete 0 Hash table size 276671, node heap has 2 buffer(s) Hash table size 276671, node heap has 1 buffer(s) Hash table size 276671, node heap has 0 buffer(s) Hash table size 276671, node heap has 0 buffer(s) Hash table size 276671, node heap has 1 buffer(s) Hash table size 276671, node heap has 0 buffer(s) Hash table size 276671, node heap has 0 buffer(s) Hash table size 276671, node heap has 2 buffer(s) 6439.79 hash searches/s, 85.26 non-hash searches/s --- LOG --- Log sequence number 6797194382 Log flushed up to   6795126836 Pages flushed up to 6565491797 Last checkpoint at  6565491797 0 pending log flushes, 0 pending chkp writes 1024 log i/o's done, 2.98 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total large memory allocated 1099431936 Dictionary memory allocated 342972 Buffer pool size   65528 Free buffers       43909 Database pages     21613 Old database pages 7814 Modified db pages  1427 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 14334, created 7279, written 9709 0.00 reads/s, 17.04 creates/s, 24.47 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 21613, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] ---------------------- INDIVIDUAL BUFFER POOL INFO ---------------------- ---BUFFER POOL 0 Buffer pool size   8191 Free buffers       5492 Database pages     2698 Old database pages 975 Modified db pages  252 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 1802, created 896, written 1514 0.00 reads/s, 1.98 creates/s, 4.20 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 2698, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] ---BUFFER POOL 1 Buffer pool size   8191 Free buffers       5500 Database pages     2690 Old database pages 972 Modified db pages  46 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 1794, created 896, written 852 0.00 reads/s, 2.84 creates/s, 2.09 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 2690, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] ---BUFFER POOL 2 Buffer pool size   8191 Free buffers       5491 Database pages     2699 Old database pages 976 Modified db pages  58 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 1797, created 902, written 980 0.00 reads/s, 2.84 creates/s, 2.62 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 2699, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] ---BUFFER POOL 3 Buffer pool size   8191 Free buffers       5461 Database pages     2729 Old database pages 987 Modified db pages  256 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 1766, created 963, written 1492 0.00 reads/s, 2.84 creates/s, 3.16 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 2729, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] ---BUFFER POOL 4 Buffer pool size   8191 Free buffers       5462 Database pages     2728 Old database pages 987 Modified db pages  216 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 1794, created 934, written 1337 0.00 reads/s, 2.27 creates/s, 3.93 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 2728, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] ---BUFFER POOL 5 Buffer pool size   8191 Free buffers       5501 Database pages     2689 Old database pages 972 Modified db pages  178 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 1793, created 896, written 1182 0.00 reads/s, 1.42 creates/s, 2.87 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 2689, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] ---BUFFER POOL 6 Buffer pool size   8191 Free buffers       5499 Database pages     2692 Old database pages 973 Modified db pages  195 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 1796, created 896, written 1198 0.00 reads/s, 1.42 creates/s, 2.76 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 2692, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] ---BUFFER POOL 7 Buffer pool size   8191 Free buffers       5503 Database pages     2688 Old database pages 972 Modified db pages  226 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 1792, created 896, written 1154 0.00 reads/s, 1.42 creates/s, 2.84 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 2688, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 0 read views open inside InnoDB Process ID=13619, Main thread ID=140400758589184, state: sleeping Number of rows inserted 1380011, updated 1380018, deleted 0, read 1380041 3245.48 inserts/s, 3245.46 updates/s, 0.00 deletes/s, 3245.46 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================   1 row in set (0.00 sec)   mysql>

 

3，检查磁盘状态

看到磁盘还有很大使用空间，没有多少被占用的：

[root@azure_dna_dbm2_3_12 data]# df -h Filesystem      Size  Used Avail Use% Mounted on /dev/sda1        29G  5.6G   22G  21% / tmpfs            14G     0   14G   0% /dev/shm /dev/sdc       1007G   43G  914G   5% /data /dev/sdb1        56G   33G   21G  62% /mnt/resource [root@azure_dna_dbm2_3_12 data]#

 

 

4，查看mysql线程状况

线程正常，slave库没有多余的恶意登录，也没有多余的正在使用的慢sql卡住的情况：

mysql> show full processlist; +----+-------------+-----------+------+---------+-------+----------------------------------+-----------------------+ | Id | User        | Host      | db   | Command | Time  | State                            | Info                  | +----+-------------+-----------+------+---------+-------+----------------------------------+-----------------------+ |  1 | system user |           | NULL | Connect |   522 | Waiting for master to send event | NULL                  | |  2 | system user |           | NULL | Connect | 29423 | System lock                      | NULL                  | |  4 | root        | localhost | NULL | Query   |     0 | starting                         | show full processlist | +----+-------------+-----------+------+---------+-------+----------------------------------+-----------------------+ 3 rows in set (0.00 sec)   mysql> show global variables like 'innodb_log%'; +-----------------------------+------------+ | Variable_name               | Value      | +-----------------------------+------------+ | innodb_log_buffer_size      | 16777216   | | innodb_log_checksums        | ON         | | innodb_log_compressed_pages | ON         | | innodb_log_file_size        | 1073741824 | | innodb_log_files_in_group   | 3          | | innodb_log_group_home_dir   | ./         | | innodb_log_write_ahead_size | 8192       | +-----------------------------+------------+ 7 rows in set (0.00 sec)   mysql>

 

 

5，查看slave日志状态

看到slave状态里面，中级日志是000026，主库记录日志是000027，表示slave正在不停的执行中继日志，来追赶master日志，而且Read_Master_Log_Pos点位也在变化，意味着slave在不停的运转，来执行relay日志：

Read_Master_Log_Pos: 909456416               Master_Log_File: mysql-bin.000027                Relay_Master_Log_File: mysql-relay-bin.000026

 

 

6，查看error日志正常

Error里面没有任何异常信息

 

 

7，其它优化操作

（1）      设置了sync_binlog为0以及innodb_flush_log_at_trx_commit为0，也基本无效。

（2）      在my.cnf里面一开始就设置 query_cache_type = 0，然后重启mysql服务，基本无效。

（3）      加大tmp空间，基本无效。

（4）      关闭 event schedule，基本无效。

（5）      关闭query_cache，基本无效。

 

 

8，分析为master批量操作导致

分析了所有过程，没有异常信息，只有slave的Seconds_Behind_Master不停的增长，而且relay日志也在不停的应用，所以想到估计是master库做过了批量操作导致的，问了同事，他刚刚用mysql的load data导入了30G的sql文件进去。Oh，my god，终于知道原因了，master库批量导入30g文件，slave的单进程单线程模式，肯定会延迟的。

 

那么这种情况下，只有等待了，等待slave慢慢执行relay log了，果然过了一个晚上，第二天一看，slave已经正常了，Seconds_Behind_Master也变成正常的0了。