Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-40188

SHOW [GLOBAL] STATUS hangs on a Galera rsync-SST donor until the transfer finishes when max_binlog_total_size != 0, because Binlog_disk_use contends on LOCK_log with the SST donor thread

    XMLWordPrintable

Details

    • Bug
    • Status: Open (View Workflow)
    • Major
    • Resolution: Unresolved
    • 11.4.3, 11.8.6, 12.3.2
    • None
    • Galera SST, Replication
    • None
    • MariaDB 12.3.2, Galera wsrep provider 4.25 (r5d07ad0), rsync SST method
    • Can result in hang or crash

    Description

      Description

      On a Galera cluster node acting as an rsync SST donor, every SHOW STATUS, SHOW GLOBAL STATUS and every SELECT ... FROM information_schema.GLOBAL_STATUS blocks for the entire duration of the SST (which can be hours for large datasets).
      The blocked threads sit in the stage Filling schema table and cannot be killed
      (KILL QUERY / KILL CONNECTION take effect only when the SST ends).

      This is a regression in effect: it only appears once the global variable max_binlog_total_size (introduced in 11.4) is set to a non-zero value. With max_binlog_total_size = 0 (the default) the same SST runs without any hang.

      The condition is independent of binlog size or purging — it reproduces with only a few MB of binary logs and a multi-GB limit. It is purely a mutex contention, not a data-volume problem.

      Root cause (two interacting sides):

      (A) HOLDER — the SST donor thread holds the binlog mutex LOG::LOCK_log over the whole transfer, by design, to keep RESET MASTER / RESET LOGS from running during the file snapshot. This is long-standing, intentional behaviour and harmless on its own.

      (B) VICTIM — when max_binlog_total_size != 0, the status variable Binlog_disk_use is materialised on every SHOW [GLOBAL] STATUS via get_binlog_space_total(), which acquires the very same LOCK_log to read the current write position.

      (B) therefore blocks behind (A) for the full SST window.

      This is destructive in production because monitoring agents (e.g. MaxScale galeramon, mysqld_exporter / Prometheus) poll SHOW [GLOBAL] STATUS every few seconds. Each poll opens a connection that hangs until the SST ends; the hung connections accumulate up to max_connections, after which the node cannot rejoin the cluster once the transfer completes. At SST end all of them are released at once, producing a burst of "Aborted connection ... (Got an error reading communication packets)".

      How to reproduce

      Minimal, no monitoring stack required. Two-node Galera cluster with wsrep_sst_method = rsync and a binary log enabled on the donor.

      1. On the donor, enable binlog and set a non-zero total-size limit:

      -- my.cnf: log_bin=ON, wsrep_sst_method=rsync
      SET GLOBAL max_binlog_total_size = 1073741824;   -- 1 GiB; any non-zero value
      

      2. Trigger an rsync SST from this donor to a joiner. Easiest way to get a long, observable window: join an empty node, OR pause the rsync to widen the window. (For a deterministic pause point, a debug build can stop at the donor-state DBUG_SYNC; on a release build, simply SST a large enough dataset that the transfer lasts long enough to query.)

      3. While the SST is in progress, from a separate connection on the donor:

      SHOW GLOBAL STATUS;                 -- hangs until the SST finishes
      SHOW STATUS LIKE 'Binlog_disk_use'; -- hangs as well
      SELECT 1;                           -- returns immediately (does not take LOCK_log)
      

      4. Confirm where it is blocked (no debugger needed):

      SELECT t.PROCESSLIST_ID, esc.EVENT_NAME AS stage, ewc.EVENT_NAME AS waiting_on
        FROM performance_schema.threads t
        JOIN performance_schema.events_stages_current esc USING (THREAD_ID)
        JOIN performance_schema.events_waits_current  ewc USING (THREAD_ID)
      WHERE esc.EVENT_NAME = 'stage/sql/Filling schema table';
      -- waiting_on => wait/synch/mutex/sql/LOG::LOCK_log
       
      -- Who holds it?
      SELECT NAME, LOCKED_BY_THREAD_ID
        FROM performance_schema.mutex_instances
      WHERE NAME = 'wait/synch/mutex/sql/LOG::LOCK_log'
         AND LOCKED_BY_THREAD_ID IS NOT NULL;
      -- => the SST donor thread
      

      5. Negative control — proves the trigger:

      SET GLOBAL max_binlog_total_size = 0;   -- back to default
      

      Repeat the SST: SHOW GLOBAL STATUS now returns immediately throughout
      the whole transfer. Toggle is fully reproducible.

      Suspected source (verified against the mariadb-12.3.2 source tree)

      We are confident about the exact code locations; line numbers below are from tag mariadb-12.3.2.

      HOLDER — donor holds LOCK_log across the transfer:

      // sql/wsrep_sst.cc — sst_donor_thread(), after sst_flush_tables() succeeds:
      2156:   locked= true;
      2157:   /*
      2158:     Lets also keep statements that modify binary logs (like RESET LOGS,
      2159:     RESET MASTER) from proceeding until the files have been transferred
      2160:     to the joiner node.
      2161:   */
      2162:   if (mysql_bin_log.is_open())
      2163:     mysql_mutex_lock(mysql_bin_log.get_log_lock());   // acquire &LOCK_log
      2165:   WSREP_INFO("Donor state reached");
      2179:   goto wait_signal;                                   // wait for rsync transfer
      ...    // released only on the "continue" signal == SST end:
      2188:   if (mysql_bin_log.is_open())
      2189:     mysql_mutex_unlock(mysql_bin_log.get_log_lock());
      

      get_log_lock() returns &LOCK_log (sql/log.h:346).

      VICTIM — Binlog_disk_use takes the same LOCK_log, but only when the limit is set:

      // sql/mysqld.cc:7926 — status variable, always materialised (SHOW_SIMPLE_FUNC):
      {"Binlog_disk_use", (char*) &show_binlog_space_total, SHOW_SIMPLE_FUNC},
       
      // sql/mysqld.cc:7811 — show_binlog_space_total():
      7817:   if (opt_bin_log && binlog_space_limit)                  // limit != 0
      7818:     *(ulonglong*) buff= mysql_bin_log.get_binlog_space_total();
      7819:   else
      7820:     *(ulonglong*) buff= 0;                                 // no lock taken
      

      binlog_space_limit is exactly max_binlog_total_size
      (sql/sys_vars.cc:1350 -> internal_binlog_space_limit, copied to
      binlog_space_limit at sql/mysqld.cc:5876).

      // sql/log.cc:6733 — get_binlog_space_total():
      6736:   mysql_mutex_lock(&LOCK_log);          // <-- blocks behind the SST donor
      6738:   used_space= my_b_tell(&log_file);     // just reads the current write pos
      6739:   mysql_mutex_lock(&LOCK_index);
      6740:   mysql_mutex_unlock(&LOCK_log);
      

      The SHOW STATUS worker therefore is the victim, not the cause: it waits on a plain mutex held by another thread (the donor), and a plain mutex wait has no thd->killed checkpoint — which is exactly why the connections are not killable until the SST releases LOCK_log.

      What it is NOT (each ruled out by source and/or performance_schema):

      • Not the Galera provider — wsrep->stats_get() takes only transient locks.
      • Not InnoDB — InnoDB is idle during the wait; a plain SELECT runs fine.
      • Not binlog size / purging — reproduces far below the limit.

      Suggested fix

      Cleanest fix is on the victim side — Binlog_disk_use should not block
      SHOW STATUS behind LOCK_log just to read the current write position:

      • take LOCK_log only via try-lock and otherwise return the last known value (a monitoring counter does not need to be exact), or
      • read the current write position from an atomic binlog_end_pos instead of under LOCK_log, or
      • compute Binlog_disk_use from the tracked binlog_space_total under LOCK_index only.

      Optionally, add a thd->killed checkpoint so such waits become killable
      (cf. MDEV-12344 class of issues).

      Workaround

      Set max_binlog_total_size = 0 on every node that can become an rsync SST donor. Verified to remove the hang completely.
      Trade-off: the total-binlog-size cap is gone — compensate with binlog_expire_logs_seconds and adequate disk.

      Related issues

      • MDEV-11312 — Galera node hangs on SHOW GLOBAL STATUS (donor pile-up,
        "Too many connections"): same symptom family.
      • MDEV-12344 — crash when killing a hung SHOW STATUS: same
        non-killability / mutex-wait class.

      Attachments

        Issue Links

          Activity

            People

              seppo Seppo Jaakola
              Wünschel Oliver Wünschel
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.