| Bug #101611 | stuck "Compressing transaction changes." when binlog_transaction_compression | ||
|---|---|---|---|
| Submitted: | 14 Nov 2020 0:40 | Modified: | 5 Mar 2021 15:20 |
| Reporter: | Ryan Perry | Email Updates: | |
| Status: | Closed | Impact on me: | |
| 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
[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 2021 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.
