Bug#32442772 LOG_STATUS HAS WRONG BINARY_LOG_POSITION OF GTID_EXECUTED

Description:
------------
When the server is under heavy write operation, binary_log_position
of gtid_executed shown in log_status doesn't match with the position
of that GTID events shown in the binary log file.

Analysis:
---------
A binlog commit has the following stages:
1. Flush  – Protected by the LOCK_log.
2. Sync   – At this stage, LOCK_log is released, and LOCK_sync is
            acquired.
3. Commit – Here, LOCK_sync is released, and LOCK_commit is acquired.
            During this stage, global_sid_lock is also acquired,
            and gtid_executed is updated.

When querying the log_status table, LOCK_log is acquired for the
binlog at Log_resource_binlog_wrapper::lock, and global_sid_lock is
acquired for gtid_executed at Log_resource_gtid_state_wrapper::lock.

The issue arises when a query to the log_status table is executed
after stage 1 of the binlog commit. At this point, LOCK_log has
already been released, the binlog file and position are updated, and
Log_resource_binlog_wrapper::lock proceeds. However, while the binlog
commit is still processing stage 2,
Log_resource_gtid_state_wrapper::lock is invoked and acquires
global_sid_lock. At this point, stage 3 of the binlog commit is
unable to update gtid_executed, leading to a mismatch between the
binlog position(the new values) and gtid_executed(old value) in the
log_status query.

Fix:
----
Increase the scope of the lock on the log_status table to also ensure
that the transactions that entered in the binlog commit pipeline are
completed. This adjustment will ensure that the query to the
log_status table waits until gtid_executed has been fully updated,
thereby guaranteeing consistency with the binlog position.


Change-Id: Iab0513821a0e1ffcc8a522b61447b0d9193aafe8

Author: Justin Jose

mysql-test/suite/binlog_gtid/r/binlog_gtid_log_status_with_ongoing_bgc.result

@@ -0,0 +1,26 @@
+#
+# 1. Initial setup
+RESET MASTER;
+CREATE TABLE t1(c1 INT);
+INSERT INTO t1 VALUES(1);
+INSERT INTO t1 VALUES(2);
+FLUSH BINARY LOGS;
+#
+# 2. Execute an INSERT query and pause after it acquires commit_lock
+[START] INSERT INTO t1 VALUES (3);
+#
+# 3. Execute a SELECT query on performance_schema.log_status and wait
+#    until it is waiting for MYSQL_BIN_LOG::prep_xids_cond
+SELECT REPLACE(LOCAL->"$.gtid_executed", '"', '') INTO @ps_log_status FROM performance_schema.log_status;
+#
+# 4. Resume the INSERT query
+[END] INSERT INTO t1 VALUES (3);
+#
+# 5. Let the SELECT query complete
+#
+# 6. Verify that the correct GTID set is received from
+#    performance_schema.log_status
+include/assert.inc [Gtid_executed is updated with GTID 4]
+#
+# 7. Cleanup
+DROP TABLE t1;

mysql-test/suite/binlog_gtid/t/binlog_gtid_log_status_with_ongoing_bgc.test

@@ -0,0 +1,84 @@
+##############################################################################
+# ==== Purpose ====
+# The purpose of this test is to verify that, at any given time,
+# the gtid_executed value shown in log_status table matches the correct
+# executed GTIDs.
+#
+# ==== Requirement ====
+# At any given time, the gtid_executed value shown in log_status must match
+# the correct executed GTIDs.
+#
+# ==== Implementation ====
+# 1. Initial setup
+# 2. Execute an INSERT query and pause after it acquires commit_lock
+# 3. Execute a SELECT query on performance_schema.log_status and verify
+#    that it is waiting on MYSQL_BIN_LOG::prep_xids_cond
+# 4. Resume the INSERT query
+# 5. Let the SELECT query complete
+# 6. Verify that the correct GTID set is received from
+#    performance_schema.log_status
+# 7. Clean up
+#
+# ==== References ====
+# Bug#32442772 LOG_STATUS HAS WRONG BINARY_LOG_POSITION OF GTID_EXECUTED
+###############################################################################
+
+# This test case is binary log format agnostic
+--source include/have_binlog_format_row.inc
+
+--source include/have_debug.inc
+--source include/have_debug_sync.inc
+
+--echo #
+--echo # 1. Initial setup
+--connect (con1,localhost,root,,)
+--connect (con2,localhost,root,,)
+
+--connection default
+RESET MASTER;
+--let $server_uuid= `SELECT @@GLOBAL.SERVER_UUID`
+CREATE TABLE t1(c1 INT);
+INSERT INTO t1 VALUES(1);
+INSERT INTO t1 VALUES(2);
+FLUSH BINARY LOGS;
+
+--echo #
+--echo # 2. Execute an INSERT query and pause after it acquires commit_lock
+--let $auxiliary_connection = default
+--let $statement_connection = con1
+--let $sync_point = update_gtid_state_before_global_sid_lock
+--let $statement = INSERT INTO t1 VALUES (3)
+--source include/execute_to_sync_point.inc
+
+--echo #
+--echo # 3. Execute a SELECT query on performance_schema.log_status and wait
+--echo #    until it is waiting for MYSQL_BIN_LOG::prep_xids_cond
+--connection con2
+--send SELECT REPLACE(LOCAL->"$.gtid_executed", '"', '') INTO @ps_log_status FROM performance_schema.log_status
+
+--connection default
+--let $wait_condition = SELECT COUNT(*) = 1 FROM performance_schema.threads T, performance_schema.events_waits_current W WHERE T.THREAD_ID=W.THREAD_ID AND W.EVENT_NAME LIKE "%MYSQL_BIN_LOG::prep_xids_cond" AND T.PROCESSLIST_INFO LIKE "%FROM%log_status%"
+--source include/wait_condition.inc
+
+--echo #
+--echo # 4. Resume the INSERT query
+--source include/execute_from_sync_point.inc
+
+--echo #
+--echo # 5. Let the SELECT query complete
+--connection con2
+--reap
+
+--echo #
+--echo # 6. Verify that the correct GTID set is received from
+--echo #    performance_schema.log_status
+--let $assert_text= Gtid_executed is updated with GTID 4
+--let $assert_cond= "[SELECT @ps_log_status]" = "$server_uuid:1-4"
+--source include/assert.inc
+
+--echo #
+--echo # 7. Cleanup
+--connection default
+--disconnect con1
+--disconnect con2
+DROP TABLE t1;

sql/binlog.cc

@@ -6559,6 +6559,15 @@ void MYSQL_BIN_LOG::dec_prep_xids(THD *thd) {
   }
 }
 
+void MYSQL_BIN_LOG::wait_for_prep_xids() {
+  DBUG_TRACE;
+  mysql_mutex_lock(&LOCK_xids);
+  while (get_prep_xids() > 0) {
+    mysql_cond_wait(&m_prep_xids_cond, &LOCK_xids);
+  }
+  mysql_mutex_unlock(&LOCK_xids);
+}
+
 /*
   Wrappers around new_file_impl to avoid using argument
   to control locking. The argument 1) less readable 2) breaks
@@ -6621,7 +6630,6 @@ int MYSQL_BIN_LOG::new_file_impl(
     mysql_mutex_assert_owner(&LOCK_log);
   DBUG_EXECUTE_IF("semi_sync_3-way_deadlock",
                   DEBUG_SYNC(current_thd, "before_rotate_binlog"););
-  mysql_mutex_lock(&LOCK_xids);
   /*
     We need to ensure that the number of prepared XIDs are 0.
 
@@ -6630,10 +6638,7 @@ int MYSQL_BIN_LOG::new_file_impl(
     - We keep the LOCK_log to block new transactions from being
       written to the binary log.
    */
-  while (get_prep_xids() > 0) {
-    mysql_cond_wait(&m_prep_xids_cond, &LOCK_xids);
-  }
-  mysql_mutex_unlock(&LOCK_xids);
+  wait_for_prep_xids();
 
   mysql_mutex_lock(&LOCK_index);
 

sql/binlog.h

@@ -269,6 +269,11 @@ class MYSQL_BIN_LOG : public TC_LOG {
   inline uint get_sync_period() { return *sync_period_ptr; }
 
  public:
+  /**
+    Wait until the number of prepared XIDs are zero.
+   */
+  void wait_for_prep_xids();
+
   /*
     This is used to start writing to a new log file. The difference from
     new_file() is locking. new_file_without_locking() does not acquire

sql/log_resource.cc

@@ -87,7 +87,15 @@ bool Log_resource_binlog_wrapper::collect_info() {
   return error;
 }
 
-void Log_resource_gtid_state_wrapper::lock() { global_sid_lock->wrlock(); }
+void Log_resource_gtid_state_wrapper::lock() {
+  /*
+    Ensure that the number of prepared XIDs is zero to confirm the completion
+    of transactions in the BGC pipeline.
+   */
+  binlog->wait_for_prep_xids();
+
+  global_sid_lock->wrlock();
+}
 
 void Log_resource_gtid_state_wrapper::unlock() { global_sid_lock->unlock(); }
 
@@ -137,9 +145,10 @@ Log_resource *Log_resource_factory::get_wrapper(MYSQL_BIN_LOG *binlog,
 }
 
 Log_resource *Log_resource_factory::get_wrapper(Gtid_state *gtid_state,
-                                                Json_dom *json) {
+                                                Json_dom *json,
+                                                MYSQL_BIN_LOG *binlog) {
   Log_resource_gtid_state_wrapper *wrapper;
-  wrapper = new Log_resource_gtid_state_wrapper(gtid_state, json);
+  wrapper = new Log_resource_gtid_state_wrapper(gtid_state, json, binlog);
   return wrapper;
 }
 

sql/log_resource.h

@@ -176,6 +176,7 @@ class Log_resource_binlog_wrapper : public Log_resource {
 */
 class Log_resource_gtid_state_wrapper : public Log_resource {
   Gtid_state *gtid_state = nullptr;
+  MYSQL_BIN_LOG *binlog = nullptr;
 
  public:
   /**
@@ -184,11 +185,14 @@ class Log_resource_gtid_state_wrapper : public Log_resource {
     @param[in] gtid_state_arg the pointer to the Gtid_state object resource.
     @param[in] json_arg the pointer to the JSON object to be populated with the
                         resource log information.
+    @param[in] binlog_arg the pointer to the MYSQL_BIN_LOG object resource.
   */
 
   Log_resource_gtid_state_wrapper(Gtid_state *gtid_state_arg,
-                                  Json_dom *json_arg)
-      : Log_resource(json_arg), gtid_state(gtid_state_arg) {}
+                                  Json_dom *json_arg, MYSQL_BIN_LOG *binlog_arg)
+      : Log_resource(json_arg),
+        gtid_state(gtid_state_arg),
+        binlog(binlog_arg) {}
 
   void lock() override;
   void unlock() override;
@@ -256,10 +260,12 @@ class Log_resource_factory {
     @param[in] gtid_state the pointer to the Gtid_state object resource.
     @param[in] json the pointer to the JSON object to be populated with the
                     resource log information.
+    @param[in] binlog the pointer to the MYSQL_BIN_LOG object resource.
     @return  the pointer to the new Log_resource.
   */
 
-  static Log_resource *get_wrapper(Gtid_state *gtid_state, Json_dom *json);
+  static Log_resource *get_wrapper(Gtid_state *gtid_state, Json_dom *json,
+                                   MYSQL_BIN_LOG *binlog);
 
   /**
     Creates a Log_resource wrapper based on a handlerton.

storage/perfschema/table_log_status.cc

@@ -226,7 +226,8 @@ int table_log_status::make_row() {
   */
   {
     Log_resource *res;
-    res = Log_resource_factory::get_wrapper(gtid_state, &json_local);
+    res = Log_resource_factory::get_wrapper(gtid_state, &json_local,
+                                            &mysql_bin_log);
     error = DBUG_EVALUATE_IF("log_status_oom_gtid", 1, !res);
     if (error) {
       my_error(ER_UNABLE_TO_COLLECT_LOG_STATUS, MYF(0), "LOCAL",