Uploaded image for project: 'Percona XtraDB Cluster'
  1. Percona XtraDB Cluster
  2. PXC-3593

Node takes a long time to complete IST

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: In Review
    • Priority: Medium
    • Resolution: Unresolved
    • Affects Version/s: 8.0.22-13.1
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      A node on a cluster under load, left of a brief second will take a few minutes to rejoin.

      The same process takes only seconds on 5.7:

       

      8.0 rejoining node log:

      2021-02-18T13:54:04.913685Z 0 [Note] [MY-000000] [Galera] Receiving IST...100.0% (2210/2210 events) complete.
      2021-02-18T13:54:04.913692Z 1 [Note] [MY-000000] [Galera] ================================================
      View:
        id: 8ca69eee-6c68-11eb-960b-5f0e4787d15f:8483639
        status: primary
        protocol_version: 4
        capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
        final: no
        own_index: 2
        members(3):
      	0: 4a7dc3be-71f0-11eb-90da-036665d9e46b, node3
      	1: a7b82107-71ef-11eb-bf3b-ab588596f780, node1
      	2: b34b18e6-71ef-11eb-9839-1bd9683c1ddb, node2
      =================================================
      2021-02-18T13:54:04.913725Z 1 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
      2021-02-18T13:54:04.916193Z 1 [Note] [MY-000000] [Galera] Draining apply monitors after IST up to 8483639
      2021-02-18T13:54:04.916518Z 1 [Note] [MY-000000] [Galera] IST received: 8ca69eee-6c68-11eb-960b-5f0e4787d15f:8483639
      2021-02-18T13:54:04.916799Z 1 [Note] [MY-000000] [Galera] Recording CC from sst: 8483639
      2021-02-18T13:54:04.916819Z 1 [Note] [MY-000000] [Galera] Lowest cert index boundary for CC from sst: 8483107
      2021-02-18T13:54:04.916844Z 1 [Note] [MY-000000] [Galera] Min available from gcache for CC from sst: 8479245
      2021-02-18T13:54:04.917195Z 0 [Note] [MY-000000] [Galera] 2.0 (node2): State transfer from 1.0 (node1) complete.
      2021-02-18T13:54:04.917246Z 0 [Note] [MY-000000] [Galera] SST leaving flow control
      2021-02-18T13:54:04.917266Z 0 [Note] [MY-000000] [Galera] Shifting JOINER -> JOINED (TO: 8486298)
      2021-02-18T13:54:05.942715Z 0 [Note] [MY-000000] [Galera] (b34b18e6-9839, 'tcp://0.0.0.0:4567') turning message relay requesting off
      2021-02-18T14:05:10.864588Z 0 [Note] [MY-000000] [Galera] Member 2.0 (node2) synced with group.
      2021-02-18T14:05:10.864642Z 0 [Note] [MY-000000] [Galera] Shifting JOINED -> SYNCED (TO: 8799531)

      Node took from 2021-02-18T13:54:04 until 2021-02-18T14:05:10 to process 2210 events and rejoin (˜11 minutes).

      5.7:

      2021-02-18T14:19:15.002005Z 0 [Note] WSREP: Receiving IST...  0.0% (    0/42513 events) complete.
      2021-02-18T14:19:16.691167Z 0 [Note] WSREP: (1b264956, 'tcp://0.0.0.0:4567') turning message relay requesting off
      2021-02-18T14:19:20.568502Z 0 [Note] WSREP: Receiving IST...100.0% (42513/42513 events) complete.
      2021-02-18T14:19:20.568639Z 1 [Note] WSREP: IST received: d1688f99-71f1-11eb-a220-ce106fe972f8:620622
      2021-02-18T14:19:20.569002Z 0 [Note] WSREP: 1.0 (node2): State transfer from 2.0 (node1) complete.
      2021-02-18T14:19:20.569023Z 0 [Note] WSREP: SST leaving flow control
      2021-02-18T14:19:20.569029Z 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 666525)
      2021-02-18T14:19:51.197358Z 0 [Note] WSREP: Member 1.0 (node2) synced with group.
      2021-02-18T14:19:51.197404Z 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 900467)
      2021-02-18T14:19:51.241377Z 1 [Note] WSREP: Synchronized with group, ready for connections
      2021-02-18T14:19:51.241389Z 1 [Note] WSREP: Setting wsrep_ready to true
      2021-02-18T14:19:51.241393Z 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 

       Node took ~36 seconds to rejoin and process 42K events

      How to reproduce:

      • Start sysbench on node1:
        WRITE_IP=10.78.159.22
        
        sysbench --db-driver=mysql --db-ps-mode=disable --mysql-host=${WRITE_IP} --mysql-user=sysbench --mysql-password=sysbench --table_size=10000 --tables=8 /usr/share/sysbench/oltp_read_write.lua prepare
        
        sysbench --db-driver=mysql --db-ps-mode=disable --mysql-host=${WRITE_IP} --mysql-user=sysbench --mysql-password=sysbench --table_size=10000 --tables=8 --threads=8 --time=0 --report-interval=1 /usr/share/sysbench/oltp_write_only.lua run
      • Briefly remove node2 from the cluster (as soon as the other nodes recalculate quorum, remove network delay):
      #add delay to split network
      tc qdisc add dev eth0 root netem delay 60000ms loss 99%; 
      
      #remove delay for node rejoin the cluster
      tc qdisc del dev eth0 root netem; 

      At this point IST will be triggered and the node will take a long time to process a few seconds of missing events.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marcelo.altmann Marcelo Altmann
              Reporter:
              marcelo.altmann Marcelo Altmann
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Dates

                Created:
                Updated:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - Not Specified
                  Not Specified
                  Logged:
                  Time Spent - 2 days, 7 hours
                  2d 7h

                    Smart Checklist