Announcement

Announcement Module
Collapse
No announcement yet.

Xtradb 5.5.34 cluster is hung with semaphores for 30 mins

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

  • Xtradb 5.5.34 cluster is hung with semaphores for 30 mins

    I had an issue with my 3 node cluster this morning
    and when i checked the processlist, it was about 300 processes and the load average on the server was about 20

    show engine innodb status was

    mysql> show engine innodb status\G;
    *************************** 1. row ***************************
    Type: InnoDB
    Name:
    Status:
    =====================================
    140530 11:56:18 INNODB MONITOR OUTPUT
    =====================================
    Per second averages calculated from the last 35 seconds
    -----------------
    BACKGROUND THREAD
    -----------------
    srv_master_thread loops: 213 1_second, 212 sleeps, 21 10_second, 1 background, 1 flush
    srv_master_thread log flush and writes: 216
    ----------
    SEMAPHORES
    ----------
    OS WAIT ARRAY INFO: reservation count 396335, signal count 65288
    --Thread 140005560661760 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --Thread 140005551077120 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --Thread 140004927194880 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --Thread 140005555869440 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --Thread 140005555603200 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --Thread 140005543622400 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --Thread 140004927993600 has waited at row0sel.c line 3670 for 0.0000 seconds the semaphore:
    S-lock on RW-latch at 0x6653a48 '&btr_search_latch_arr[i]'
    number of readers 0, waiters flag 0, lock_word: 100000
    Last time read locked in file row0sel.c line 3670
    Last time write locked in file /mnt/workspace/percona-xtradb-cluster-debs/label_exp/ubuntu-precise-64bit/target/Percona-XtraDB-Cluster-5.5.34/storage/innobase/btr/btr0sea.c line 674
    --Thread 140005536966400 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --Thread 140005551875840 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --Thread 140005535368960 has waited at row0sel.c line 3670 for 0.0000 seconds the semaphore:
    S-lock on RW-latch at 0x6653a48 '&btr_search_latch_arr[i]'
    number of readers 0, waiters flag 0, lock_word: 100000
    Last time read locked in file row0sel.c line 3670
    Last time write locked in file /mnt/workspace/percona-xtradb-cluster-debs/label_exp/ubuntu-precise-64bit/target/Percona-XtraDB-Cluster-5.5.34/storage/innobase/btr/btr0sea.c line 674
    --Thread 140005536700160 has waited at row0sel.c line 3670 for 0.0000 seconds the semaphore:
    S-lock on RW-latch at 0x6653a48 '&btr_search_latch_arr[i]'
    number of readers 0, waiters flag 0, lock_word: 100000
    Last time read locked in file row0sel.c line 3670
    Last time write locked in file /mnt/workspace/percona-xtradb-cluster-debs/label_exp/ubuntu-precise-64bit/target/Percona-XtraDB-Cluster-5.5.34/storage/innobase/btr/btr0sea.c line 674
    --Thread 140005559064320 has waited at buf0buf.ic line 376 for 0.0000 seconds the semaphore:
    Mutex at 0x7f55a3f645f0 '&block->mutex', lock var 0
    waiters flag 0
    --------
    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, 0] , aio writes: 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
    78491 OS file reads, 13057 OS file writes, 10571 OS fsyncs
    0.49 reads/s, 16384 avg bytes/read, 48.17 writes/s, 24.26 fsyncs/s
    -------------------------------------
    INSERT BUFFER AND ADAPTIVE HASH INDEX
    -------------------------------------
    Ibuf: size 1, free list len 29, seg size 31, 202 merges
    merged operations:
    insert 1312, delete mark 19, delete 14
    discarded operations:
    insert 0, delete mark 0, delete 0
    Hash table size 4425293, node heap has 33 buffer(s)
    451242.08 hash searches/s, 224663.50 non-hash searches/s
    ---
    LOG
    ---
    Log sequence number 147447557967
    Log flushed up to 147447557686
    Last checkpoint at 147447475545
    Max checkpoint age 108005254
    Checkpoint age target 104630090
    Modified age 82422
    Checkpoint age 82422
    0 pending log writes, 0 pending chkp writes
    10361 log i/o's done, 22.34 log i/o's/second
    ----------------------
    BUFFER POOL AND MEMORY
    ----------------------
    Total memory allocated 2204106752; in additional pool allocated 0
    Total memory allocated by read views 31912
    Internal hash tables (constant factor + variable factor)
    Adaptive hash index 35947232 (35402344 + 544888)
    Page hash 2213656 (buffer pool 0 only)
    Dictionary cache 9282508 (8851984 + 430524)
    File system 214000 (82672 + 131328)
    Lock system 5339736 (5313416 + 26320)
    Recovery system 0 (0 + 0)
    Dictionary memory allocated 430524
    Buffer pool size 131071
    Buffer pool size, bytes 2147467264
    Free buffers 52526
    Database pages 78512
    Old database pages 29001
    Modified db pages 113
    Pending reads 0
    Pending writes: LRU 0, flush list 0, single page 0
    Pages made young 13, not young 0
    0.03 youngs/s, 0.00 non-youngs/s
    Pages read 78427, created 85, written 2630
    0.46 reads/s, 0.20 creates/s, 25.26 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: 78512, 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
    66 read views open inside InnoDB
    65 transactions active inside InnoDB
    65 out of 1000 descriptors used
    ---OLDEST VIEW---
    Normal read view
    Read view low limit trx n 2747ABC
    Read view up limit trx id 2747ABB
    Read view low limit trx id 2747ABC
    Read view individually stored trx ids:
    Read view trx id 2747ABB
    -----------------
    Main thread process no. 11805, id 140005579044608, state: flushing log
    Number of rows inserted 4641, updated 886, deleted 72, read 96396503
    10.06 inserts/s, 2.03 updates/s, 0.09 deletes/s, 450948.66 reads/s

  • #2
    ok a bug report has been updated with this issue, so if anyone wants to follow the issue here is the link

    https://bugs.launchpad.net/percona-server/+bug/1182918

    Comment

    Working...
    X