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

Wrong locking order of LOCK_log and LOCK_global_system_variables, potential deadlock of server

Details

    Description

      Looks related to MDEV-29744, though is substantially different (different testcase, different versions affected, looks to be a new regression and the mutex order is reversed)

      # mysqld options required for replay: --log_bin
      SET GLOBAL binlog_checksum=0;
      INSTALL SONAME 'ha_spider';
      RESET MASTER;
      

      Leads to:

      CS 11.7.0 4016c905cbabea7f29ed282dc2125254c7c0d419 (Debug)

      Version: '11.7.0-MariaDB-debug-log'  socket: '/test/MD141024-mariadb-11.7.0-linux-x86_64-dbg/socket.sock'  port: 12847  MariaDB Server
      safe_mutex: Found wrong usage of mutex 'LOCK_log' and 'LOCK_global_system_variables'
      Mutex currently locked (in reverse order):
      LOCK_global_system_variables      /test/11.7_dbg/sql/sql_plugin.cc  line 3132
      LOCK_log                          /test/11.7_dbg/sql/log.cc  line 4449
      

      MTR Testcase:

      --source include/have_log_bin.inc
      SET GLOBAL binlog_checksum=0;
      INSTALL SONAME 'ha_spider';
      RESET MASTER;
      

      Found present in 11.4-11.7, though may have been introduced in 11.3. Not present in 11.2.

      Attachments

        Issue Links

          Activity

            ycp Yuchen Pei added a comment - - edited

            the testcase reproduces at the patch for MDEV-25611 (35c732cdde6a637514ec29abcb752446e5a24295), and passes at its parent commit.

            More specifically caused by this addition

            modified   sql/log.cc
            @@ -4435,6 +4435,9 @@ bool MYSQL_BIN_LOG::reset_logs(THD *thd, bool create_new_log,
                 mark_xids_active(current_binlog_id, 1);
                 do_checkpoint_request(current_binlog_id);
             
            +    /* Flush all engine logs to force checkpoint responses to come through. */
            +    ha_flush_logs();
            +
                 /* Now wait for all checkpoint requests and pending unlog() to complete. */
                 mysql_mutex_lock(&LOCK_xid_list);
                 for (;;)
            

            ycp Yuchen Pei added a comment - - edited the testcase reproduces at the patch for MDEV-25611 (35c732cdde6a637514ec29abcb752446e5a24295), and passes at its parent commit. More specifically caused by this addition modified sql/log.cc @@ -4435,6 +4435,9 @@ bool MYSQL_BIN_LOG::reset_logs(THD *thd, bool create_new_log, mark_xids_active(current_binlog_id, 1); do_checkpoint_request(current_binlog_id); + /* Flush all engine logs to force checkpoint responses to come through. */ + ha_flush_logs(); + /* Now wait for all checkpoint requests and pending unlog() to complete. */ mysql_mutex_lock(&LOCK_xid_list); for (;;)

            Hm. I need to investigate a bit to understand if it is ok for RESET MASTER to call handlerton flush_logs() while holding LOCK_log...

            knielsen Kristian Nielsen added a comment - Hm. I need to investigate a bit to understand if it is ok for RESET MASTER to call handlerton flush_logs() while holding LOCK_log...

            This patch seems to fix the assertion:

            diff --git a/storage/spider/spd_table.cc b/storage/spider/spd_table.cc
            index 8391b5451a5..dbd5f2f7e41 100644
            --- a/storage/spider/spd_table.cc
            +++ b/storage/spider/spd_table.cc
            @@ -6150,7 +6150,7 @@ bool spider_flush_logs(
                 DBUG_RETURN(TRUE);
               }
               if (
            -    spider_param_use_flash_logs(trx->thd) &&
            +    spider_param_use_flash_logs(nullptr) &&
                 (
                   !trx->trx_consistent_snapshot ||
                   !spider_param_use_all_conns_snapshot(trx->thd) ||
            

            The rationale for this is that flush_logs() is a global operation, it is not really related to any particular THD or transaction - presumably that is why flush_logs() does not pass THD. It looks a bit like this can actually start a transaction, which is unexpected for RESET MASTER. Possibly Spider could also avoid passing current_thd to spider_get_trx() in spider_flush_logs(), again because flush_logs() is not associated with any specific transaction, but I am not familiar with Spider code to really say.

            Still, Spider is somewhat a victim here of the patch for MDEV-25611, as Yuchen Pei noted. The problem is rooted in the mutex LOCK_global_system_variables, which is often problematic. Some system variables take LOCK_log while holding LOCK_global_system_variables, which is opposite of what Spider does and causes the warning. Probably Spider does the right thing; in fact, there are already many other system variables that temporarily release LOCK_global_system_variables while invoking code that locks LOCK_log or other locks. The following patch adds this temporary unlock to a few sysvar functions that lack it, and also fixes the lock order issue without changing Spider code:

            diff --git a/sql/log.cc b/sql/log.cc
            index d5b0f0ba95d..5bd0e319f5c 100644
            --- a/sql/log.cc
            +++ b/sql/log.cc
            @@ -3565,6 +3565,12 @@ void MYSQL_BIN_LOG::init_pthread_objects()
                               &COND_binlog_background_thread, 0);
               mysql_cond_init(key_BINLOG_COND_binlog_background_thread_end,
                               &COND_binlog_background_thread_end, 0);
            +
            +  /* Fix correct mutex order to catch violations quicker (MDEV-35197). */
            +  mysql_mutex_lock(&LOCK_log);
            +  mysql_mutex_lock(&LOCK_global_system_variables);
            +  mysql_mutex_unlock(&LOCK_global_system_variables);
            +  mysql_mutex_unlock(&LOCK_log);
             }
             
             
            @@ -12544,6 +12550,7 @@ binlog_checksum_update(MYSQL_THD thd, struct st_mysql_sys_var *var,
               bool check_purge= false;
               ulong UNINIT_VAR(prev_binlog_id);
             
            +  mysql_mutex_unlock(&LOCK_global_system_variables);
               mysql_mutex_lock(mysql_bin_log.get_log_lock());
               if(mysql_bin_log.is_open())
               {
            @@ -12562,6 +12569,7 @@ binlog_checksum_update(MYSQL_THD thd, struct st_mysql_sys_var *var,
               mysql_mutex_unlock(mysql_bin_log.get_log_lock());
               if (check_purge)
                 mysql_bin_log.checkpoint_and_purge(prev_binlog_id);
            +  mysql_mutex_lock(&LOCK_global_system_variables);
             }
             
             
            diff --git a/sql/sys_vars.cc b/sql/sys_vars.cc
            index 9fd51fbe4a0..ed9a9747524 100644
            --- a/sql/sys_vars.cc
            +++ b/sql/sys_vars.cc
            @@ -1254,6 +1254,7 @@ static bool update_binlog_space_limit(sys_var *, THD *,
                                                   enum_var_type type)
             {
             #ifdef HAVE_REPLICATION
            +  mysql_mutex_unlock(&LOCK_global_system_variables);
               /* Refresh summary of binlog sizes */
               mysql_bin_log.lock_index();
               binlog_space_limit= internal_binlog_space_limit;
            @@ -1268,9 +1269,10 @@ static bool update_binlog_space_limit(sys_var *, THD *,
                 sending_new_binlog_file++;
                 mysql_bin_log.unlock_index();
                 mysql_bin_log.purge(1);
            -    return 0;
               }
            -  mysql_bin_log.unlock_index();
            +  else
            +    mysql_bin_log.unlock_index();
            +  mysql_mutex_lock(&LOCK_global_system_variables);
             #endif
               return 0;
             }
            @@ -1790,7 +1792,9 @@ Sys_max_binlog_stmt_cache_size(
             
             static bool fix_max_binlog_size(sys_var *self, THD *thd, enum_var_type type)
             {
            +  mysql_mutex_unlock(&LOCK_global_system_variables);
               mysql_bin_log.set_max_size(max_binlog_size);
            +  mysql_mutex_lock(&LOCK_global_system_variables);
               return false;
             }
             static Sys_var_on_access_global<Sys_var_ulong,
            

            Possibly both patches are correct and should be pushed. I am not so familiar with Spider, so would want to hear Yuchen Pei's opinion on the first patch. I think the second patch is probably correct and could fix other similar problems that are just not known yet.

            ycp, any comments?

            knielsen Kristian Nielsen added a comment - This patch seems to fix the assertion: diff --git a/storage/spider/spd_table.cc b/storage/spider/spd_table.cc index 8391b5451a5..dbd5f2f7e41 100644 --- a/storage/spider/spd_table.cc +++ b/storage/spider/spd_table.cc @@ -6150,7 +6150,7 @@ bool spider_flush_logs( DBUG_RETURN(TRUE); } if ( - spider_param_use_flash_logs(trx->thd) && + spider_param_use_flash_logs(nullptr) && ( !trx->trx_consistent_snapshot || !spider_param_use_all_conns_snapshot(trx->thd) || The rationale for this is that flush_logs() is a global operation, it is not really related to any particular THD or transaction - presumably that is why flush_logs() does not pass THD. It looks a bit like this can actually start a transaction, which is unexpected for RESET MASTER. Possibly Spider could also avoid passing current_thd to spider_get_trx() in spider_flush_logs(), again because flush_logs() is not associated with any specific transaction, but I am not familiar with Spider code to really say. Still, Spider is somewhat a victim here of the patch for MDEV-25611 , as Yuchen Pei noted. The problem is rooted in the mutex LOCK_global_system_variables, which is often problematic. Some system variables take LOCK_log while holding LOCK_global_system_variables, which is opposite of what Spider does and causes the warning. Probably Spider does the right thing; in fact, there are already many other system variables that temporarily release LOCK_global_system_variables while invoking code that locks LOCK_log or other locks. The following patch adds this temporary unlock to a few sysvar functions that lack it, and also fixes the lock order issue without changing Spider code: diff --git a/sql/log.cc b/sql/log.cc index d5b0f0ba95d..5bd0e319f5c 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -3565,6 +3565,12 @@ void MYSQL_BIN_LOG::init_pthread_objects() &COND_binlog_background_thread, 0); mysql_cond_init(key_BINLOG_COND_binlog_background_thread_end, &COND_binlog_background_thread_end, 0); + + /* Fix correct mutex order to catch violations quicker (MDEV-35197). */ + mysql_mutex_lock(&LOCK_log); + mysql_mutex_lock(&LOCK_global_system_variables); + mysql_mutex_unlock(&LOCK_global_system_variables); + mysql_mutex_unlock(&LOCK_log); } @@ -12544,6 +12550,7 @@ binlog_checksum_update(MYSQL_THD thd, struct st_mysql_sys_var *var, bool check_purge= false; ulong UNINIT_VAR(prev_binlog_id); + mysql_mutex_unlock(&LOCK_global_system_variables); mysql_mutex_lock(mysql_bin_log.get_log_lock()); if(mysql_bin_log.is_open()) { @@ -12562,6 +12569,7 @@ binlog_checksum_update(MYSQL_THD thd, struct st_mysql_sys_var *var, mysql_mutex_unlock(mysql_bin_log.get_log_lock()); if (check_purge) mysql_bin_log.checkpoint_and_purge(prev_binlog_id); + mysql_mutex_lock(&LOCK_global_system_variables); } diff --git a/sql/sys_vars.cc b/sql/sys_vars.cc index 9fd51fbe4a0..ed9a9747524 100644 --- a/sql/sys_vars.cc +++ b/sql/sys_vars.cc @@ -1254,6 +1254,7 @@ static bool update_binlog_space_limit(sys_var *, THD *, enum_var_type type) { #ifdef HAVE_REPLICATION + mysql_mutex_unlock(&LOCK_global_system_variables); /* Refresh summary of binlog sizes */ mysql_bin_log.lock_index(); binlog_space_limit= internal_binlog_space_limit; @@ -1268,9 +1269,10 @@ static bool update_binlog_space_limit(sys_var *, THD *, sending_new_binlog_file++; mysql_bin_log.unlock_index(); mysql_bin_log.purge(1); - return 0; } - mysql_bin_log.unlock_index(); + else + mysql_bin_log.unlock_index(); + mysql_mutex_lock(&LOCK_global_system_variables); #endif return 0; } @@ -1790,7 +1792,9 @@ Sys_max_binlog_stmt_cache_size( static bool fix_max_binlog_size(sys_var *self, THD *thd, enum_var_type type) { + mysql_mutex_unlock(&LOCK_global_system_variables); mysql_bin_log.set_max_size(max_binlog_size); + mysql_mutex_lock(&LOCK_global_system_variables); return false; } static Sys_var_on_access_global<Sys_var_ulong, Possibly both patches are correct and should be pushed. I am not so familiar with Spider, so would want to hear Yuchen Pei's opinion on the first patch. I think the second patch is probably correct and could fix other similar problems that are just not known yet. ycp , any comments?
            ycp Yuchen Pei added a comment - - edited

            Thanks for the analysis and the proposal, knielsen.

            The first patch is basically changing the spider_use_flash_logs to a global var. I am not sure if it makes sense. The meaning of this user variable is whether to push down flush logs to the data node. I can imagine different local sessions may have different preferences when it comes to whether flush logs is executed remotely, and this has nothing to do with whether the flush logs is a session or global operation locally.

            Another issue is that spider_use_flash_logs is not the only session variable in use here. Just below the offending line, there are also calls to spider_param_use_all_conns_snapshot() and spider_param_use_snapshot_with_flush_tables(), as well as other spider_param_...() calls in spider_open_all_tables(), so we have to understand the use of these variables and fix them as well if we follow this idea, provided that it makes sense to make them global or remove them.

            Since the second patch fixes the issue without applying the first patch, shall we proceed with the idea in the second patch? If so, I suggest that we either re-assign this issue to you or create a new issue assigned to you and continue there with the idea of the second patch.

            ycp Yuchen Pei added a comment - - edited Thanks for the analysis and the proposal, knielsen . The first patch is basically changing the spider_use_flash_logs to a global var. I am not sure if it makes sense. The meaning of this user variable is whether to push down flush logs to the data node. I can imagine different local sessions may have different preferences when it comes to whether flush logs is executed remotely, and this has nothing to do with whether the flush logs is a session or global operation locally. Another issue is that spider_use_flash_logs is not the only session variable in use here. Just below the offending line, there are also calls to spider_param_use_all_conns_snapshot() and spider_param_use_snapshot_with_flush_tables(), as well as other spider_param_...() calls in spider_open_all_tables(), so we have to understand the use of these variables and fix them as well if we follow this idea, provided that it makes sense to make them global or remove them. Since the second patch fixes the issue without applying the first patch, shall we proceed with the idea in the second patch? If so, I suggest that we either re-assign this issue to you or create a new issue assigned to you and continue there with the idea of the second patch.

            Thanks for your comments, ycp.

            Yes, I think it's fine to proceed with the second patch only, that should fix this problem. The fact that this problem shows up with Spider is mostly accidental and not really caused by Spider doing anything wrong.

            For the first patch, I just happened to notice the spider_flush_logs() code and thought it looked odd that it uses current_thd and transaction associated with THD, so I wanted to mention it. But I don't see any specific problem with it, it is up to you.

            So as you suggested, let me take over this issue and I will get a review for the second patch to fix this problem without requiring Spider changes.

            Thanks!

            - Kristian.

            knielsen Kristian Nielsen added a comment - Thanks for your comments, ycp . Yes, I think it's fine to proceed with the second patch only, that should fix this problem. The fact that this problem shows up with Spider is mostly accidental and not really caused by Spider doing anything wrong. For the first patch, I just happened to notice the spider_flush_logs() code and thought it looked odd that it uses current_thd and transaction associated with THD, so I wanted to mention it. But I don't see any specific problem with it, it is up to you. So as you suggested, let me take over this issue and I will get a review for the second patch to fix this problem without requiring Spider changes. Thanks! - Kristian.

            The "patch 2" also fixes all the failures in MDEV-29744. So as I suspected, the locking order is wrong in the system variables, and this problem is not specific to Spider.
            I will close this bug as a duplicate of MDEV-29744, and propose the "patch 2" as a fix for that one.

            knielsen Kristian Nielsen added a comment - The "patch 2" also fixes all the failures in MDEV-29744 . So as I suspected, the locking order is wrong in the system variables, and this problem is not specific to Spider. I will close this bug as a duplicate of MDEV-29744 , and propose the "patch 2" as a fix for that one.
            ycp Yuchen Pei added a comment -

            Thanks for the prompt response and resolution, knielsen.

            ycp Yuchen Pei added a comment - Thanks for the prompt response and resolution, knielsen .

            People

              knielsen Kristian Nielsen
              Roel Roel Van de Paar
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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