MDEV-7802: group commit status variable addition

Backport into 10.0

mysql-test/r/features.result

@@ -120,6 +120,9 @@ drop trigger trg;
 drop table t1;
 show status like "%trigger%";
 Variable_name	Value
+Binlog_group_commit_trigger_count	0
+Binlog_group_commit_trigger_lock_wait	0
+Binlog_group_commit_trigger_timeout	0
 Com_create_trigger	1
 Com_drop_trigger	1
 Com_show_create_trigger	0

mysql-test/suite/binlog/r/binlog_commit_wait.result

@@ -4,6 +4,14 @@ SET @old_count= @@GLOBAL.binlog_commit_wait_count;
 SET GLOBAL binlog_commit_wait_count= 3;
 SET @old_usec= @@GLOBAL.binlog_commit_wait_usec;
 SET GLOBAL binlog_commit_wait_usec= 20000000;
+SELECT variable_value INTO @group_commits FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commits';
+SELECT variable_value INTO @group_commit_trigger_count FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_count';
+SELECT variable_value INTO @group_commit_trigger_timeout FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+SELECT variable_value INTO @group_commit_trigger_lock_wait FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
 SET @a= current_timestamp();
 BEGIN;
 INSERT INTO t1 VALUES (1,0);
@@ -13,6 +21,22 @@ SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
 SELECT IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"));
 IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"))
 Ok
+SELECT variable_value - @group_commits FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commits';
+variable_value - @group_commits
+1
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_count';
+variable_value - @group_commit_trigger_count
+0
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+variable_value - @group_commit_trigger_timeout
+0
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+variable_value - @group_commit_trigger_lock_wait
+1
 ERROR 23000: Duplicate entry '1' for key 'PRIMARY'
 SET @a= current_timestamp();
 INSERT INTO t1 VALUES (2,0);
@@ -22,6 +46,22 @@ SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
 SELECT IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"));
 IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"))
 Ok
+SELECT variable_value - @group_commits FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commits';
+variable_value - @group_commits
+2
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_count';
+variable_value - @group_commit_trigger_count
+1
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+variable_value - @group_commit_trigger_timeout
+0
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+variable_value - @group_commit_trigger_lock_wait
+1
 SET @a= current_timestamp();
 INSERT INTO t1 VALUES (6,0);
 BEGIN;
@@ -36,6 +76,22 @@ SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
 SELECT IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"));
 IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"))
 Ok
+SELECT variable_value - @group_commits FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commits';
+variable_value - @group_commits
+3
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_count';
+variable_value - @group_commit_trigger_count
+1
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+variable_value - @group_commit_trigger_timeout
+0
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+variable_value - @group_commit_trigger_lock_wait
+2
 SET @a= current_timestamp();
 INSERT INTO t1 VALUES (7,0);
 INSERT INTO t1 VALUES (8,0);
@@ -43,6 +99,47 @@ SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
 SELECT IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"));
 IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"))
 Ok
+SELECT variable_value - @group_commits FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commits';
+variable_value - @group_commits
+4
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_count';
+variable_value - @group_commit_trigger_count
+2
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+variable_value - @group_commit_trigger_timeout
+0
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+variable_value - @group_commit_trigger_lock_wait
+2
+SET @a= current_timestamp();
+SET GLOBAL binlog_commit_wait_usec= 5*1000*1000;
+INSERT INTO t1 VALUES (9,0);
+SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
+SELECT IF(@b < 4, CONCAT("Error: too little time elapsed: ", @b, " seconds < 4"),
+IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20")));
+IF(@b < 4, CONCAT("Error: too little time elapsed: ", @b, " seconds < 4"),
+IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20")))
+Ok
+SELECT variable_value - @group_commits FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commits';
+variable_value - @group_commits
+5
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_count';
+variable_value - @group_commit_trigger_count
+2
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+variable_value - @group_commit_trigger_timeout
+1
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+variable_value - @group_commit_trigger_lock_wait
+2
 SELECT * FROM t1 ORDER BY a;
 a	b
 1	11
@@ -52,6 +149,7 @@ a	b
 6	0
 7	0
 8	0
+9	0
 DROP TABLE t1;
 SET GLOBAL binlog_commit_wait_count= @old_count;
 SET GLOBAL binlog_commit_wait_usec= @old_usec;

mysql-test/suite/binlog/t/binlog_commit_wait.test

@@ -13,6 +13,20 @@ connect(con1,localhost,root,,test);
 connect(con2,localhost,root,,test);
 connect(con3,localhost,root,,test);
 
+# Get Initial status measurements
+--connection default
+SELECT variable_value INTO @group_commits FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commits';
+SELECT variable_value INTO @group_commit_trigger_count FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_count';
+SELECT variable_value INTO @group_commit_trigger_timeout FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+SELECT variable_value INTO @group_commit_trigger_lock_wait FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+
+# Note: binlog_group_commits is counted at the start of the group and group_commit_trigger_* is
+# counted near when the groups its finalised.
+
 # Check that if T2 goes to wait for a row lock of T1 while T1 is waiting for
 # more transactions to arrive for group commit, the commit of T1 will complete
 # immediately.
@@ -37,6 +51,23 @@ reap;
 SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
 SELECT IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"));
 
+# All connections are to the same server. One transaction occurs on con1. It is
+# commited before con2 is started. con2 transaction violates the unique key contraint. This
+# type of group commit is binlog_group_commit_trigger_lock_wait so that further con2
+# transactions will occur afterwards as they may be as result of the ER_DUP_ENTRY on the 
+# application side.
+# before: binlog_group_commit=0, binlog_group_commit_trigger_count=0
+# before: binlog_group_commit_trigger_timeout=0, binlog_group_commit_trigger_lock_wait=0
+# after:  binlog_group_commit+1 by reason of binlog_group_commit_trigger_lock_wait+1
+SELECT variable_value - @group_commits FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commits';
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_count';
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+
 --connection con2
 --error ER_DUP_ENTRY
 reap;
@@ -64,6 +95,21 @@ reap;
 SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
 SELECT IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"));
 
+# All connections are to the same server. 3 non-conflicting transaction occur
+# on each connection. The binlog_commit_wait_count=3 at the start therefore 1
+# group is committed by virtue of reaching 3 transactions. Hence
+# binlog_group_commit_trigger_count is incremented.
+# before: binlog_group_commit=1, binlog_group_commit_trigger_count=0
+# before: binlog_group_commit_trigger_timeout=0, binlog_group_commit_trigger_lock_wait=1
+# after:  binlog_group_commit+1 by reason of binlog_group_commit_trigger_count+1
+SELECT variable_value - @group_commits FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commits';
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_count';
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
 
 # Test that commit triggers immediately if there is already a transaction
 # waiting on another transaction that reaches its commit.
@@ -99,6 +145,21 @@ reap;
 SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
 SELECT IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"));
 
+# All connections are to the same server. con2 and con3 updates are aquiring
+# the same row lock for a=1. Either con2 or con3 will be in a lock wait
+# thefore the binlog_group_commit_trigger_lock_wait is incremented.
+# before: binlog_group_commit=2, binlog_group_commit_trigger_count=1
+# before: binlog_group_commit_trigger_timeout=0, binlog_group_commit_trigger_lock_wait=1
+# after:  binlog_group_commit+1 by reason of binlog_group_commit_trigger_lock_wait+1
+SELECT variable_value - @group_commits FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commits';
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_count';
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+
 --connection default
 SET @a= current_timestamp();
 
@@ -114,6 +175,51 @@ reap;
 SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
 SELECT IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20"));
 
+# The con1 and con2 transactions above are combined with the 'send UPDATE t1 SET b=b+10 WHERE a=1;'
+# on con3 from the previous block. So we have 3 so this is a count based group.
+# before: binlog_group_commit=3, binlog_group_commit_trigger_count=1
+# before: binlog_group_commit_trigger_timeout=0, binlog_group_commit_trigger_lock_wait=2
+# after:  binlog_group_commit+1 by reason of binlog_group_commit_trigger_count+1
+SELECT variable_value - @group_commits FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commits';
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_count';
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+
+# Test that when the binlog_commit_wait_usec is reached the tranction gets a group commit
+
+--connection default
+SET @a= current_timestamp();
+SET GLOBAL binlog_commit_wait_usec= 5*1000*1000;
+
+--connection con1
+reap;
+INSERT INTO t1 VALUES (9,0);
+
+--connection default
+SET @b= unix_timestamp(current_timestamp()) - unix_timestamp(@a);
+SELECT IF(@b < 4, CONCAT("Error: too little time elapsed: ", @b, " seconds < 4"),
+          IF(@b < 20, "Ok", CONCAT("Error: too much time elapsed: ", @b, " seconds >= 20")));
+
+# con1 pushes 1 transaction. The count was for 3 to occur before a group commit.
+# The timeout is 5 seconds but we allow between 4 and 20 because of the fragile nature
+# of time in test. This is a timeout causing the commit so binlog_group_commit_trigger_timeout
+# is incremented.
+# before: binlog_group_commit=4, binlog_group_commit_trigger_count=2
+# before: binlog_group_commit_trigger_timeout=0, binlog_group_commit_trigger_lock_wait=2
+# after:  binlog_group_commit+1 by reason of binlog_group_commit_trigger_timeout+1
+SELECT variable_value - @group_commits FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commits';
+SELECT variable_value - @group_commit_trigger_count FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_count';
+SELECT variable_value - @group_commit_trigger_timeout FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_timeout';
+SELECT variable_value - @group_commit_trigger_lock_wait FROM information_schema.global_status
+ WHERE variable_name = 'binlog_group_commit_trigger_lock_wait';
+
 --connection default
 SELECT * FROM t1 ORDER BY a;
 

sql/log.cc

@@ -95,6 +95,9 @@ mysql_mutex_t LOCK_commit_ordered;
 
 static ulonglong binlog_status_var_num_commits;
 static ulonglong binlog_status_var_num_group_commits;
+static ulonglong binlog_status_group_commit_trigger_count;
+static ulonglong binlog_status_group_commit_trigger_lock_wait;
+static ulonglong binlog_status_group_commit_trigger_timeout;
 static char binlog_snapshot_file[FN_REFLEN];
 static ulonglong binlog_snapshot_position;
 
@@ -104,6 +107,12 @@ static SHOW_VAR binlog_status_vars_detail[]=
     (char *)&binlog_status_var_num_commits, SHOW_LONGLONG},
   {"group_commits",
     (char *)&binlog_status_var_num_group_commits, SHOW_LONGLONG},
+  {"group_commit_trigger_count",
+    (char *)&binlog_status_group_commit_trigger_count, SHOW_LONGLONG},
+  {"group_commit_trigger_lock_wait",
+    (char *)&binlog_status_group_commit_trigger_lock_wait, SHOW_LONGLONG},
+  {"group_commit_trigger_timeout",
+    (char *)&binlog_status_group_commit_trigger_timeout, SHOW_LONGLONG},
   {"snapshot_file",
     (char *)&binlog_snapshot_file, SHOW_CHAR},
   {"snapshot_position",
@@ -3035,6 +3044,8 @@ MYSQL_BIN_LOG::MYSQL_BIN_LOG(uint *sync_period)
    bytes_written(0), file_id(1), open_count(1),
    group_commit_queue(0), group_commit_queue_busy(FALSE),
    num_commits(0), num_group_commits(0),
+   group_commit_trigger_count(0), group_commit_trigger_timeout(0),
+   group_commit_trigger_lock_wait(0),
    sync_period_ptr(sync_period), sync_counter(0),
    state_file_deleted(false), binlog_state_recover_done(false),
    is_relay_log(0), signal_cnt(0),
@@ -7562,8 +7573,18 @@ MYSQL_BIN_LOG::wait_for_sufficient_commits()
   mysql_mutex_assert_owner(&LOCK_prepare_ordered);
 
   for (e= last_head= group_commit_queue, count= 0; e; e= e->next)
-    if (++count >= opt_binlog_commit_wait_count || unlikely(e->thd->has_waiter))
+  {
+    if (++count >= opt_binlog_commit_wait_count)
+    {
+      group_commit_trigger_count++;
+      return;
+    }
+    if (unlikely(e->thd->has_waiter))
+    {
+      group_commit_trigger_lock_wait++;
       return;
+    }
+  }
 
   mysql_mutex_unlock(&LOCK_log);
   set_timespec_nsec(wait_until, (ulonglong)1000*opt_binlog_commit_wait_usec);
@@ -7576,18 +7597,30 @@ MYSQL_BIN_LOG::wait_for_sufficient_commits()
     err= mysql_cond_timedwait(&COND_prepare_ordered, &LOCK_prepare_ordered,
                               &wait_until);
     if (err == ETIMEDOUT)
+    {
+      group_commit_trigger_timeout++;
       break;
+    }
     if (unlikely(last_head->thd->has_waiter))
+    {
+      group_commit_trigger_lock_wait++;
       break;
+    }
     head= group_commit_queue;
     for (e= head; e && e != last_head; e= e->next)
     {
       ++count;
       if (unlikely(e->thd->has_waiter))
+      {
+        group_commit_trigger_lock_wait++;
         goto after_loop;
+      }
     }
     if (count >= opt_binlog_commit_wait_count)
+    {
+      group_commit_trigger_count++;
       break;
+    }
     last_head= head;
   }
 after_loop:
@@ -9771,6 +9804,11 @@ TC_LOG_BINLOG::set_status_variables(THD *thd)
     binlog_snapshot_position= last_commit_pos_offset;
   }
   mysql_mutex_unlock(&LOCK_commit_ordered);
+  mysql_mutex_lock(&LOCK_prepare_ordered);
+  binlog_status_group_commit_trigger_count= this->group_commit_trigger_count;
+  binlog_status_group_commit_trigger_timeout= this->group_commit_trigger_timeout;
+  binlog_status_group_commit_trigger_lock_wait= this->group_commit_trigger_lock_wait;
+  mysql_mutex_unlock(&LOCK_prepare_ordered);
 
   if (have_snapshot)
   {

sql/log.h

@@ -515,6 +515,9 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
   ulonglong num_commits;
   /* Number of group commits done. */
   ulonglong num_group_commits;
+  /* The reason why the group commit was grouped */
+  ulonglong group_commit_trigger_count, group_commit_trigger_timeout;
+  ulonglong group_commit_trigger_lock_wait;
 
   /* pointer to the sync period variable, for binlog this will be
      sync_binlog_period, for relay log this will be