2

I'm having some hard time diagnosing MariaDB Cluster issue that I would like to have some advices.

We're running a 3-nodes MariaDB Cluster, each node is on a dedicated ESXi server, and connected by local network at the same data center. Recently, we found out that they are occasionally having timeout error, we look at a lot of things but failed to come to a conclusion.

Here are the detailed logs of the timeout error:

181009 18:35:14 [Note] WSREP: (b1d2aacb, 'tcp://0.0.0.0:4567') connection to peer 0a520ba7 with addr tcp://192.168.[censor]:4567 timed out, no messages seen in PT3S
181009 18:35:14 [Note] WSREP: (b1d2aacb, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: tcp://192.168.[censor]:4567
181009 18:35:15 [Note] WSREP: (b1d2aacb, 'tcp://0.0.0.0:4567') reconnecting to 0a520ba7 (tcp://192.168.[censor]:4567), attempt 0
181009 18:35:17 [Note] WSREP: evs::proto(b1d2aacb, GATHER, view_id(REG,0a520ba7,147)) suspecting node: 0a520ba7
181009 18:35:17 [Note] WSREP: evs::proto(b1d2aacb, GATHER, view_id(REG,0a520ba7,147)) suspected node without join message, declaring inactive
181009 18:35:18 [Note] WSREP: declaring e0d6a63b at tcp://192.168.[censor]:4567 stable
181009 18:35:18 [Note] WSREP: Node b1d2aacb state prim
181009 18:35:18 [Note] WSREP: view(view_id(PRIM,b1d2aacb,148) memb {
    b1d2aacb,0
    e0d6a63b,0
} joined {
} left {
} partitioned {
    0a520ba7,0
})
181009 18:35:18 [Note] WSREP: save pc into disk
181009 18:35:18 [Note] WSREP: forgetting 0a520ba7 (tcp://192.168.[censor]:4567)
181009 18:35:18 [Note] WSREP: deleting entry tcp://192.168.[censor]:4567
181009 18:35:18 [Note] WSREP: (b1d2aacb, 'tcp://0.0.0.0:4567') turning message relay requesting off
181009 18:35:18 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
181009 18:35:18 [Note] WSREP: STATE_EXCHANGE: sent state UUID: a226ba90-cba6-11e8-af4f-3751d36b7f83
181009 18:35:18 [Note] WSREP: STATE EXCHANGE: sent state msg: a226ba90-cba6-11e8-af4f-3751d36b7f83
181009 18:35:18 [Note] WSREP: STATE EXCHANGE: got state msg: a226ba90-cba6-11e8-af4f-3751d36b7f83 from 0 (CLUSTER002)
181009 18:35:18 [Note] WSREP: STATE EXCHANGE: got state msg: a226ba90-cba6-11e8-af4f-3751d36b7f83 from 1 (CLUSTER003)
181009 18:35:18 [Note] WSREP: Quorum results:
    version    = 4,
    component  = PRIMARY,
    conf_id    = 126,
    members    = 2/2 (joined/total),
    act_id     = 781947656,
    last_appl. = 781947602,
    protocols  = 0/7/3 (gcs/repl/appl),
    group UUID = efec8dfa-4c2b-11e7-8f56-a7bf24f4c9a9
181009 18:35:18 [Note] WSREP: Flow-control interval: [23, 23]
181009 18:35:18 [Note] WSREP: New cluster view: global state: efec8dfa-4c2b-11e7-8f56-a7bf24f4c9a9:781947656, view# 127: Primary, number of nodes: 2, my index: 0, protocol version 3
181009 18:35:18 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
181009 18:35:18 [Note] WSREP: REPL Protocols: 7 (3, 2)
181009 18:35:18 [Note] WSREP: Assign initial position for certification: 781947656, protocol version: 3
181009 18:35:18 [Note] WSREP: Service thread queue flushed.
181009 18:35:20 [Note] WSREP:  cleaning up 0a520ba7 (tcp://192.168.[censor]:4567)
181009 18:35:22 [Note] WSREP: (b1d2aacb, 'tcp://0.0.0.0:4567') connection established to 0a520ba7 tcp://192.168.[censor]:4567
181009 18:35:22 [Note] WSREP: (b1d2aacb, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
181009 18:35:25 [Note] WSREP: (b1d2aacb, 'tcp://0.0.0.0:4567') turning message relay requesting off
181009 18:35:27 [Note] WSREP: declaring 0a520ba7 at tcp://192.168.[censor]:4567 stable
181009 18:35:27 [Note] WSREP: declaring e0d6a63b at tcp://192.168.[censor]:4567 stable
181009 18:35:27 [Note] WSREP: Node b1d2aacb state prim
181009 18:35:27 [Note] WSREP: view(view_id(PRIM,0a520ba7,149) memb {
    0a520ba7,0
    b1d2aacb,0
    e0d6a63b,0
} joined {
} left {
} partitioned {
})
181009 18:35:27 [Note] WSREP: save pc into disk
181009 18:35:27 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 3
181009 18:35:27 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
181009 18:35:27 [Note] WSREP: STATE EXCHANGE: sent state msg: a7a0c1ba-cba6-11e8-b2c4-7bc932a69143
181009 18:35:27 [Note] WSREP: STATE EXCHANGE: got state msg: a7a0c1ba-cba6-11e8-b2c4-7bc932a69143 from 0 (CLUSTER004)
181009 18:35:27 [Note] WSREP: STATE EXCHANGE: got state msg: a7a0c1ba-cba6-11e8-b2c4-7bc932a69143 from 2 (CLUSTER003)
181009 18:35:27 [Note] WSREP: STATE EXCHANGE: got state msg: a7a0c1ba-cba6-11e8-b2c4-7bc932a69143 from 1 (CLUSTER002)
181009 18:35:27 [Note] WSREP: Quorum results:
    version    = 4,
    component  = PRIMARY,
    conf_id    = 127,
    members    = 2/3 (joined/total),
    act_id     = 781948414,
    last_appl. = 781948375,
    protocols  = 0/7/3 (gcs/repl/appl),
    group UUID = efec8dfa-4c2b-11e7-8f56-a7bf24f4c9a9
181009 18:35:27 [Note] WSREP: Flow-control interval: [28, 28]
181009 18:35:27 [Note] WSREP: New cluster view: global state: efec8dfa-4c2b-11e7-8f56-a7bf24f4c9a9:781948414, view# 128: Primary, number of nodes: 3, my index: 1, protocol version 3
181009 18:35:27 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
181009 18:35:27 [Note] WSREP: REPL Protocols: 7 (3, 2)
181009 18:35:27 [Note] WSREP: Assign initial position for certification: 781948414, protocol version: 3
181009 18:35:27 [Note] WSREP: Service thread queue flushed.
181009 18:35:29 [Note] WSREP: Member 0.0 (CLUSTER004) requested state transfer from '*any*'. Selected 2.0 (CLUSTER003)(SYNCED) as donor.
181009 18:35:29 [Note] WSREP: 2.0 (CLUSTER003): State transfer to 0.0 (CLUSTER004) complete.
181009 18:35:29 [Note] WSREP: Member 2.0 (CLUSTER003) synced with group.
181009 18:35:29 [Note] WSREP: 0.0 (CLUSTER004): State transfer from 2.0 (CLUSTER003) complete.
181009 18:35:29 [Note] WSREP: Member 0.0 (CLUSTER004) synced with group.

What did we do:

  1. We enhanced the database monitoring and compare the data to other working environments, we found that "innodb_checkpoint_age.uncheckpointed_bytes" is high around 4MB ~ 10MB.

  2. We conduct some Traceroute monitoring, and found that sometimes, especially when WSREP is doing connection check, Ping shoots to >8000ms and even once >16000ms, which normally it should be 0.2ms.

  3. We tried to adjust the Network Adapter's rx and tx value from 256/256 to 512/512 to see if it helps. It did not.

  4. Someone on the Internet says changing MTU from 9000 to 1500 helps, and it did not, Cluster refused to start at MTU 1500.

  5. There are some slow query right before a big incident, in which all clusters are shutdown and we have to manually restart them all. Although we have no evidence or not enough experience to confirm it has anything to do with the slow query.

I'm no DB expert so this could be the best I could do, if there is something we missed please kindly reply to this post, many thanks.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.