Hi,
we have been testing MariaDB 5.5.29 with Galera
(wsrep_provider_version 23.2.4(r147)) for a few months now and have had
a freeze of the cluster for the second time now. I didn't report the
first hang about 6 weeks ago as I wanted to be sure it wasn't our fault,
but I can't find any type of network issue or such in our monitoring
system and nothing in the logs that could be related to this problem:
We have 2 database servers running Ubuntu 12.10 with Kernel 3.5.0
(names: db8, db9), with a bunch of 15k-disks, some SSDs, 128GB RAM and a
test database of about 600-700GB. The amount of binlogs written every
day is around 500GB, so you get an idea of the workload.
db8 is a slave (traditional replication) of our main database. We have a
garbd running on another server as a third galera instance.
Everything runs smooth for some weeks, but since this morning at 3:50am
db9 seems to be frozen. The server itself looks good, mysqld is taking
about 50% of one CPU core, everything else looks normal. Nothing in the
logs. Connecting to mysql works, but any query (like "show status" or
normal selects) hang forever. Only "show engine innodb status" returns.
There are almost 3000 processes that piled up like this:
---TRANSACTION 2F89D7CB, not started
MySQL thread id 113575, OS thread handle 0x7fab31821700, query id
45249946 cl4.logical-line.de 192.168.0.16 stats_pflege sleeping
but none of them ever gets any further. I can issue a "kill 113575" and
the prompt returns, but nothing happens.
This is what db8's global status says:
wsrep_local_state_uuid 41d7259d-7200-11e2-0800-943dd0e2f659
wsrep_protocol_version 4
wsrep_last_committed 179518511
wsrep_replicated 53590833
wsrep_replicated_bytes 14768686288759
wsrep_received 894995
wsrep_received_bytes 7161712
wsrep_local_commits 53583808
wsrep_local_cert_failures 60
wsrep_local_bf_aborts 0
wsrep_local_replays 0
wsrep_local_send_queue 8
wsrep_local_send_queue_avg 0.000000
wsrep_local_recv_queue 0
wsrep_local_recv_queue_avg 0.000000
wsrep_flow_control_paused 1.000000
wsrep_flow_control_sent 0
wsrep_flow_control_recv 0
wsrep_cert_deps_distance 73.229730
wsrep_apply_oooe 0.000000
wsrep_apply_oool 0.000000
wsrep_apply_window 0.000000
wsrep_commit_oooe 0.000000
wsrep_commit_oool 0.000000
wsrep_commit_window 0.000000
wsrep_local_state 4
wsrep_local_state_comment Synced
wsrep_cert_index_size 25606
wsrep_causal_reads 0
wsrep_incoming_addresses 192.168.10.30:3306,192.168.10.31:3306,
wsrep_cluster_conf_id 15
wsrep_cluster_size 3
wsrep_cluster_state_uuid 41d7259d-7200-11e2-0800-943dd0e2f659
wsrep_cluster_status Primary
wsrep_connected ON
wsrep_local_index 0
wsrep_provider_name Galera
wsrep_provider_vendor Codership Oy <info@xxxxxxxxxxxxx>
wsrep_provider_version 23.2.4(r147)
wsrep_ready ON
Here is the innodb status from db9 (the one that hangs). This is the
only output I could get out of db9 at all:
Type Name Status
InnoDB
=====================================
130531 10:02:08 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 18 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 907033 1_second, 906789 sleeps, 89831
10_second, 22491 background, 22489 flush
srv_master_thread log flush and writes: 478222
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 17017782, signal count 287266881
Mutex spin waits 98936299, rounds 91970366, OS waits 868715
RW-shared spins 139527705, rounds 455067309, OS waits 6488041
RW-excl spins 58122849, rounds 842712424, OS waits 8565312
Spin rounds per wait: 0.93 mutex, 3.26 RW-shared, 14.50 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 (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
49405970 OS file reads, 277420410 OS file writes, 6653801 OS fsyncs
1 pending preads, 0 pending pwrites
49.44 reads/s, 16384 avg bytes/read, 0.61 writes/s, 0.61 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 698, seg size 700, 300226 merges
merged operations:
insert 410879, delete mark 8032461, delete 82075
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 212497717, node heap has 450852 buffer(s)
16846.79 hash searches/s, 77045.28 non-hash searches/s
---
LOG
---
Log sequence number 18522888544071
Log flushed up to 18522888544071
Last checkpoint at 18522888544051
Max checkpoint age 2035833201
Checkpoint age target 1972213414
Modified age 20
Checkpoint age 20
0 pending log writes, 0 pending chkp writes
6895012 log i/o's done, 0.39 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 110310195200; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
Adaptive hash index 9086745120 \t(1699981736 + 7386763384)
Page hash 106249768 (buffer pool 0 only)
Dictionary cache 426512815 \t(424997488 + 1515327)
File system 429392 \t(82672 + 346720)
Lock system 296805680 \t(295674296 + 1131384)
Recovery system 0 \t(0 + 0)
Dictionary memory allocated 1515327
Buffer pool size 6553599
Buffer pool size, bytes 107374166016
Free buffers 0
Database pages 6102747
Old database pages 2252752
Modified db pages 1
Pending reads 1
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 48135625, not young 0
64.83 youngs/s, 0.00 non-youngs/s
Pages read 49405737, created 7213276, written 266046626
49.44 reads/s, 0.00 creates/s, 0.11 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 40.11/s, Random read
ahead 0.00/s
LRU len: 6102747, unzip_LRU len: 0
I/O sum[2662]:cur[22], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
1 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o 2F754555
Read view up limit trx id 2F754555
Read view low limit trx id 2F754555
Read view individually stored trx ids:
-----------------
Main thread process no. 15888, id 140381271201536, state: sleeping
Number of rows inserted 46059494, updated 2501543763, deleted 28801859,
read 17046037029
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 48965.50 reads/s
------------
TRANSACTIONS
------------
Trx id counter 2F89DD34
Purge done for trx's n:o < 2F754554 undo n:o < 0
History list length 140
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 113586, OS thread handle 0x7fab314fe700, query id
45250432 localhost root sleeping
SHOW engine INNODB STATUS
---TRANSACTION 2F89DC7B, not started
MySQL thread id 113583, OS thread handle 0x7fab315d9700, query id
45250367 cl4.logical-line.de 192.168.0.16 stats_pflege sleeping
---TRANSACTION 2F89DB4F, not started
MySQL thread id 113582, OS thread handle 0x7fab31622700, query id
45250261 cl4.logical-line.de 192.168.0.16 stats_pflege sleeping
---TRANSACTION 2F89DA23, not started
MySQL thread id 113578, OS thread handle 0x7fab31746700, query id
45250159 cl4.logical-line.de 192.168.0.16 stats_pflege sleeping
---TRANSACTION 0, not started
<many many rows like these, around 3000 although max_connections is 300?! >
As soon as I trigger the restart of mysql on db9 (service mysql
restart), I see normal log entries like this:
May 31 10:16:59 db9 mysqld: 130531 10:16:59 [Note] WSREP: Stop replication
May 31 10:16:59 db9 mysqld: 130531 10:16:59 [Note] WSREP: Closing send
monitor...
May 31 10:16:59 db9 mysqld: 130531 10:16:59 [Note] WSREP: Closed send
monitor.
May 31 10:16:59 db9 mysqld: 130531 10:16:59 [Note] WSREP: gcomm:
terminating thread
and db8 is accepting inserts again and catches up with replication.
meanwhile, db9 says:
May 31 10:17:02 db9 mysqld: 130531 10:17:02 [Note] WSREP: killing local
connection: 113529
May 31 10:17:02 db9 mysqld: 130531 10:17:02 [Note] WSREP: killing local
connection: 113199
May 31 10:17:02 db9 mysqld: 130531 10:17:02 [Note] WSREP: killing local
connection: 110221
and nothing happens any more. No CPU and no IO load coming from the
mysqld processes.
After 5 minutes I killed the mysqld with "killall -9 mysqld" and then
started it again the normal way.
db9 syncs via IST and everything is fine again. But I have no idea what
caused all this. According to a colleague killing mysql on db9 was the
thing that helped 6 weeks ago, too.
Thanks for any pointers where we should look further.
Jan Kirchhoff
