maria-developers team mailing list archive

[sujatha <sujatha.sivakumar@xxxxxxxxxxx>]

revision-id: e4fa0c805adf06c637cc3867427ca529b40e19ce (mariadb-10.1.43-267-ge4fa0c805ad)
parent(s): de49e603770463e64cf4a79a7414bac93c02254f
author: Sujatha
committer: Sujatha
timestamp: 2020-08-28 12:03:09 +0530
message:

MDEV-4633: multi_source.simple test fails sporadically

Analysis:
========
Writes to 'rli->log_space_total' needs to be synchronized. All modifications
to 'rli->log_space_total' should be performed by holding
'rli->log_space_lock'. But IO thread doesn't acquire this mutex while writing
events to relay log. Hence there is a race condition between SQL THREAD and
IO THREAD, when both try to modify the same variable. SQL_THREAD is trying to
decrement 'rli->log_space_total' in 'purge_first_log'  and IO_THREAD is trying
to increment the 'rli->log_space_total' in 'queue_event' simultaneously .
Hence test occasionally fails with  result mismatch.

Fix:
===
Acquire 'rli->log_space_lock' while modifying 'rli->log_space_total'.

---
 sql/log.cc     | 15 +++++++++++++++
 sql/log.h      | 13 +------------
 sql/rpl_rli.cc |  4 ++++
 sql/slave.cc   | 28 ++++++++++++++--------------
 4 files changed, 34 insertions(+), 26 deletions(-)

diff --git a/sql/log.cc b/sql/log.cc
index 8049b94bab1..28a3d58d9e4 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -10265,6 +10265,21 @@ MYSQL_BIN_LOG::do_binlog_recovery(const char *opt_name, bool do_xa_recovery)
   return error;
 }
 
+void MYSQL_BIN_LOG::harvest_bytes_written(Relay_log_info *rli)
+{
+#ifndef DBUG_OFF
+  char buf1[22],buf2[22];
+#endif
+  DBUG_ENTER("harvest_bytes_written");
+  mysql_mutex_lock(&rli->log_space_lock);
+  rli->log_space_total+=bytes_written;
+  DBUG_PRINT("info",("relay_log_space: %s  bytes_written: %s",
+                     llstr(rli->log_space_total,buf1),
+                     llstr(bytes_written,buf2)));
+  bytes_written=0;
+  mysql_mutex_unlock(&rli->log_space_lock);
+  DBUG_VOID_RETURN;
+}
 
 #ifdef INNODB_COMPATIBILITY_HOOKS
 /**
diff --git a/sql/log.h b/sql/log.h
index 277e5c6f69c..3b136c47bcf 100644
--- a/sql/log.h
+++ b/sql/log.h
@@ -706,18 +706,7 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
   {
     bytes_written = 0;
   }
-  void harvest_bytes_written(ulonglong* counter)
-  {
-#ifndef DBUG_OFF
-    char buf1[22],buf2[22];
-#endif
-    DBUG_ENTER("harvest_bytes_written");
-    (*counter)+=bytes_written;
-    DBUG_PRINT("info",("counter: %s  bytes_written: %s", llstr(*counter,buf1),
-		       llstr(bytes_written,buf2)));
-    bytes_written=0;
-    DBUG_VOID_RETURN;
-  }
+  void harvest_bytes_written(Relay_log_info *rli);
   void set_max_size(ulong max_size_arg);
   void signal_update();
   void wait_for_sufficient_commits();
diff --git a/sql/rpl_rli.cc b/sql/rpl_rli.cc
index c196a65809a..18d7db234fe 100644
--- a/sql/rpl_rli.cc
+++ b/sql/rpl_rli.cc
@@ -467,7 +467,9 @@ static inline int add_relay_log(Relay_log_info* rli,LOG_INFO* linfo)
                     linfo->log_file_name);
     DBUG_RETURN(1);
   }
+  mysql_mutex_lock(&rli->log_space_lock);
   rli->log_space_total += s.st_size;
+  mysql_mutex_unlock(&rli->log_space_lock);
   DBUG_PRINT("info",("log_space_total: %llu", rli->log_space_total));
   DBUG_RETURN(0);
 }
@@ -477,7 +479,9 @@ static int count_relay_log_space(Relay_log_info* rli)
 {
   LOG_INFO linfo;
   DBUG_ENTER("count_relay_log_space");
+  mysql_mutex_lock(&rli->log_space_lock);
   rli->log_space_total= 0;
+  mysql_mutex_unlock(&rli->log_space_lock);
   if (rli->relay_log.find_log_pos(&linfo, NullS, 1))
   {
     sql_print_error("Could not find first log while counting relay log space");
diff --git a/sql/slave.cc b/sql/slave.cc
index 06f2b0d955a..3d9e23441bc 100644
--- a/sql/slave.cc
+++ b/sql/slave.cc
@@ -2508,7 +2508,7 @@ static void write_ignored_events_info_to_relay_log(THD *thd, Master_info *mi)
     }
     if (likely (rev || glev))
     {
-      rli->relay_log.harvest_bytes_written(&rli->log_space_total);
+      rli->relay_log.harvest_bytes_written(rli);
       if (flush_master_info(mi, TRUE, TRUE))
         sql_print_error("Failed to flush master info file");
     }
@@ -5270,7 +5270,7 @@ static int process_io_create_file(Master_info* mi, Create_file_log_event* cev)
                      "error writing Exec_load event to relay log");
           goto err;
         }
-        mi->rli.relay_log.harvest_bytes_written(&mi->rli.log_space_total);
+        mi->rli.relay_log.harvest_bytes_written(&mi->rli);
         break;
       }
       if (unlikely(cev_not_written))
@@ -5285,7 +5285,7 @@ static int process_io_create_file(Master_info* mi, Create_file_log_event* cev)
           goto err;
         }
         cev_not_written=0;
-        mi->rli.relay_log.harvest_bytes_written(&mi->rli.log_space_total);
+        mi->rli.relay_log.harvest_bytes_written(&mi->rli);
       }
       else
       {
@@ -5299,7 +5299,7 @@ static int process_io_create_file(Master_info* mi, Create_file_log_event* cev)
                      "error writing Append_block event to relay log");
           goto err;
         }
-        mi->rli.relay_log.harvest_bytes_written(&mi->rli.log_space_total) ;
+        mi->rli.relay_log.harvest_bytes_written(&mi->rli) ;
       }
     }
   }
@@ -5489,7 +5489,7 @@ static int queue_binlog_ver_1_event(Master_info *mi, const char *buf,
       mysql_mutex_unlock(&mi->data_lock);
       DBUG_RETURN(1);
     }
-    rli->relay_log.harvest_bytes_written(&rli->log_space_total);
+    rli->relay_log.harvest_bytes_written(rli);
   }
   delete ev;
   mi->master_log_pos+= inc_pos;
@@ -5547,7 +5547,7 @@ static int queue_binlog_ver_3_event(Master_info *mi, const char *buf,
     mysql_mutex_unlock(&mi->data_lock);
     DBUG_RETURN(1);
   }
-  rli->relay_log.harvest_bytes_written(&rli->log_space_total);
+  rli->relay_log.harvest_bytes_written(rli);
   delete ev;
   mi->master_log_pos+= inc_pos;
 err:
@@ -5784,9 +5784,7 @@ static int queue_event(Master_info* mi,const char* buf, ulong event_len)
       mysql_mutex_lock(log_lock);
       if (likely(!rli->relay_log.write_event(&fdle) &&
                  !rli->relay_log.flush_and_sync(NULL)))
-      {
-        rli->relay_log.harvest_bytes_written(&rli->log_space_total);
-      }
+        rli->relay_log.harvest_bytes_written(rli);
       else
       {
         error= ER_SLAVE_RELAY_LOG_WRITE_FAILURE;
@@ -6221,7 +6219,7 @@ static int queue_event(Master_info* mi,const char* buf, ulong event_len)
           (rli->relay_log.description_event_for_queue))
         error= ER_SLAVE_RELAY_LOG_WRITE_FAILURE;
       else
-        rli->relay_log.harvest_bytes_written(&rli->log_space_total);
+        rli->relay_log.harvest_bytes_written(rli);
     }
     else if (mi->gtid_reconnect_event_skip_count == 0)
     {
@@ -6234,7 +6232,7 @@ static int queue_event(Master_info* mi,const char* buf, ulong event_len)
       if (rli->relay_log.append_no_lock(&fake_rev))
         error= ER_SLAVE_RELAY_LOG_WRITE_FAILURE;
       else
-        rli->relay_log.harvest_bytes_written(&rli->log_space_total);
+        rli->relay_log.harvest_bytes_written(rli);
     }
   }
   else
@@ -6302,7 +6300,7 @@ static int queue_event(Master_info* mi,const char* buf, ulong event_len)
     {
       mi->master_log_pos+= inc_pos;
       DBUG_PRINT("info", ("master_log_pos: %lu", (ulong) mi->master_log_pos));
-      rli->relay_log.harvest_bytes_written(&rli->log_space_total);
+      rli->relay_log.harvest_bytes_written(rli);
     }
     else
     {
@@ -6382,7 +6380,7 @@ void end_relay_log_info(Relay_log_info* rli)
   log_lock= rli->relay_log.get_log_lock();
   mysql_mutex_lock(log_lock);
   rli->relay_log.close(LOG_CLOSE_INDEX | LOG_CLOSE_STOP_EVENT);
-  rli->relay_log.harvest_bytes_written(&rli->log_space_total);
+  rli->relay_log.harvest_bytes_written(rli);
   mysql_mutex_unlock(log_lock);
   /*
     Delete the slave's temporary tables from memory.
@@ -7318,7 +7316,9 @@ int rotate_relay_log(Master_info* mi)
     Note that it needs to be protected by mi->data_lock.
   */
   mysql_mutex_assert_owner(&mi->data_lock);
-  rli->relay_log.harvest_bytes_written(&rli->log_space_total);
+
+  rli->relay_log.harvest_bytes_written(rli);
+
 end:
   DBUG_RETURN(error);
 }