Bug #101611 stuck "Compressing transaction changes." when binlog_transaction_compression
Submitted: 14 Nov 2020 0:40 Modified: 5 Mar 15:20
Reporter: Ryan Perry Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:8.0.20 OS:FreeBSD (12.1, 11.2)
Assigned to: CPU Architecture:x86
Tags: zstd

[14 Nov 2020 0:40] Ryan Perry
Description:
With the following configuration, performing an INSERT with a field > 256K, the row is inserted, but then becomes stuck in the state of "Compressing transaction changes.".  Killing the query does not seem to clear it.  The server eventually took up all available CPU.  I have repeated this on a second server.  (No errors in error log)

 binlog_format                   = ROW
 binlog_row_image                = minimal
 binlog_transaction_compression = ON
 binlog_transaction_compression_level_zstd = 5
root@localhost [(none)]> show processlist;
+--------+------------------+---------------------+--------------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
| Id     | User             | Host                | db           | Command     | Time   | State                                                         | Info                                                                                                 |
+--------+------------------+---------------------+--------------+-------------+--------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
|      5 | event_scheduler  | localhost           | NULL         | Daemon      |    157 | Waiting for next activation                                   | NULL                                                                                                 |
|      8 | pmk-vcare        | 172.16.29.21:35972  | vcare        | Sleep       |      8 |                                                               | NULL                                                                                                 |
|      9 | pmk-folsom       | 172.16.29.18:35973  | folsom       | Sleep       |      5 |                                                               | NULL                                                                                                 |
|     10 | pmk-cchmclibop   | 172.16.29.30:35975  | cchmclibop   | Sleep       |      7 |                                                               | NULL                                                                                                 |
| 414373 | pmk-api4b        | 172.16.29.80:34410  | pmk          | Query       |  36436 | Compressing transaction changes.                              | INSERT INTO `rd_faxes`.`fax_data` (`id`, `date_created`, `date_updated`, `encoding_type`, `mime`, `d |

How to repeat:
turn on 
 binlog_transaction_compression = ON
 binlog_transaction_compression_level_zstd = 5

INSERT a row larger than 256Kb.
[14 Nov 2020 6:08] Ryan Perry
tag as zstd
[14 Nov 2020 6:08] Ryan Perry
tag as zstd
[18 Nov 2020 21:14] MySQL Verification Team
Hi Ryan,

Thanks for your report. I'm having some issues reproducing this. Might be related to a certain row design. I tried with (id bigind, x blob) and failed. Can you share:

SHOW CREATE TABLE `rd_faxes`.`fax_data` \G

so I can try with exactly same table as you are reproducing this with.

Thanks
Bogdan
[18 Nov 2020 22:18] Ryan Perry
CREATE TABLE `fax_data` (
  `id` int NOT NULL AUTO_INCREMENT,
  `date_created` datetime NOT NULL,
  `date_updated` datetime NOT NULL,
  `encoding_type` varchar(64) NOT NULL DEFAULT 'binary',
  `mime` varchar(64) NOT NULL DEFAULT 'application/pdf',
  `data_obj` mediumblob NOT NULL,
  `incoming_fax_id` bigint DEFAULT NULL,
  `fax_id` bigint DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `idx_date_created` (`date_created`),
  KEY `idx_date_updated` (`date_updated`),
  KEY `data_records_idx_incoming_fax_id` (`incoming_fax_id`)
) ENGINE=InnoDB AUTO_INCREMENT=809914 DEFAULT CHARSET=latin1
[19 Nov 2020 7:17] MySQL Verification Team
Hi,

Can you retest this with 8.0.22?

I'm having issues reproducing this even with your table.

How are you creating the insert? Do you do prepare statement or you just execute it directly? What type of connector are you using? Did you connect directly to MySQL server or you are connecting through MySQL router? 

Thanks
Bogdan

p.s. 
mysql [localhost:8022] {msandbox} (test) > select LENGTH(data_obj) from fax_data;
+------------------+
| LENGTH(data_obj) |
+------------------+
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           659642 |
|           659642 |
+------------------+
24 rows in set (0.00 sec)

mysql [localhost:8022] {msandbox} (test) >
[19 Nov 2020 7:18] MySQL Verification Team
mysql [localhost:8022] {msandbox} (test) > show global variables like '%binlog%';
+------------------------------------------------+----------------------+
| Variable_name                                  | Value                |
+------------------------------------------------+----------------------+
| binlog_cache_size                              | 32768                |
| binlog_checksum                                | CRC32                |
| binlog_direct_non_transactional_updates        | OFF                  |
| binlog_encryption                              | OFF                  |
| binlog_error_action                            | ABORT_SERVER         |
| binlog_expire_logs_seconds                     | 2592000              |
| binlog_format                                  | ROW                  |
| binlog_group_commit_sync_delay                 | 0                    |
| binlog_group_commit_sync_no_delay_count        | 0                    |
| binlog_gtid_simple_recovery                    | ON                   |
| binlog_max_flush_queue_time                    | 0                    |
| binlog_order_commits                           | ON                   |
| binlog_rotate_encryption_master_key_at_startup | OFF                  |
| binlog_row_event_max_size                      | 8192                 |
| binlog_row_image                               | MINIMAL              |
| binlog_row_metadata                            | MINIMAL              |
| binlog_row_value_options                       |                      |
| binlog_rows_query_log_events                   | OFF                  |
| binlog_stmt_cache_size                         | 32768                |
| binlog_transaction_compression                 | ON                   |
| binlog_transaction_compression_level_zstd      | 5                    |
| binlog_transaction_dependency_history_size     | 25000                |
| binlog_transaction_dependency_tracking         | COMMIT_ORDER         |
| innodb_api_enable_binlog                       | OFF                  |
| log_statements_unsafe_for_binlog               | ON                   |
| max_binlog_cache_size                          | 18446744073709547520 |
| max_binlog_size                                | 1073741824           |
| max_binlog_stmt_cache_size                     | 18446744073709547520 |
| sync_binlog                                    | 1                    |
+------------------------------------------------+----------------------+
29 rows in set (0.00 sec)
[19 Nov 2020 8:37] MySQL Verification Team
mysql [localhost:8022] {msandbox} (test) > insert into fax_data values (null, now(), now(), REPEAT('X', 64), REPEAT('Y', 64), REPEAT('Z', 262144), 1, 1);
Query OK, 1 row affected (0.01 sec)

mysql [localhost:8022] {msandbox} (test) > insert into fax_data values (null, now(), now(), REPEAT('X', 64), REPEAT('Y', 64), REPEAT('Z', 2621440), 1, 1);
Query OK, 1 row affected (0.06 sec)

mysql [localhost:8022] {msandbox} (test) > insert into fax_data values (null, now(), now(), REPEAT('X', 64), REPEAT('Y', 64), REPEAT('Z', 16777210), 1, 1);
Query OK, 1 row affected (0.34 sec)

mysql [localhost:8022] {msandbox} (test) > select LENGTH(data_obj) from fax_data;
+------------------+
| LENGTH(data_obj) |
+------------------+
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           659642 |
|           659642 |
|           262144 |
|          2621440 |
|         16777210 |
+------------------+
27 rows in set (0.01 sec)

mysql [localhost:8022] {msandbox} (test) >
[19 Nov 2020 9:17] MySQL Verification Team
tried adding "non compressable" data 

mysql [localhost:8022] {msandbox} (test) > insert into fax_data values (null, now(), now(), REPEAT('X', 64), REPEAT('Y', 64), LOAD_FILE('keetah.gz'), 1, 1);
Query OK, 1 row affected (0.01 sec)

mysql [localhost:8022] {msandbox} (test) > select LENGTH(data_obj) from fax_data;
+------------------+
| LENGTH(data_obj) |
+------------------+
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           580626 |
|           659642 |
|           659642 |
|           262144 |
|          2621440 |
|         16777210 |
|           732126 |
|           732126 |
+------------------+
29 rows in set (0.18 sec)

mysql [localhost:8022] {msandbox} (test) >

not reproducing :(
[19 Nov 2020 9:19] Ryan Perry
At this point I can no longer reproduce the issue in my test environment.  I was able to reproduce this in 3 FreeBSD systems previously, but there must be another factor.

Queries were prepared using perl DBI 1.643/DBD::mysql 4.0.50.
I believe the client version was 5.7.31, but have since upgrade 1 environment to 5.7.32 and the other to 8.0.22.  (I do not think that was the issue however).

We can close this until I have a further example.  Thanks for your time with it.
[19 Nov 2020 9:22] MySQL Verification Team
Hi,

Closing it. It is possible that there was some miss compatibility between older connectors and newer mysqld.

all best
Bogdan
[19 Nov 2020 10:28] MySQL Verification Team
Hi,

I managed to verify this with a help of my colleague :)

mysql [localhost:8022] {msandbox} (test) > prepare s from "insert into t1 (x) values (?)";
Query OK, 0 rows affected (0.01 sec)
Statement prepared

mysql [localhost:8022] {msandbox} (test) > set @a = LOAD_FILE('/home/arhimed/sandboxes/msb_8_0_22/data/keetah.gz');
Query OK, 0 rows affected (0.00 sec)

mysql [localhost:8022] {msandbox} (test) > execute s using @a;

-- STUCK!

> show processlist\G
*************************** 1. row ***************************
     Id: 5
   User: event_scheduler
   Host: localhost
     db: NULL
Command: Daemon
   Time: 141
  State: Waiting on empty queue
   Info: NULL
*************************** 2. row ***************************
     Id: 8
   User: msandbox
   Host: localhost
     db: test
Command: Query
   Time: 109
  State: Compressing transaction changes.
   Info: insert into t1 (x) values ('\03G\▒^\0\▒[ms\▒H▒▒\▒▒▒▒)2▒ֻ2u▒V/-▒ $F3\▒ˬlH\▒#/\▒d▒▒▒>▒6\▒\
*************************** 3. row ***************************
     Id: 9
   User: msandbox
   Host: localhost
     db: NULL
Command: Query
   Time: 0
  State: init
   Info: show processlist
3 rows in set (0.00 sec)

The way to reproduce:

config:
binlog-format = ROW
binlog_row_image = minimal
binlog_transaction_compression = ON
binlog_transaction_compression_level_zstd = 5
binlog_cache_size=10M

script:
CREATE TABLE t1 (id bigint NOT NULL AUTO_INCREMENT PRIMARY KEY, x mediumblob NOT NULL) ENGINE=InnoDB;
prepare s from "insert into t1 (x) values (?)";
set @a = LOAD_FILE('some-archive-file-larger-than-256k');
execute s using @a;

Important:
- the binlog_cache_size is critical to reproduce the problem
- the data must be "uncompressable", REPEAT('x', 512k) will not reproduce problem for e.g.

Thanks for your report
Bogdan
[19 Nov 2020 10:35] MySQL Verification Team
Here's the stack trace of the hanging thread in 8.0.20

[anon@fc30 bld]$ pstack `pidof mysqld`
Thread 41 (Thread 0x7f16fc921700 (LWP 512901)):
#0  futex_wait_cancelable (private=0, expected=0, futex_word=0x85d962c <Per_thread_connection_handler::COND_thread_cache+44>) at ../sysdeps/nptl/futex-internal.h:183
#1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x85d9660 <Per_thread_connection_handler::LOCK_thread_cache>, cond=0x85d9600 <Per_thread_connection_handler::COND_thread_cache>) at pthread_cond_wait.c:508
#2  __pthread_cond_wait (cond=cond@entry=0x85d9600 <Per_thread_connection_handler::COND_thread_cache>, mutex=mutex@entry=0x85d9660 <Per_thread_connection_handler::LOCK_thread_cache>) at pthread_cond_wait.c:638
#3  0x000000000288f615 in native_cond_wait (cond=cond@entry=0x85d9600 <Per_thread_connection_handler::COND_thread_cache>, mutex=mutex@entry=0x85d9660 <Per_thread_connection_handler::LOCK_thread_cache>) at /home/anon/builds/mysqlcom-8.0.20/include/thr_cond.h:109
#4  0x000000000288f6bc in my_cond_wait (cond=cond@entry=0x85d9600 <Per_thread_connection_handler::COND_thread_cache>, mp=0x85d9660 <Per_thread_connection_handler::LOCK_thread_cache>) at /home/anon/builds/mysqlcom-8.0.20/include/thr_cond.h:162
#5  0x000000000288f824 in inline_mysql_cond_wait (that=that@entry=0x85d9600 <Per_thread_connection_handler::COND_thread_cache>, src_line=src_line@entry=161, src_file=0x63e13c0 "/home/anon/builds/mysqlcom-8.0.20/sql/conn_handler/connection_handler_per_thread.cc", mutex=0x85d9660 <Per_thread_connection_handler::LOCK_thread_cache>) at /home/anon/builds/mysqlcom-8.0.20/include/mysql/psi/mysql_cond.h:174
#6  0x0000000002890c8a in Per_thread_connection_handler::block_until_new_connection () at /home/anon/builds/mysqlcom-8.0.20/sql/conn_handler/connection_handler_per_thread.cc:161
#7  0x0000000002890ef6 in handle_connection (arg=arg@entry=0x603000069220) at /home/anon/builds/mysqlcom-8.0.20/sql/conn_handler/connection_handler_per_thread.cc:331
#8  0x00000000054dc81d in pfs_spawn_thread (arg=0x61400008be60) at /home/anon/builds/mysqlcom-8.0.20/storage/perfschema/pfs.cc:2854
#9  0x00007f171c5f4432 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007f171bd4d913 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Thread 40 (Thread 0x7f16f4736700 (LWP 512736)):
#0  0x0000000005958ee9 in ZSTD_compressStream2 (cctx=cctx@entry=0x61900014e680, output=0x6070005b4d48, input=input@entry=0x7f16f472dc70, endOp=endOp@entry=ZSTD_e_end) at /home/anon/builds/mysqlcom-8.0.20/extra/zstd/lib/compress/zstd_compress.c:3620
#1  0x0000000005959c20 in ZSTD_endStream (zcs=0x61900014e680, output=output@entry=0x6070005b4d48) at /home/anon/builds/mysqlcom-8.0.20/extra/zstd/lib/compress/zstd_compress.c:3749
#2  0x0000000004a14701 in binary_log::transaction::compression::Zstd_comp::close (this=0x6070005b4d20) at /home/anon/builds/mysqlcom-8.0.20/libbinlogevents/src/compression/zstd.cpp:121
#3  0x000000000437f540 in binlog_cache_data::compress (this=0x61900023d458, thd=0x6260000b7100) at /home/anon/builds/mysqlcom-8.0.20/sql/binlog.cc:1942
#4  0x000000000435fc65 in binlog_cache_data::finalize (this=this@entry=0x61900023d458, thd=thd@entry=0x6260000b7100, end_event=end_event@entry=0x7f16f472e420) at /home/anon/builds/mysqlcom-8.0.20/sql/binlog.cc:2001
#5  0x000000000438aed9 in MYSQL_BIN_LOG::commit (this=<optimized out>, thd=0x6260000b7100, all=<optimized out>) at /home/anon/builds/mysqlcom-8.0.20/sql/binlog.cc:8097
#6  0x0000000002b552d8 in ha_commit_trans (thd=thd@entry=0x6260000b7100, all=all@entry=false, ignore_global_read_lock=ignore_global_read_lock@entry=false) at /home/anon/builds/mysqlcom-8.0.20/sql/handler.cc:1748
#7  0x0000000002827666 in trans_commit_stmt (thd=thd@entry=0x6260000b7100, ignore_global_read_lock=ignore_global_read_lock@entry=false) at /home/anon/builds/mysqlcom-8.0.20/sql/transaction.cc:521
#8  0x00000000025af793 in mysql_execute_command (thd=0x6260000b7100, first_level=<optimized out>) at /home/anon/builds/mysqlcom-8.0.20/sql/sql_parse.cc:4654
#9  0x00000000025b357d in mysql_parse (thd=thd@entry=0x6260000b7100, parser_state=parser_state@entry=0x7f16f4732890) at /home/anon/builds/mysqlcom-8.0.20/sql/sql_parse.cc:5306
#10 0x00000000025b6b3b in dispatch_command (thd=0x6260000b7100, com_data=<optimized out>, command=<optimized out>) at /home/anon/builds/mysqlcom-8.0.20/sql/sql_parse.cc:1776
#11 0x00000000025b8938 in do_command (thd=thd@entry=0x6260000b7100) at /home/anon/builds/mysqlcom-8.0.20/sql/sql_parse.cc:1274
#12 0x0000000002891010 in handle_connection (arg=arg@entry=0x6070000dccf0) at /home/anon/builds/mysqlcom-8.0.20/sql/conn_handler/connection_handler_per_thread.cc:302
#13 0x00000000054dc81d in pfs_spawn_thread (arg=0x61400008c060) at /home/anon/builds/mysqlcom-8.0.20/storage/perfschema/pfs.cc:2854
#14 0x00007f171c5f4432 in start_thread (arg=<optimized out>) at pthread_create.c:477
#15 0x00007f171bd4d913 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[5 Mar 15:20] Margaret Fisher
Posted by developer:
 
Changelog entry added for MySQL 8.0.24:

Binary log transaction compression could not continue if a row event included a BLOB column containing uncompressable data, and the compressed size of the row event was higher than its uncompressed size. The function now handles the additional post-compression bytes correctly.