[MDEV-14264] [Draft] Assertion `empty()' failed in binlog_cache_data::reset Created: 2017-11-02  Updated: 2018-11-18

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.1, 10.2
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Elena Stepanova
Resolution: Unresolved Votes: 0
Labels: None

Attachments: File mdev-3972.yy     File mdev-3972.zz     File my.cnf     HTML File threads    

 Description   

10.1.24 BUILD/compile-pentium64-debug-max

2017-11-03  0:02:11 140573382466304 [Note] InnoDB: Created tablespace for space 15583 name test/table0_innodb_bigint_autoinc key_id 0 encryption 0.
2017-11-03  0:02:12 140573382466304 [Note] InnoDB: Created tablespace for space 15584 name test/table1_innodb_bigint_autoinc key_id 0 encryption 0.
2017-11-03  0:02:12 140573382466304 [Note] InnoDB: Created tablespace for space 15585 name test/table10_innodb_bigint_autoinc key_id 0 encryption 0.
2017-11-03  0:02:12 140573382466304 [Note] InnoDB: Created tablespace for space 15586 name test/table100_innodb_bigint_autoinc key_id 0 encryption 0.
2017-11-03  0:02:13 140573382466304 [Note] InnoDB: Created tablespace for space 15587 name test/table1000_innodb_bigint_autoinc key_id 0 encryption 0.
mysqld: /data/src/10.1-mdev13461/sql/log.cc:313: void binlog_cache_data::reset(): Assertion `empty()' failed.
171103  0:16:24 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.1.24-MariaDB-debug
key_buffer_size=1073741824
read_buffer_size=262144
max_used_connections=9
max_threads=361
thread_count=9
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1241013 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7fd8362ad070
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7fd9ca86d278 thread_stack 0x48400
/data/src/10.1-mdev13461/sql/mysqld(my_print_stacktrace+0x35)[0xfae082]
/data/src/10.1-mdev13461/sql/mysqld(handle_fatal_signal+0x394)[0x89314f]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110c0)[0x7fd9cc49f0c0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7fd9cab87fcf]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fd9cab893fa]
/lib/x86_64-linux-gnu/libc.so.6(+0x2be37)[0x7fd9cab80e37]
/lib/x86_64-linux-gnu/libc.so.6(+0x2bee2)[0x7fd9cab80ee2]
/data/src/10.1-mdev13461/sql/mysqld(_ZN17binlog_cache_data5resetEv+0xbb)[0x97c053]
/data/src/10.1-mdev13461/sql/mysqld(_ZN17binlog_cache_mngr5resetEbb+0x40)[0x97c3ce]
/data/src/10.1-mdev13461/sql/mysqld[0x96722f]
/data/src/10.1-mdev13461/sql/mysqld[0x967908]
/data/src/10.1-mdev13461/sql/mysqld(_Z17ha_rollback_transP3THDb+0x1ca)[0x896e0d]
/data/src/10.1-mdev13461/sql/mysqld(_Z19trans_rollback_stmtP3THD+0x9d)[0x7a9654]
/data/src/10.1-mdev13461/sql/mysqld(_Z21mysql_execute_commandP3THD+0xa626)[0x67836f]
/data/src/10.1-mdev13461/sql/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x255)[0x67c1db]
/data/src/10.1-mdev13461/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xd19)[0x66b801]
mysys/stacktrace.c:267(my_print_stacktrace)[0x66a5dd]
sql/log.cc:314(binlog_cache_data::reset())[0x79525c]
sql/transaction.cc:489(trans_rollback_stmt(THD*))[0x794fc0]
sql/sql_connect.cc:1262(handle_one_connection)[0x7fd9cc495494]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fd9cac3d93f]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fd83142c088): INSERT IGNORE INTO `table1_innodb_bigint_autoinc` ( `pk` ) SELECT `col_int` FROM `table1_myisam_bigint_autoinc` /* QNO 144 CON_ID 37 */
Connection ID (thread ID): 37
Status: NOT_KILLED

# 2017-11-03T00:16:36 [4899] #3  <signal handler called>
# 2017-11-03T00:16:36 [4899] #4  0x00007fd9cab87fcf in raise () from /lib/x86_64-linux-gnu/libc.so.6
# 2017-11-03T00:16:36 [4899] #5  0x00007fd9cab893fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
# 2017-11-03T00:16:36 [4899] #6  0x00007fd9cab80e37 in __assert_fail_base () from /lib/x86_64-linux-gnu/libc.so.6
# 2017-11-03T00:16:36 [4899] #7  0x00007fd9cab80ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
# 2017-11-03T00:16:36 [4899] #8  0x000000000097c053 in binlog_cache_data::reset (this=0x7fd9c9132c18) at /data/src/10.1-mdev13461/sql/log.cc:313
# 2017-11-03T00:16:36 [4899] #9  0x000000000097c3ce in binlog_cache_mngr::reset (this=0x7fd9c9132a70, do_stmt=false, do_trx=true) at /data/src/10.1-mdev13461/sql/log.cc:481
# 2017-11-03T00:16:36 [4899] #10 0x000000000096722f in binlog_truncate_trx_cache (thd=0x7fd8362ad070, cache_mngr=0x7fd9c9132a70, all=false) at /data/src/10.1-mdev13461/sql/log.cc:1915
# 2017-11-03T00:16:36 [4899] #11 0x0000000000967908 in binlog_rollback (hton=0x7fd9ca039c70, thd=0x7fd8362ad070, all=false) at /data/src/10.1-mdev13461/sql/log.cc:2113
# 2017-11-03T00:16:36 [4899] #12 0x0000000000896e0d in ha_rollback_trans (thd=0x7fd8362ad070, all=false) at /data/src/10.1-mdev13461/sql/handler.cc:1659
# 2017-11-03T00:16:36 [4899] #13 0x00000000007a9654 in trans_rollback_stmt (thd=0x7fd8362ad070) at /data/src/10.1-mdev13461/sql/transaction.cc:488
# 2017-11-03T00:16:36 [4899] #14 0x000000000067836f in mysql_execute_command (thd=0x7fd8362ad070) at /data/src/10.1-mdev13461/sql/sql_parse.cc:5738
# 2017-11-03T00:16:36 [4899] #15 0x000000000067c1db in mysql_parse (thd=0x7fd8362ad070, rawbuf=0x7fd83142c088 "INSERT IGNORE INTO `table1_innodb_bigint_autoinc` ( `pk` ) SELECT `col_int` FROM `table1_myisam_bigint_autoinc` /* QNO 144 CON_ID 37 */", length=135, parser_state=0x7fd9ca86c690) at /data/src/10.1-mdev13461/sql/sql_parse.cc:7339
# 2017-11-03T00:16:36 [4899] #16 0x000000000066b801 in dispatch_command (command=COM_QUERY, thd=0x7fd8362ad070, packet=0x7fd8362b3071 "INSERT IGNORE INTO `table1_innodb_bigint_autoinc` ( `pk` ) SELECT `col_int` FROM `table1_myisam_bigint_autoinc` /* QNO 144 CON_ID 37 */ ", packet_length=136) at /data/src/10.1-mdev13461/sql/sql_parse.cc:1490
# 2017-11-03T00:16:36 [4899] #17 0x000000000066a5dd in do_command (thd=0x7fd8362ad070) at /data/src/10.1-mdev13461/sql/sql_parse.cc:1109
# 2017-11-03T00:16:36 [4899] #18 0x000000000079525c in do_handle_one_connection (thd_arg=0x7fd8313dd070) at /data/src/10.1-mdev13461/sql/sql_connect.cc:1349
# 2017-11-03T00:16:36 [4899] #19 0x0000000000794fc0 in handle_one_connection (arg=0x7fd8313dd070) at /data/src/10.1-mdev13461/sql/sql_connect.cc:1261
# 2017-11-03T00:16:36 [4899] #20 0x00007fd9cc495494 in start_thread (arg=0x7fd9ca86db00) at pthread_create.c:333
# 2017-11-03T00:16:36 [4899] #21 0x00007fd9cac3d93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

start_server --defaults-file=/data/jira-eventum/mdev13461/my.cnf  --datadir=/dev/shm/vardir1 --lock-wait-timeout=120 --debug-sync-timeout=10 --tmpdir=/smalldisk/tmp

$ df -k /smalldisk/
Filesystem     1K-blocks    Used Available Use% Mounted on
/dev/sda7        1409536 1305128     14760  99% /smalldisk
 
$ df -k /dev/shm/
Filesystem     1K-blocks    Used Available Use% Mounted on
tmpfs            8209408 7847312    362096  96% /dev/shm

experimental 9f5fdd0d14391aeb414e8430dd4ef8b88eaddb60

perl ./gentest.pl --gendata=/data/tmp/mdev-3972.zz --threads=8 --queries=100M --duration=3600 --dsn=dbi:mysql:host=127.0.0.1:port=3306:user=root:database=test --grammar=/data/tmp/mdev-3972.yy

diff --git a/lib/GenTest/Constants.pm b/lib/GenTest/Constants.pm
index 8c7f511..5754b1e 100644
--- a/lib/GenTest/Constants.pm
+++ b/lib/GenTest/Constants.pm
@@ -137,7 +137,7 @@ use constant STATUS_SERVER_KILLED           => 102; # Willfull killing of the server, wil
 use constant STATUS_REPLICATION_FAILURE                => 103;
 use constant STATUS_UPGRADE_FAILURE         => 104;
 use constant STATUS_RECOVERY_FAILURE           => 105;
-use constant STATUS_DATABASE_CORRUPTION                => 106;
+use constant STATUS_DATABASE_CORRUPTION                => 96;
 use constant STATUS_SERVER_DEADLOCKED          => 107;
 use constant STATUS_BACKUP_FAILURE             => 108;
 use constant STATUS_VALGRIND_FAILURE           => 109;
diff --git a/runall-new.pl b/runall-new.pl
index eacbac9..4ef7ef4 100755
--- a/runall-new.pl
+++ b/runall-new.pl
@@ -71,7 +71,8 @@ use DBI;
 use Cwd;
 
 my $database = 'test';
-my $user = 'rqg';
+my $user = 'root';
+
 my @dsns;



 Comments   
Comment by Elena Stepanova [ 2017-11-02 ]

On the 2nd attempt it did actually say "no space"

2017-11-03  0:43:42 140524442565376 [ERROR] mysqld: Error writing file '1701-bin-log' (errno: 28 "No space left on device")
mysqld: /data/src/10.1-mdev13461/sql/log.cc:313: void binlog_cache_data::reset(): Assertion `empty()' failed.
171103  0:43:42 [ERROR] mysqld got signal 6 ;

But this is weird, because now the data dir on a regular disk with plenty of space:

$ df -k data/
Filesystem      1K-blocks       Used Available Use% Mounted on
/dev/sdb1      1922728752 1350655424 474381272  75% /data

So, it must refer to the tmpdir even though it doesn't say so.

Comment by Elena Stepanova [ 2018-11-18 ]

Occurrence on 10.2 in travis: https://travis-ci.org/elenst/travis-tests/jobs/456069542
Technically, it's possible that tests in travis run out of disk space, but there is no indication of it in this particular test run.

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