Bug #76614 Assertion `!(mysql_bin_log.is_open()&&!thd.is_current_stmt_bi nlog_format_row())
Submitted: 8 Apr 2015 4:01 Modified: 25 Nov 22:54
Reporter: Ramesh Sivaraman (OCA) Email Updates:
Status: Won't fix Impact on me:
None 
Category:MySQL Server: DML Severity:S3 (Non-critical)
Version:5.6.23, 5.6.24, 5.6.25 OS:Linux (CentOS 7)
Assigned to: CPU Architecture:Any
Tags: debug

[8 Apr 2015 4:01] Ramesh Sivaraman
Description:
2015-04-07 23:54:17 7255 [Note] /sda/old_run/mysql-5.6.23-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.6.23-debug-log'  socket: '/dev/shm/1428460412/socket.sock'  port: 32738  MySQL Community Server (GPL)
2015-04-07 23:54:17 7255 [Note] Event Scheduler: scheduler thread started with id 1
mysqld: /sda/mysql-server-5.6/sql/sql_insert.cc:3196: bool Delayed_insert::handle_inserts(): Assertion `!(mysql_bin_log.is_open() && !thd.is_current_stmt_binlog_format_row())' failed.
03:54:17 UTC - mysqld got signal 6 ;

** GDB info

#0  0x00007fa37f5f0771 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1  0x0000000000a980a6 in my_write_core (sig=6) at /sda/mysql-server-5.6/mysys/stacktrace.c:422
#2  0x00000000007277f0 in handle_fatal_signal (sig=6) at /sda/mysql-server-5.6/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007fa37e3fc5d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5  0x00007fa37e3fdcc8 in __GI_abort () at abort.c:90
#6  0x00007fa37e3f5546 in __assert_fail_base (fmt=0x7fa37e545128 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0xefe910 "!(mysql_bin_log.is_open() && !thd.is_current_stmt_binlog_format_row())", file=file@entry=0xefe2f0 "/sda/mysql-server-5.6/sql/sql_insert.cc", line=line@entry=3196, function=function@entry=0xeff580 <Delayed_insert::handle_inserts()::__PRETTY_FUNCTION__> "bool Delayed_insert::handle_inserts()") at assert.c:92
#7  0x00007fa37e3f55f2 in __GI___assert_fail (assertion=0xefe910 "!(mysql_bin_log.is_open() && !thd.is_current_stmt_binlog_format_row())", file=0xefe2f0 "/sda/mysql-server-5.6/sql/sql_insert.cc", line=3196, function=0xeff580 <Delayed_insert::handle_inserts()::__PRETTY_FUNCTION__> "bool Delayed_insert::handle_inserts()") at assert.c:101
#8  0x00000000007b81ba in Delayed_insert::handle_inserts (this=0x7fa361474000) at /sda/mysql-server-5.6/sql/sql_insert.cc:3195
#9  0x00000000007b7a6c in handle_delayed_insert (arg=0x7fa361474000) at /sda/mysql-server-5.6/sql/sql_insert.cc:3028
#10 0x0000000000b5d7f0 in pfs_spawn_thread (arg=0x7fa3614fa020) at /sda/mysql-server-5.6/storage/perfschema/pfs.cc:1860
#11 0x00007fa37f5ebdf5 in start_thread (arg=0x7fa37fb68700) at pthread_create.c:308
#12 0x00007fa37e4bd1ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

How to repeat:
** Testcase

DROP DATABASE test;CREATE DATABASE test;USE test;
SET @@GLOBAL.binlog_format=1;
SET SQL_LOG_BIN=0;
SET @@session.storage_engine=MYISAM;
CREATE TABLE t1(c1 DATE KEY,c2 DATE,c3 INT,INDEX idx2(c2));
INSERT DELAYED INTO t1 VALUES(6);
set @@session.sql_log_bin=TRUE;
xa start,;
set global binlog_format=row;
INSERT DELAYED INTO t1 VALUES(0,0,0);

** Startup option

--log-bin=binlog

  The attached tarball gives the testcase as an exact match of our system,
  including some handy utilities

  $ vi {epoch}_mybase # Update base path in this file (the only change
  required!). For non-binary (i.e. non-tarball/non-build-binary-distribution) distributions please update SOURCE_DIR location also.
  $ ./{epoch}_init # Initializes the data dir
  $ ./{epoch}_start # Starts mysqld
  $ ./{epoch}_cl # To check mysqld is up
  $ ./{epoch}_run # Run the testcase with pquery binary(produces
  output)
  $ vi /dev/shm/{epoch}/error.log.out # Verify the error log
  $ ./{epoch}_gdb # Brings you to a gdb prompt attached to correct
  mysqld
  & generated core
  $ ./{epoch}_parse_core # Create {epoch}_STD.gdb and {epoch}_FULL.gdb;
  standard and full var gdb stack traces
  etc.
[8 Apr 2015 4:01] Ramesh Sivaraman
Testcase bundle

Attachment: 1428460412_bug_bundle.tar.gz (application/gzip, text), 998.15 KiB.

[8 Apr 2015 5:01] Umesh Shastry
Hello Ramesh Sivaraman,

Thank you for the report and test case.
Observed that 5.6.24/5.6.25 debug builds are affected.

Thanks,
Umesy
[8 Apr 2015 5:02] Umesh Shastry
// 5.6.24 - only debug build affected

scripts/mysql_install_db --basedir=/export/umesh/server/binaries/mysql-5.6.24 --datadir=/export/umesh/server/binaries/mysql-5.6.24/76614
bin/mysqld-debug --log-bin=master-bin --basedir=/export/umesh/server/binaries/mysql-5.6.24 --datadir=/export/umesh/server/binaries/mysql-5.6.24/76614 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.24/76614/log.err 2>&1 &

commit: 97543660999308893335d81b92307c389e6821a5
date: 2015-03-25 17:22:45 +0100
build-date: 2015-03-25 17:26:48 +0100
short: 9754366
branch: mysql-5.6.24-release

MySQL source 5.6.24

(gdb) bt
#0  0x00007fb46f674771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000ae0f7f in my_write_core (sig=6) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/mysys/stacktrace.c:422
#2  0x0000000000745f8a in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007fb46e27a5c9 in raise () from /lib64/libc.so.6
#5  0x00007fb46e27bcd8 in abort () from /lib64/libc.so.6
#6  0x00007fb46e273536 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007fb46e2735e2 in __assert_fail () from /lib64/libc.so.6
#8  0x00000000007da70e in Delayed_insert::handle_inserts (this=0x7fb410019700) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/sql_insert.cc:3195
#9  0x00000000007dbb71 in handle_delayed_insert (arg=0x7fb410019700) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/sql/sql_insert.cc:3028
#10 0x0000000000dd43e0 in pfs_spawn_thread (arg=0x7fb41000f8e0) at /export/home/pb2/build/sb_0-14808650-1427301633.73/mysqlcom-pro-5.6.24/storage/perfschema/pfs.cc:1860
#11 0x00007fb46f66fdf3 in start_thread () from /lib64/libpthread.so.0
#12 0x00007fb46e33b47d in clone () from /lib64/libc.so.6
(gdb)
[8 Apr 2015 5:02] Umesh Shastry
// 5.6.25  - only debug build affected

scripts/mysql_install_db --basedir=/export/umesh/server/binaries/mysql-5.6.25 --datadir=/export/umesh/server/binaries/mysql-5.6.25/76614
bin/mysqld-debug --log-bin=master-bin --basedir=/export/umesh/server/binaries/mysql-5.6.25 --datadir=/export/umesh/server/binaries/mysql-5.6.25/76614 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.25/76614/log.err 2>&1 &

commit: a322a3cf5881a77b2fe55a531a18f0bd4c19dabc
date: 2015-04-06 14:32:57 +0530
build-date: 2015-04-06 11:26:23 +0200
short: a322a3c
branch: mysql-5.6

MySQL source 5.6.25

(gdb) bt
#0  0x00007fb394998771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000ae1513 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-14909455-1428315097.54/mysqlcom-pro-5.6.25/mysys/stacktrace.c:422
#2  0x000000000074600a in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-14909455-1428315097.54/mysqlcom-pro-5.6.25/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007fb39359e5c9 in raise () from /lib64/libc.so.6
#5  0x00007fb39359fcd8 in abort () from /lib64/libc.so.6
#6  0x00007fb393597536 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007fb3935975e2 in __assert_fail () from /lib64/libc.so.6
#8  0x00000000007da92a in Delayed_insert::handle_inserts (this=0x7fb334019700) at /export/home/pb2/build/sb_0-14909455-1428315097.54/mysqlcom-pro-5.6.25/sql/sql_insert.cc:3195
#9  0x00000000007dbd8d in handle_delayed_insert (arg=0x7fb334019700) at /export/home/pb2/build/sb_0-14909455-1428315097.54/mysqlcom-pro-5.6.25/sql/sql_insert.cc:3028
#10 0x0000000000dd49cc in pfs_spawn_thread (arg=0x7fb33400f930) at /export/home/pb2/build/sb_0-14909455-1428315097.54/mysqlcom-pro-5.6.25/storage/perfschema/pfs.cc:1860
#11 0x00007fb394993df3 in start_thread () from /lib64/libpthread.so.0
#12 0x00007fb39365f47d in clone () from /lib64/libc.so.6
(gdb)
[10 Apr 2015 8:09] Ståle Deraas
Posted by developer:
 
Note that INSERT DELAYED is deprecated in 5.6 and removed in 5.7, so the issue is not present in 5.7.