Hello guys, I need you, I have one problem and don’t know to solve. My slave servers, are delaying, delaying about 1 minute and a half and return to normal. And by the time delay, this message appears: “Connect invalidating query cache entrie (table)” … I disabled query_cache_type and query_cache_size, but the problem was not solved. Version mysql 5.1.69. Thank you very much.
This requires more information to diagnose the slave lag. Can you please share the processlist, innodb status, slave status etc or run pt-stalk during slave lag with --no-stock option. It will help to identify the issue.
FYI, some reasons of slave lag
- Replication is single threaded and if transaction on master is changing alot of rows this way slave can lag behind.
- If there are lot of read queries are running on slave this can bring slave lag because of locking.
I would also suggest that to enable slow query log on slave and identify the culprit queries and fix them.
Thank you for answering mirfan and help me figure out the problem. Below is the results you see, the same runtime process ID 11, is the same delay time. This problem started from nothing, did rollback to version 5.1.63, but the problem persists. The slow query log is also enabled, I’ll take a parsed. Thank you for your information, helped me a lot, especially the pt-stalk, I did not know him.
wsantana@edipo:(none)-> show full processlist; show innodb status\G show slave status\G
±------±------------±-------------------±--------±--------±------±-----------------------------------------±----------------------+
| Id | User | Host | db | Command | Time | State | Info |
±------±------------±-------------------±--------±--------±------±-----------------------------------------±----------------------+
| 10 | system user | | NULL | Connect | 73684 | Waiting for master to send event | NULL |
| 11 | system user | | NULL | Connect | 55 | invalidating query cache entries (table) | NULL |
| 45389 | wsantana | 172.16.18.22:44803 | NULL | Query | 0 | NULL | show full processlist |
| 45407 | ci_vagas | 10.41.21.30:56392 | conline | Sleep | 1 | | NULL |
±------±------------±-------------------±--------±--------±------±-----------------------------------------±----------------------+
4 rows in set (0.00 sec)
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
130606 11:52:00 INNODB MONITOR OUTPUT
Per second averages calculated from the last 5 seconds
BACKGROUND THREAD
srv_master_thread loops: 61610 1_second, 61609 sleeps, 6042 10_second, 6081 background, 6077 flush
srv_master_thread log flush and writes: 61931
SEMAPHORES
OS WAIT ARRAY INFO: reservation count 38287, signal count 222611
Mutex spin waits 361197, rounds 1012970, OS waits 22385
RW-shared spins 50511, OS waits 12166; RW-excl spins 4205, OS waits 3505
Spin rounds per wait: 2.80 mutex, 10.31 RW-shared, 74.48 RW-excl
TRANSACTIONS
Trx id counter 2827A8402
Purge done for trx’s n:o < 2827A83E1 undo n:o < 0
History list length 11
LIST OF TRANSACTIONS FOR EACH SESSION:
—TRANSACTION 2827A83F5, not started, process no 20489, OS thread id 140424495904512
MySQL thread id 45407, query id 4702285 10.41.21.30 ci_vagas
—TRANSACTION 0, not started, process no 20489, OS thread id 140424434325248
MySQL thread id 45389, query id 4702309 172.16.18.22 wsantana
show innodb status
—TRANSACTION 2827A8401, ACTIVE 0 sec, process no 20489, OS thread id 140424495105792 fetching rows
mysql tables in use 1, locked 1
7610 lock struct(s), heap size 948664, 79377 row lock(s), undo log entries 1
MySQL thread id 11, query id 4702307 invalidating query cache entries (table)
FILE I/O
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
ibuf aio reads: 0, log i/o’s: 0, sync i/o’s: 0
Pending flushes (fsync) log: 0; buffer pool: 0
469096 OS file reads, 2601641 OS file writes, 2035578 OS fsyncs
0.80 reads/s, 16384 avg bytes/read, 56.99 writes/s, 33.39 fsyncs/s
INSERT BUFFER AND ADAPTIVE HASH INDEX
Ibuf: size 1, free list len 687, seg size 689,
139722 inserts, 145505 merged recs, 97389 merges
Hash table size 31874747, node heap has 17975 buffer(s)
805291.14 hash searches/s, 3482.70 non-hash searches/s
LOG
Log sequence number 9526051723870
Log flushed up to 9526051723630
Last checkpoint at 9526015758438
0 pending log writes, 0 pending chkp writes
1925300 log i/o’s done, 31.39 log i/o’s/second
BUFFER POOL AND MEMORY
Total memory allocated 16467886080; in additional pool allocated 0
Dictionary memory allocated 3965962
Buffer pool size 983040
Free buffers 421349
Database pages 543659
Old database pages 200706
Modified db pages 19948
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8099, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 530302, created 16070, written 854406
0.80 reads/s, 0.00 creates/s, 53.19 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: 543659, unzip_LRU len: 0
I/O sum[1046]:cur[0], unzip sum[0]:cur[0]
ROW OPERATIONS
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 20489, id 140406392428288, state: sleeping
Number of rows inserted 1903838, updated 566562, deleted 1263229, read 18118733133
27.99 inserts/s, 17.40 updates/s, 24.00 deletes/s, 807927.01 reads/s
END OF INNODB MONITOR OUTPUT
1 row in set, 1 warning (0.01 sec)
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 10.40.41.11
Master_User: slave
Master_Port: 3306
Connect_Retry: 15
Master_Log_File: afrodite-bin.000332
Read_Master_Log_Pos: 78044461
Relay_Log_File: relay-bin.001005
Relay_Log_Pos: 78033814
Relay_Master_Log_File: afrodite-bin.000332
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: mysql.%,temporario.%
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 78041766
Relay_Log_Space: 78044860
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: 55
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
1 row in set (0.00 sec)
Wsantana,
Are you running with ROW based replication?
It seems similar to the bug described here: [url]MySQL Bugs: #60696: invalidating query cache entries (table) hangs replication
I think you should try to disable query cache in my.cnf and restart the server to see if you still get into this “invalidating query cache entries” state again.
Add following to configuration, since disabling dynamically may not have exactly the same effect.
query_cache_type=0
query_cache_size=0
Thank you very much for answering przemek and help me figure out the problem, my based replication is MIXED.
I read about bug, described here: [url]MySQL Bugs: #60696: invalidating query cache entries (table) hangs replication, and I disabled as you directed me, because I had disabled dynamically. Even disabling in the my.cnf, the problem persisted.
I managed to find the cause of the problem, is a php script which is scheduled to run from 12 to 12 minutes. The pt-stalk helped me find the problem.
Just Could not understand why the lag, below is the error that is happening, the error is CONSTRAINT, has warned developers to correct them.
Foreign key constraint fails for table atende_produto_especial.produto_distribuicao_texto:
LATEST FOREIGN KEY ERROR
130607 15:37:24 Transaction:
TRANSACTION 2AE56991E, ACTIVE 0 sec, process no 21066, OS thread id 140289406871296 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 1
MySQL thread id 21335800, query id 1397584584 10.81.21.113 modulos_produto update
INSERT INTO^M
produto_distribuicao_texto^M
SET^M
produto_distribuicao_texto.produto_distribuicao_id = “2729727” , produto_distribuicao_texto.texto = "Telefone Principal: 11-^M
Telefone Secund?rio: 11-**^M
Email: ***@gmail.com" / — /www_mounted/intranet/htdocs/siscorp/action/cron/cron_atende_distribuicao_especial.php/
Foreign key constraint fails for table atende_produto_especial.produto_distribuicao_texto:
,
CONSTRAINT produto_distribuicao_texto_ibfk_1 FOREIGN KEY (produto_distribuicao_id) REFERENCES produto_distribuicao (produto_distribuicao_id) ON DELETE NO ACTION ON UPDATE NO ACTION
Trying to add in child table, in index produto_distribuicao_id tuple:
DATA TUPLE: 2 fields;
0: len 4; hex 0029a6ff; asc ) ;;
1: len 4; hex 802a4caf; asc *L ;;
But in parent table atende_produto_especial.produto_distribuicao, in index PRIMARY,
the closest match we can find is record:
PHYSICAL RECORD: n_fields 9; compact format; info bits 0
0: len 4; hex 0029a700; asc ) ;;
1: len 6; hex 0002ae5128d1; asc Q( ;;
2: len 7; hex 80000000330110; asc 3 ;;
3: len 4; hex 0000014d; asc M;;
4: len 3; hex 06adc3; asc ;;
5: len 4; hex 51b20642; asc Q B;;
6: len 4; hex 0000004b; asc K;;
7: len 1; hex 02; asc ;;
8: len 4; hex 80000000; asc ;;