[MDEV-19764] binlog.flashback-largebinlog fails in buildbot with out of memory Created: 2019-06-14  Updated: 2023-11-29  Resolved: 2023-11-29

Status: Closed
Project: MariaDB Server
Component/s: Replication, Tests
Affects Version/s: 10.2
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Andrei Elkin
Resolution: Won't Fix Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-32352 binlog.flashback-largebinlog crashes ... Open

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2-big/builds/3246

10.2 50653e021f1678c3c28c6b5886fadb9f

binlog.flashback-largebinlog 'row'       w2 [ fail ]
        Test ended at 2019-06-14 11:54:09
 
CURRENT_TEST: binlog.flashback-largebinlog
mysqltest: At line 77: query 'INSERT INTO t1 VALUES (REPEAT('ManyMegaByteBlck', 67108864))' failed: 1041: Out of memory; check if mysqld or some other process uses all available memory; if not, you may have to use 'ulimit' to allow mysqld to use more memory or you can add more swap space
 
The result from queries just before the failure was:
< snip >
connect  default, localhost,root,,;
#
# Delete all existing binary logs.
#
RESET MASTER;
#
# Create a test table.
#
use mysqltest;
CREATE TABLE t1 (
c1 LONGTEXT
) DEFAULT CHARSET latin1;
#
# Show how many rows are affected by each statement.
#
#
# Insert some big rows.
#
insert 1024MB data twice
INSERT INTO t1 VALUES (REPEAT('ManyMegaByteBlck', 67108864));



 Comments   
Comment by Andrei Elkin [ 2019-06-14 ]

elenst This is OOM, and while this test may be not that parsimonious, should it be tackled by expanding
the VM's RAM, what do you think?

Comment by Elena Stepanova [ 2019-06-14 ]

We can't be jumping into expanding just because a test was written to consume a lot of resources. I'm not saying it's the case here. If it is really necessary and there is a good justification why it can't be made reasonable, then I suppose it can be considered. But it's an exception, not a rule.

Comment by Andrei Elkin [ 2019-06-15 ]

Fair enough, thanks! I am checking if it can be optimized. (Yet, can't help feeling more such tests are coming out over time as the server must be gradually loaded more and more).

Comment by Andrei Elkin [ 2020-05-18 ]

alice: Let me bounce this one to you as it looks pretty much pure test failure. Could you please check whether the culprit is in EPEAT('ManyMegaByteBlck', 67108864) and how that could be worked around? Sure come up with a patch if/when you'll sort it out.

Comment by Alice Sherepa [ 2020-05-28 ]

1. Test purpose was to check that binlog bigger then 2GB could be read with mysqlbinlog --flashback (-v), but test generates binlog files=1GB. (as binlog max size 1GB after each insert (REPEAT('ManyMegaByteBlck', 67108864))' there was a new binlog file opened)

2. After rewriting test the bigger binlog will need even more memory (in my test it was ~6Gb for 10.2, >10Gb for 10.5), so OOM problem will still be there.

--let $mysqlbinlog_output= tmp/mysqlbinlog_big_1.out
 
--source include/have_binlog_format_row.inc
--source include/big_test.inc
--source include/have_64bit.inc
 
--echo # Capture initial value of max_allowed_packet
let $orig_max_allowed_packet = 
query_get_value(SELECT @@global.max_allowed_packet, @@global.max_allowed_packet, 1);
 
SET @@global.max_allowed_packet= 1024*1024*1024;
 
#as max_allowed_packet is a global variable:
disconnect default;
connect (default, localhost,root,,);
 
RESET MASTER;
 
CREATE TABLE t1 (c1 longtext, c2 longtext);
INSERT t1 VALUES (repeat(1, @@max_allowed_packet),  repeat(1, @@max_allowed_packet));
 
FLUSH LOGS;
 
--echo # Call mysqlbinlog to display the master-bin.000001 (2.1Gb).
 
let $MYSQLD_DATADIR= `select @@datadir`;
--exec $MYSQL_BINLOG --flashback -v $MYSQLD_DATADIR/master-bin.000001 > $MYSQLTEST_VARDIR/$mysqlbinlog_output
 
--echo # Cleanup.
eval SET @@global.max_allowed_packet = $orig_max_allowed_packet;
DROP TABLE t1;
 
--echo remove_file \$MYSQLTEST_VARDIR/$mysqlbinlog_output
--remove_file $MYSQLTEST_VARDIR/$mysqlbinlog_output

Test fails for mysqlbinlog with --flashback -v options ( just --flashback seems to work). KB advises not to use this combination of options as " information to the binary log which can cause problems when importing" https://mariadb.com/kb/en/flashback/

10.3-10.5 fail with assertion "size <= 0xFFFFFFFFL" in String::append

10.3 ecc7f305dde85d704a37e58

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007f16060ba801 in __GI_abort () at abort.c:79
#2  0x00007f16060aa39a in __assert_fail_base (fmt=0x7f16062317d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x563d28c4d62c "size <= 0xFFFFFFFFL", file=file@entry=0x563d28c4d538 "/10.3/sql/sql_string.cc", line=line@entry=530, function=function@entry=0x563d28c4ee20 <String::append(char const*, unsigned long)::__PRETTY_FUNCTION__> "bool String::append(const char*, size_t)") at assert.c:92
#3  0x00007f16060aa412 in __GI___assert_fail (assertion=0x563d28c4d62c "size <= 0xFFFFFFFFL", file=0x563d28c4d538 "/10.3/sql/sql_string.cc", line=530, function=0x563d28c4ee20 <String::append(char const*, unsigned long)::__PRETTY_FUNCTION__> "bool String::append(const char*, size_t)") at assert.c:101
#4  0x0000563d28ba6492 in String::append (this=0x563d297cef80, s=0x7f13816c2080 "\nSET @binlog_fragment_0 ='\nbaLPXhMBAAAAMAAAAKUCAAAAACAAAAAAAAEABHRlc3QAAnQxAAL8/AIEBAPa1K/i\nbaLPXhkBAAAAKgAAgM8CAIAAACAAAAAAAAEAAv/8AAAAQDExMTExMTExMTExMTExMTExMTExMTEx\nMTExMTExMTExMTExMTExMTExMTExMTE"..., size=5048470638) at /10.3/sql/sql_string.cc:530
#5  0x0000563d28ba18b9 in Rows_log_event::print_helper (this=0x563d297cef20, file=0x7f1606466760 <_IO_2_1_stdout_>, print_event_info=0x7ffe40945e40, name=0x563d28c4a545 "Delete_rows") at /10.3/sql/log_event.cc:12235
#6  0x0000563d28ba2fb9 in Write_rows_log_event::print (this=0x563d297cef20, file=0x7f1606466760 <_IO_2_1_stdout_>, print_event_info=0x7ffe40945e40) at /10.3/sql/log_event.cc:13754
#7  0x0000563d28b815f5 in print_base64 (print_event_info=0x7ffe40945e40, ev=0x563d297cef20) at /10.3/client/mysqlbinlog.cc:899
#8  0x0000563d28b8185d in print_row_event (print_event_info=0x7ffe40945e40, ev=0x563d297cef20, table_id=32, is_stmt_end=true) at /10.3/client/mysqlbinlog.cc:994
#9  0x0000563d28b82430 in process_event (print_event_info=0x7ffe40945e40, ev=0x563d297cef20, pos=677, logname=0x7ffe40947c86 "/10.3/mysql-test/var/mysqld.1/data//master-bin.000001") at /10.3/client/mysqlbinlog.cc:1474
#10 0x0000563d28b853e5 in dump_local_log_entries (print_event_info=0x7ffe40945e40, logname=0x7ffe40947c86 "/10.3/mysql-test/var/mysqld.1/data//master-bin.000001") at /10.3/client/mysqlbinlog.cc:2990
#11 0x0000563d28b8373b in dump_log_entries (logname=0x7ffe40947c86 "/10.3/mysql-test/var/mysqld.1/data//master-bin.000001") at /10.3/client/mysqlbinlog.cc:2217
#12 0x0000563d28b859b6 in main (argc=0, argv=0x563d297c5e90) at /10.3/client/mysqlbinlog.cc:3150

10.2 fails like this:

Thread 1 (Thread 0x7f80f0852740 (LWP 15395)):
#0  0x00007f80ef44ec01 in __GI___libc_free (mem=0x7f7fedbb0010) at malloc.c:3123
#1  0x00005627cb4f0bf0 in Rows_log_event::~Rows_log_event (this=0x5627cd023368, __in_chrg=<optimized out>) at /10.2/sql/log_event.cc:10582
#2  0x00005627cb50348f in Write_rows_log_event::~Write_rows_log_event (this=0x5627cd023368, __in_chrg=<optimized out>) at /10.2/sql/log_event.h:4701
#3  Write_rows_log_event::~Write_rows_log_event (this=0x5627cd023368, __in_chrg=<optimized out>) at /10.2/sql/log_event.h:4701
#4  0x00005627cb4fe4a9 in process_event (print_event_info=<optimized out>, ev=0x5627cd023368, pos=<optimized out>, logname=<optimized out>) at /10.2/client/mysqlbinlog.cc:1543
#5  0x00005627cb4ffa67 in dump_local_log_entries (logname=0x7ffdc6bacc34 "/10.2/mysql-test/var/mysqld.1/data//master-bin.000001", print_event_info=0x7ffdc6ba9bd0) at /10.2/client/mysqlbinlog.cc:2930
#6  dump_log_entries (logname=<optimized out>) at /10.2/client/mysqlbinlog.cc:2162
#7  0x00005627cb4e0e8f in main (argc=0, argv=0x5627cd018aa8) at /10.2/client/mysqlbinlog.cc:3097

3. Test was added in this commit https://github.com/mariadb/server/commit/d7c8423a3d44a5eb9bb22efd957eab3f32497b0f in 10.2
In 10.3 there is another commit by Monty https://github.com/MariaDB/server/commit/afbb72b3b6988f4c5242d46588754517724b2950 that seems to fix the same. Please recheck how they co-exist in versions >=10.3.

Generated at Thu Feb 08 08:54:11 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.