GET 24/7 LIVE HELP NOW

Announcement

Announcement Module
Collapse
No announcement yet.

Replication lag in 5.5 after buffer pool fills up

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

  • Replication lag in 5.5 after buffer pool fills up

    Hi,

    Recently we've completed an upgrade to Percona 5.5.21 and after running fine for a few weeks, our slaves started lagging behind. We noticed this occurred right when the buffer pool filled up on the slaves. After bouncing one of the slaves and clearing the buffer pool, the replication caught up right away. We did not experience this problem on 5.1 on the same hardware configuration. The insert rate is very low, around 70/sec. There was a huge jump in spin rounds once the buffer pool filled up. Below is a copy of the my.cnf from a server and an output of SHOW INNODB STATUS from a slave that is falling behind.


    [mysqld]
    datadir=/data/mysql
    expire_logs_days = 15
    innodb_adaptive_flushing = 0
    innodb_buffer_pool_size = 53G
    innodb_data_file_path = ibdata1:100M:autoextend
    innodb_doublewrite = 1
    innodb_file_per_table = 1
    innodb_flush_log_at_trx_commit = 2
    innodb_flush_method = O_DIRECT
    innodb_io_capacity = 3000
    innodb_log_buffer_size = 4M
    innodb_log_file_size = 512M
    innodb_log_files_in_group = 3
    innodb_max_dirty_pages_pct = 80
    innodb_read_ahead = none
    innodb_read_io_threads = 24
    innodb_support_xa = 0
    innodb_thread_concurrency = 16
    innodb_use_sys_malloc = 1
    innodb_write_io_threads = 12
    key_buffer_size = 64M
    log-error = /var/log/mysqld.log
    log-queries-not-using-indexes
    log-slow-queries = /data/mysql/mysql-slow.log
    log_bin = /data/mysql/binlog/mysql-bin.log
    log_slave_updates = 1
    long_query_time = 2
    max_binlog_size = 250M
    max_connections = 4096
    max_heap_table_size = 64M
    query_cache_limit = 2M
    query_cache_size = 64M
    read_buffer_size = 2M
    read_rnd_buffer_size = 8M
    relay-log-index = /data/mysql/relay-logs/db-relay-bin.index
    relay-log = /data/mysql/relay-logs/db-relay-bin
    relay_log_space_limit = 25G
    replicate-same-server-id = 0
    server-id = 11129
    skip-name-resolve
    skip-slave-start
    socket = /var/lib/mysql/mysql.sock
    table_cache = 2048
    thread_cache_size = 32
    tmp_table_size = 64M
    tmpdir = /data/mysql/tmp
    user = mysql
    lc-messages-dir = /usr/share/mysql/english/



    mysql> SHOW ENGINE INNODB STATUS\G
    *************************** 1. row ***************************
    Type: InnoDB
    Name:
    Status:
    =====================================
    120605 15:57:07 INNODB MONITOR OUTPUT
    =====================================
    Per second averages calculated from the last 8 seconds
    -----------------
    BACKGROUND THREAD
    -----------------
    srv_master_thread loops: 2289882 1_second, 2289881 sleeps, 228966 10_second, 241 background, 241 flush
    srv_master_thread log flush and writes: 2311034
    ----------
    SEMAPHORES
    ----------
    OS WAIT ARRAY INFO: reservation count 613934, signal count 566935
    Mutex spin waits 4387304, rounds 7999861, OS waits 150111
    RW-shared spins 233448, rounds 6922705, OS waits 230420
    RW-excl spins 0, rounds 7033695, OS waits 231218
    Spin rounds per wait: 1.82 mutex, 29.65 RW-shared, 7033695.00 RW-excl
    --------
    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 (read thread)
    I/O thread 7 state: waiting for completed aio requests (read thread)
    I/O thread 8 state: waiting for completed aio requests (read thread)
    I/O thread 9 state: waiting for completed aio requests (read thread)
    I/O thread 10 state: waiting for completed aio requests (read thread)
    I/O thread 11 state: waiting for completed aio requests (read thread)
    I/O thread 12 state: waiting for completed aio requests (read thread)
    I/O thread 13 state: waiting for completed aio requests (read thread)
    I/O thread 14 state: waiting for completed aio requests (read thread)
    I/O thread 15 state: waiting for completed aio requests (read thread)
    I/O thread 16 state: waiting for completed aio requests (read thread)
    I/O thread 17 state: waiting for completed aio requests (read thread)
    I/O thread 18 state: waiting for completed aio requests (read thread)
    I/O thread 19 state: waiting for completed aio requests (read thread)
    I/O thread 20 state: waiting for completed aio requests (read thread)
    I/O thread 21 state: waiting for completed aio requests (read thread)
    I/O thread 22 state: waiting for completed aio requests (read thread)
    I/O thread 23 state: waiting for completed aio requests (read thread)
    I/O thread 24 state: waiting for completed aio requests (read thread)
    I/O thread 25 state: waiting for completed aio requests (read thread)
    I/O thread 26 state: waiting for completed aio requests (write thread)
    I/O thread 27 state: waiting for completed aio requests (write thread)
    I/O thread 28 state: waiting for completed aio requests (write thread)
    I/O thread 29 state: waiting for completed aio requests (write thread)
    I/O thread 30 state: waiting for completed aio requests (write thread)
    I/O thread 31 state: waiting for completed aio requests (write thread)
    I/O thread 32 state: waiting for completed aio requests (write thread)
    I/O thread 33 state: waiting for completed aio requests (write thread)
    I/O thread 34 state: waiting for completed aio requests (write thread)
    I/O thread 35 state: waiting for completed aio requests (write thread)
    I/O thread 36 state: waiting for completed aio requests (write thread)
    I/O thread 37 state: waiting for completed aio requests (write thread)
    Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] ,
    ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
    Pending flushes (fsync) log: 0; buffer pool: 0
    1714541 OS file reads, 224305112 OS file writes, 12307842 OS fsyncs
    2.62 reads/s, 16384 avg bytes/read, 105.86 writes/s, 8.37 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 112623829, node heap has 1 buffer(s)
    0.00 hash searches/s, 39.12 non-hash searches/s
    ---
    LOG
    ---
    Log sequence number 1015113642854
    Log flushed up to 1015113642854
    Last checkpoint at 1015113625347
    Max checkpoint age 1302939833
    Checkpoint age target 1262222964
    Modified age 17507
    Checkpoint age 17507
    0 pending log writes, 0 pending chkp writes
    116560569 log i/o's done, 38.62 log i/o's/second
    ----------------------
    BUFFER POOL AND MEMORY
    ----------------------
    Total memory allocated 58464403456; in additional pool allocated 0
    Internal hash tables (constant factor + variable factor)
    Adaptive hash index 901011232 (900990632 + 20600)
    Page hash 56312744 (buffer pool 0 only)
    Dictionary cache 225319932 (225249296 + 70636)
    File system 87512 (82672 + 4840)
    Lock system 146585976 (146585224 + 752)
    Recovery system 0 (0 + 0)
    Dictionary memory allocated 70636
    Buffer pool size 3473407
    Buffer pool size, bytes 56908300288
    Free buffers 0
    Database pages 3473406
    Old database pages 1282189
    Modified db pages 137
    Pending reads 0
    Pending writes: LRU 112, flush list 0, single page 0
    Pages made young 0, not young 0
    0.00 youngs/s, 0.00 non-youngs/s
    Pages read 1714385, created 1988761, written 105847991
    2.10 reads/s, 0.70 creates/s, 52.59 writes/s
    Buffer pool hit rate 992 / 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: 3473406, unzip_LRU len: 0
    I/O sum[4087]:cur[0], unzip sum[0]:cur[0]
    --------------
    ROW OPERATIONS
    --------------
    0 queries inside InnoDB, 0 queries in queue
    1 read views open inside InnoDB
    ---OLDEST VIEW---
    Normal read view
    Read view low limit trx n 6F812800
    Read view up limit trx id 6F812800
    Read view low limit trx id 6F812800
    Read view individually stored trx ids:
    -----------------
    Main thread process no. 24458, id 1509325120, state: sleeping
    Number of rows inserted 113611681, updated 0, deleted 0, read 0
    37.12 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
    ------------
    TRANSACTIONS
    ------------
    Trx id counter 7646BBA2
    Purge done for trx's n < 0 undo n < 0
    History list length 8
    LIST OF TRANSACTIONS FOR EACH SESSION:
    ---TRANSACTION 0, not started
    MySQL thread id 27122, OS thread handle 0x5d1ee940, query id 227343485 localhost root
    SHOW ENGINE INNODB STATUS
    ---TRANSACTION 7646BBA1, ACTIVE 6 sec inserting
    mysql tables in use 1, locked 1
    1 lock struct(s), heap size 376, 0 row lock(s)
    MySQL thread id 4, OS thread handle 0x5d270940, query id
    ----------------------------
    END OF INNODB MONITOR OUTPUT
    ============================

    1 row in set (1.80 sec)



    One possibility discussed was looking at the multiple buffer pool option in 5.5 but given we did not experience this in 5.1, I'm curious if there's something obvious to explain why we see such a performance degradation when the buffer pool fills up on 5.5. Thanks

  • #2
    if your not too concerned with a crash, innodb_flush_log_at_trx_commit = 0 , for the lag on the replica's

    state: sleeping
    History list length 8

    would indicate, to me at least, that your buffer pool isn't 'filled up' and flushing. also if you have your io capacity set to 3000, did you try O_DSYNC? ( assuming your on a san but maybe you have ssds ).

    Comment


    • #3
      federated_life wrote on Wed, 06 June 2012 20:15
      if your not too concerned with a crash, innodb_flush_log_at_trx_commit = 0 , for the lag on the replica's
      Since he is already running innodb_flush_log_at_trx_commit = 2 I don't think that is going to make any direct difference. Especially since the modification rate is so low as 105 writes/second.


      But here are the questions:
      1.
      What about overall memory usage on the machine?
      Is the OS possibly starting to swap and start use up IO, but you have only been looking at the MySQL status and only associated the problem with the buffer pool filling up?

      2.
      What kind of storage solution do you have?
      How much does it actually handle?

      3.
      Biggest change in 5.5 related to this is probably the native support for AIO on Linux.
      Have you tried as a test to switch back to InnoDB's emulated AIO with innodb_use_native_aio = 0 ? (although I think it's a long shot)

      Comment


      • #4
        Quote:
        But here are the questions:
        1.
        What about overall memory usage on the machine?
        Is the OS possibly starting to swap and start use up IO, but you have only been looking at the MySQL status and only associated the problem with the buffer pool filling up?
        Memory usage on the machine is stable, not going into swap at all. We also have the NUMA fix in place to ensure the memory is being evenly balanced.

        Quote:
        2.
        What kind of storage solution do you have?
        How much does it actually handle?
        12 disk, RAID 10 with 15k drives, utilization during normal replication is 2%, during backups it peaks to 60%

        Quote:
        3.
        Biggest change in 5.5 related to this is probably the native support for AIO on Linux.
        Have you tried as a test to switch back to InnoDB's emulated AIO with innodb_use_native_aio = 0 ? (although I think it's a long shot)
        I'll have to research this some more.


        Oddly enough when trying to run oprofile and get some information on one of the slaves we left up and running without a restart, it magically fixed itself seemingly during the time I was running oprofile to try and gather information. The slave started catching up shortly after, still unsure if it was a coincidence or not.

        Comment


        • #5
          We just had the problem crop up again and it "fixed" itself after a few hours again. Any ideas why we would see so many rounds but no spins?

          "RW-excl spins 0, rounds 7033695, OS waits 231218"

          Comment

          Working...
          X