Bug #114198 Using PERSIST on binlog_transaction_compression partially compresses binary log

Submitted: 4 Mar 2024 4:21 Modified: 6 Mar 2024 8:22
Reporter: Jaime Sicam Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:8.0.35, 8.0.36 OS:Any
Assigned to: CPU Architecture:Any

[4 Mar 2024 4:21] Jaime Sicam 
Description:
If binlog_transaction_compression is enabled as a persistent variable on the replica and the server is restarted, some transactions in the binary log is stored as uncompressed as per the output of SELECT * FROM performance_schema.binary_log_transaction_compression_stats\G

mysql> SELECT * FROM performance_schema.binary_log_transaction_compression_stats\G
*************************** 1. row ***************************
                            LOG_TYPE: BINARY
                    COMPRESSION_TYPE: ZSTD
                 TRANSACTION_COUNTER: 2280
            COMPRESSED_BYTES_COUNTER: 13186769
          UNCOMPRESSED_BYTES_COUNTER: 26687624
              COMPRESSION_PERCENTAGE: 51
                FIRST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:48
  FIRST_TRANSACTION_COMPRESSED_BYTES: 262381
FIRST_TRANSACTION_UNCOMPRESSED_BYTES: 518182
         FIRST_TRANSACTION_TIMESTAMP: 2024-03-04 11:58:21.063953
                 LAST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:3207
   LAST_TRANSACTION_COMPRESSED_BYTES: 687
 LAST_TRANSACTION_UNCOMPRESSED_BYTES: 1614
          LAST_TRANSACTION_TIMESTAMP: 2024-03-04 11:58:26.280288
*************************** 2. row ***************************
                            LOG_TYPE: BINARY
                    COMPRESSION_TYPE: NONE
                 TRANSACTION_COUNTER: 894
            COMPRESSED_BYTES_COUNTER: 16435285
          UNCOMPRESSED_BYTES_COUNTER: 16435285
              COMPRESSION_PERCENTAGE: 0
                FIRST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:34
  FIRST_TRANSACTION_COMPRESSED_BYTES: 149
FIRST_TRANSACTION_UNCOMPRESSED_BYTES: 149
         FIRST_TRANSACTION_TIMESTAMP: 2024-03-04 11:53:03.686463
                 LAST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:3205
   LAST_TRANSACTION_COMPRESSED_BYTES: 1617
 LAST_TRANSACTION_UNCOMPRESSED_BYTES: 1617
          LAST_TRANSACTION_TIMESTAMP: 2024-03-04 11:58:26.278651
*************************** 3. row ***************************
                            LOG_TYPE: RELAY
                    COMPRESSION_TYPE: NONE
                 TRANSACTION_COUNTER: 5935
            COMPRESSED_BYTES_COUNTER: 47941303
          UNCOMPRESSED_BYTES_COUNTER: 47941303
              COMPRESSION_PERCENTAGE: 0
                FIRST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:34
  FIRST_TRANSACTION_COMPRESSED_BYTES: 157
FIRST_TRANSACTION_UNCOMPRESSED_BYTES: 157
         FIRST_TRANSACTION_TIMESTAMP: 2103-06-04 03:25:48.779456
                 LAST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:5968
   LAST_TRANSACTION_COMPRESSED_BYTES: 1673
 LAST_TRANSACTION_UNCOMPRESSED_BYTES: 1673
          LAST_TRANSACTION_TIMESTAMP: 2103-06-04 04:19:34.810144
3 rows in set (0.00 sec)

However, if you place binlog_transaction_compression under the [mysqld] section of my.cnf and restart MySQL there is no entry for uncompressed binary log in binary_log_transaction_compression_stats. 

How to repeat:
Setup GTID asynchronous replication:
dbdeployer deploy replication --nodes=2 --gtid --super-read-only-slaves --sandbox-binary=~/opt/mysql 8.0.36

On the replica, set binlog_transaction_compression as persistent variable and restart the MySQL server:
SET PERSIST binlog_transaction_compression=ON;

On the primary, create table and insert records:
mysql> USE test;
Database changed
mysql> CREATE TABLE t1(a INT NOT NULL AUTO_INCREMENT PRIMARY KEY, b INT);
Query OK, 0 rows affected (0.02 sec)

mysql> INSERT INTO t1(b) VALUES (0),(1),(2);
Query OK, 3 rows affected (0.02 sec)
Records: 3  Duplicates: 0  Warnings: 0

On the replica, check binary_log_transaction_compression_stats and as you can see the binary log is uncompressed:
mysql> SELECT * FROM performance_schema.binary_log_transaction_compression_stats\G
*************************** 1. row ***************************
                            LOG_TYPE: BINARY
                    COMPRESSION_TYPE: NONE
                 TRANSACTION_COUNTER: 2
            COMPRESSED_BYTES_COUNTER: 345
          UNCOMPRESSED_BYTES_COUNTER: 345
              COMPRESSION_PERCENTAGE: 0
                FIRST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:34
  FIRST_TRANSACTION_COMPRESSED_BYTES: 149
FIRST_TRANSACTION_UNCOMPRESSED_BYTES: 149
         FIRST_TRANSACTION_TIMESTAMP: 2024-03-04 11:53:03.686463
                 LAST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:35
   LAST_TRANSACTION_COMPRESSED_BYTES: 196
 LAST_TRANSACTION_UNCOMPRESSED_BYTES: 196
          LAST_TRANSACTION_TIMESTAMP: 2024-03-04 11:53:23.709827
*************************** 2. row ***************************
                            LOG_TYPE: RELAY
                    COMPRESSION_TYPE: NONE
                 TRANSACTION_COUNTER: 2
            COMPRESSED_BYTES_COUNTER: 378
          UNCOMPRESSED_BYTES_COUNTER: 378
              COMPRESSION_PERCENTAGE: 0
                FIRST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:34
  FIRST_TRANSACTION_COMPRESSED_BYTES: 157
FIRST_TRANSACTION_UNCOMPRESSED_BYTES: 157
         FIRST_TRANSACTION_TIMESTAMP: 2103-06-04 03:25:48.779456
                 LAST_TRANSACTION_ID: 00022637-1111-1111-1111-111111111111:35
   LAST_TRANSACTION_COMPRESSED_BYTES: 221
 LAST_TRANSACTION_UNCOMPRESSED_BYTES: 221
          LAST_TRANSACTION_TIMESTAMP: 2103-06-04 03:29:08.993604
2 rows in set (0.01 sec)

Also, on the replica, try using older version of mysqlbinlog(<8.0.20) to see if binary log can be read which means that the binary log data is not compressed:
~/opt/mysql/8.0.11/bin/mysqlbinlog -v --base64-output=decode-rows data/mysql-bin.000002
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#240304 11:51:50 server id 22638  end_log_pos 126 CRC32 0xa0dc129f 	Start: binlog v 4, server v 8.0.36 created 240304 11:51:50 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 126
#240304 11:51:50 server id 22638  end_log_pos 197 CRC32 0x812aa432 	Previous-GTIDs
# 00022637-1111-1111-1111-111111111111:1-33
# at 197
#240304 11:53:03 server id 22637  end_log_pos 281 CRC32 0x85c4c307 	GTID	last_committed=0	sequence_number=1	rbr_only=no	original_committed_timestamp=1709524383677080	immediate_commit_timestamp=1709524383686463	transaction_length=237
# original_commit_timestamp=1709524383677080 (2024-03-04 11:53:03.677080 PST)
# immediate_commit_timestamp=1709524383686463 (2024-03-04 11:53:03.686463 PST)
/*!80001 SET @@session.original_commit_timestamp=1709524383677080*//*!*/;
SET @@SESSION.GTID_NEXT= '00022637-1111-1111-1111-111111111111:34'/*!*/;
# at 281
#240304 11:53:03 server id 22637  end_log_pos 434 CRC32 0x3db3fc99 	Query	thread_id=12	exec_time=0	error_code=0	Xid = 2
use `test`/*!*/;
SET TIMESTAMP=1709524383/*!*/;
SET @@session.pseudo_thread_id=12/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80005 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
CREATE TABLE t1(a INT NOT NULL AUTO_INCREMENT PRIMARY KEY, b INT)
/*!*/;
# at 434
#240304 11:53:23 server id 22637  end_log_pos 520 CRC32 0xd42f24c8 	GTID	last_committed=1	sequence_number=2	rbr_only=yes	original_committed_timestamp=1709524403697941	immediate_commit_timestamp=1709524403709827	transaction_length=298
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1709524403697941 (2024-03-04 11:53:23.697941 PST)
# immediate_commit_timestamp=1709524403709827 (2024-03-04 11:53:23.709827 PST)
/*!80001 SET @@session.original_commit_timestamp=1709524403697941*//*!*/;
SET @@SESSION.GTID_NEXT= '00022637-1111-1111-1111-111111111111:35'/*!*/;
# at 520
#240304 11:53:23 server id 22637  end_log_pos 590 CRC32 0x2bf551a5 	Query	thread_id=12	exec_time=0	error_code=0
SET TIMESTAMP=1709524403/*!*/;
SET @@session.sql_mode=1168637984/*!*/;
BEGIN
/*!*/;
# at 590
#240304 11:53:23 server id 22637  end_log_pos 639 CRC32 0x7f55886c 	Table_map: `test`.`t1` mapped to number 85
# at 639
#240304 11:53:23 server id 22637  end_log_pos 701 CRC32 0xf71de157 	Write_rows: table id 85 flags: STMT_END_F
### INSERT INTO `test`.`t1`
### SET
###   @1=1
###   @2=0
### INSERT INTO `test`.`t1`
### SET
###   @1=2
###   @2=1
### INSERT INTO `test`.`t1`
### SET
###   @1=3
###   @2=2
# at 701
#240304 11:53:23 server id 22637  end_log_pos 732 CRC32 0x8df9022a 	Xid = 4
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

On the other hand, if sysbench is used on master, you can see both compressed and uncompressed entries in binary_log_transaction_compression_stats as shown in the description above.
[6 Mar 2024 8:22] MySQL Verification Team 
Hello Jaime,

Thank you for the report and test case.
Verified as described.

regards,
Umesh
[7 Mar 2024 7:23] Tsubasa Tanaka 
Is this same as #114125 ?

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.041 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.