Announcement

Announcement Module
Collapse
No announcement yet.

My slave servers, are delaying (Connect invalidating query cache entrie (table))

Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • My slave servers, are delaying (Connect invalidating query cache entrie (table))

    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.

  • #2
    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
    1) Replication is single threaded and if transaction on master is changing alot of rows this way slave can lag behind.
    2) 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.

    Comment


    • #3
      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@ediponone)-> 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 < 2827A83E1 undo n < 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)
      Last edited by wsantana; 06-06-2013, 12:53 PM.

      Comment


      • #4
        Wsantana,

        Are you running with ROW based replication?
        It seems similar to the bug described here: http://bugs.mysql.com/bug.php?id=60696
        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

        Comment


        • wsantana
          wsantana commented
          Editing a comment
          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: http://bugs.mysql.com/bug.php?id=60696, 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_te xto`:

          ------------------------
          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_te xto`:
          ,
          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 ;;
      Working...
      X