← Back to team overview

maria-developers team mailing list archive

Re: [codership-team] Hanging Galera Cluster, looking for the cause


I have seen exactly the same issue again, second day in a row. This time at 7:30 in the morning and again, no logs or anything that would give me an idea of what could have caused this. "killall -9 mysqld" and "service mysql start" on the hanging node is the only solution I have so far...

I am crossposting this to maria-developers, maybe somebody on that list has an idea where to start?


Am 31.05.2013 10:29, schrieb Jan Kirchhoff:

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 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_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
Per second averages calculated from the last 18 seconds
srv_master_thread loops: 907033 1_second, 906789 sleeps, 89831
10_second, 22491 background, 22489 flush
srv_master_thread log flush and writes: 478222
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
I/O thread 0 state: waiting for completed aio requests (insert buffer
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
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 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
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]
1 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
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
Trx id counter 2F89DD34
Purge done for trx's n:o < 2F754554 undo n:o < 0
History list length 140
---TRANSACTION 0, not started
MySQL thread id 113586, OS thread handle 0x7fab314fe700, query id
45250432 localhost root sleeping
---TRANSACTION 2F89DC7B, not started
MySQL thread id 113583, OS thread handle 0x7fab315d9700, query id
45250367 cl4.logical-line.de stats_pflege sleeping
---TRANSACTION 2F89DB4F, not started
MySQL thread id 113582, OS thread handle 0x7fab31622700, query id
45250261 cl4.logical-line.de stats_pflege sleeping
---TRANSACTION 2F89DA23, not started
MySQL thread id 113578, OS thread handle 0x7fab31746700, query id
45250159 cl4.logical-line.de 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
May 31 10:16:59 db9 mysqld: 130531 10:16:59 [Note] WSREP: Closed send
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