Bug #71523 mysqlbinlog does not show commit_seq_no used for parallel slaves

• Submitted: 30 Jan 2014 11:23
• Modified: 23 Jan 2016 12:04
• Reporter: Jean-François Gagné
• Status: Closed
• Category: MySQL Server: Replication
• Severity: S4 (Feature request)
• Version: 5.7.3
• OS: Any
• CPU Architecture: Any
• Tags: Group Commit, mysqlbinlog, Parallel Slave

[30 Jan 2014 11:23] Jean-François Gagné

Description:
MySQL 5.7.2 introduced the slave-parallel-type=LOGICAL_CLOCK to run transactions in parallel on slaves based on a "commit sequence number".  This commit_seq_no is sent from the master to slaves using the binary logs.  mysqlbinlog does not show commit_seq_no even it the information is in the binary logs.

Note: this information is useful to determine the number of slave-parallel-workers to allocate on slaves.

How to repeat:
On a server with binary logs enable, run many transactions in parallel, and use mysqlbinlog on the generated binary logs.

Suggested fix:
The patch bellow allows to show commit_seq_no with mysqlbinlog.

$ diff -u mysql-5.7.3-m13/sql/log_event.cc{.org,}
--- mysql-5.7.3-m13/sql/log_event.cc.org        2013-11-16 21:48:52.000000000 +0100
+++ mysql-5.7.3-m13/sql/log_event.cc    2014-01-30 10:55:42.000000000 +0100
@@ -4525,9 +4525,16 @@
   if (!print_event_info->short_form)
   {
     print_header(file, print_event_info, FALSE);
+if (commit_seq_no != -1) {
+    my_b_printf(file, "\t%s\tthread_id=%lu\texec_time=%lu\terror_code=%d\tcommit_seq_no=%ld\n",
+                get_type_str(), (ulong) thread_id, (ulong) exec_time,
+                error_code, (long)commit_seq_no);
+}
+else {
     my_b_printf(file, "\t%s\tthread_id=%lu\texec_time=%lu\terror_code=%d\n",
                 get_type_str(), (ulong) thread_id, (ulong) exec_time,
                 error_code);
+}
   }

   bool suppress_use_flag= is_binlog_rewrite_db(db);
$

[5 Feb 2014 11:56] Jean-François Gagné

Updated patch to display the commit_seq_no from GTID transactions:

$  diff -u mysql-5.7.3-m13/sql/log_event.cc{.org,}
--- mysql-5.7.3-m13/sql/log_event.cc.org        2013-11-16 21:48:52.000000000 +0100
+++ mysql-5.7.3-m13/sql/log_event.cc    2014-02-05 10:40:01.000000000 +0100
@@ -4525,9 +4525,16 @@
   if (!print_event_info->short_form)
   {
     print_header(file, print_event_info, FALSE);
+if (commit_seq_no != -1) {
+    my_b_printf(file, "\t%s\tthread_id=%lu\texec_time=%lu\terror_code=%d\tcommit_seq_no=%ld\n",
+                get_type_str(), (ulong) thread_id, (ulong) exec_time,
+                error_code, (long)commit_seq_no);
+}
+else {
     my_b_printf(file, "\t%s\tthread_id=%lu\texec_time=%lu\terror_code=%d\n",
                 get_type_str(), (ulong) thread_id, (ulong) exec_time,
                 error_code);
+}
   }

   bool suppress_use_flag= is_binlog_rewrite_db(db);
@@ -13590,7 +13597,12 @@
   if (!print_event_info->short_form)
   {
     print_header(head, print_event_info, FALSE);
+if (commit_seq_no != -1) {
+    my_b_printf(head, "\tGTID [commit=%s]\tcommit_seq_no=%ld\n", commit_flag ? "yes" : "no", (long)commit_seq_no);
+}
+else {
     my_b_printf(head, "\tGTID [commit=%s]\n", commit_flag ? "yes" : "no");
+}
   }
   to_string(buffer);
   my_b_printf(head, "%s%s\n", buffer, print_event_info->delimiter);

[23 Jan 2016 12:04] Jean-François Gagné

mysqlbinlog from MySQL 5.7.10 has interval information (see below) so closing this feature request.  Thanks for implementing that.

#160121 15:45:51 ... last_committed=0  sequence_number=9
#160121 15:45:51 ... last_committed=0  sequence_number=10
#160121 15:45:51 ... last_committed=10 sequence_number=11
#160121 15:45:51 ... last_committed=10 sequence_number=12
...
#160121 15:45:51 ... last_committed=10 sequence_number=19
#160121 15:45:51 ... last_committed=10 sequence_number=20
#160121 15:45:52 ... last_committed=20 sequence_number=21
#160121 15:45:52 ... last_committed=20 sequence_number=22