Bug #88324 handle_fatal_signal (sig=11) in ha_innobase::update_thd
Submitted: 2 Nov 2017 6:37 Modified: 22 Dec 2017 8:57
Reporter: Roel Van de Paar Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: DML Severity:S6 (Debug Builds)
Version:8.0.3 RC OS:Any
Assigned to: CPU Architecture:Any

[2 Nov 2017 6:37] Roel Van de Paar
Description:
2017-11-02T05:57:42.957769Z 4 [Note] Event Scheduler: scheduler thread started with id 4
2017-11-02T05:59:14.480374Z 6 [Warning] InnoDB: Cannot find a free slot for an undo log. Do you have too many active transactions running concurrently?
2017-11-02T05:59:14.480585Z 6 [Warning] InnoDB: Cannot find a free slot for an undo log. Do you have too many active transactions running concurrently?
2017-11-02T05:59:14.545006Z 6 [Warning] InnoDB: Cannot find a free slot for an undo log. Do you have too many active transactions running concurrently?
05:59:14 UTC - mysqld got signal 11 ;

Core was generated by `/sda/MS201017-mysql-8.0.3-rc-linux-x86_64-debug/bin/mysqld --no-defaults --core'.
Program terminated with signal 11, Segmentation fault.
#0  0x00007ff4f9d609b1 in __pthread_kill (threadid=<optimized out>, signo=11) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
61	  val = INTERNAL_SYSCALL (tgkill, err, 3, THREAD_GETMEM (THREAD_SELF, pid),
(gdb) bt
#0  0x00007ff4f9d609b1 in __pthread_kill (threadid=<optimized out>, signo=11) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1  0x000000000369e428 in my_write_core (sig=11) at /git/mysql-server_dbg/mysys/stacktrace.cc:291
#2  0x000000000286b8f6 in handle_fatal_signal (sig=11) at /git/mysql-server_dbg/sql/signal_handler.cc:234
#3  <signal handler called>
#4  0x000000000381d807 in ha_innobase::update_thd (this=0x7ff4b31bc030, thd=0x7ff4b3019000)
    at /git/mysql-server_dbg/storage/innobase/handler/ha_innodb.cc:3041
#5  0x000000000383c8c0 in ha_innobase::external_lock (this=0x7ff4b31bc030, thd=0x7ff4b3019000, lock_type=2)
    at /git/mysql-server_dbg/storage/innobase/handler/ha_innodb.cc:17588
#6  0x00000000029d6f2b in handler::ha_external_lock (this=0x7ff4b31bc030, thd=0x7ff4b3019000, lock_type=2)
    at /git/mysql-server_dbg/sql/handler.cc:8267
#7  0x0000000002b64bdc in unlock_external (thd=0x7ff4b3019000, table=0x7ff4b3275db8, count=1)
    at /git/mysql-server_dbg/sql/lock.cc:676
#8  0x0000000002b64328 in mysql_unlock_tables (thd=0x7ff4b3019000, sql_lock=0x7ff4b3275da0) at /git/mysql-server_dbg/sql/lock.cc:442
#9  0x0000000002b64396 in mysql_unlock_some_tables (thd=0x7ff4b3019000, table=0x7ff4fa303bc8, count=1)
    at /git/mysql-server_dbg/sql/lock.cc:457
#10 0x0000000002b64661 in mysql_lock_remove (thd=0x7ff4b3019000, locked=0x7ff4b3275e60, table=0x7ff4b308ee20)
    at /git/mysql-server_dbg/sql/lock.cc:548
#11 0x000000000241980c in close_all_tables_for_name (thd=0x7ff4b3019000, key=0x7ff4fa303c90 "test", key_length=8, 
    db=0x7ff4fa303c90 "test", table_name=0x7ff4fa303c95 "t3", remove_from_locked_tables=false, skip_table=0x0)
    at /git/mysql-server_dbg/sql/sql_base.cc:1524
#12 0x0000000002419955 in close_all_tables_for_name (thd=0x7ff4b3019000, share=0x7ff4b30ad430, remove_from_locked_tables=false, 
    skip_table=0x0) at /git/mysql-server_dbg/sql/sql_base.cc:1561
#13 0x0000000002c2f8ab in Sql_cmd_truncate_table::truncate_table (this=0x7ff4b302f9d8, thd=0x7ff4b3019000, table_ref=0x7ff4b302fa00)
    at /git/mysql-server_dbg/sql/sql_truncate.cc:690
#14 0x0000000002c2fb80 in Sql_cmd_truncate_table::execute (this=0x7ff4b302f9d8, thd=0x7ff4b3019000)
    at /git/mysql-server_dbg/sql/sql_truncate.cc:751
#15 0x00000000024be1ff in mysql_execute_command (thd=0x7ff4b3019000, first_level=true)
    at /git/mysql-server_dbg/sql/sql_parse.cc:4628
#16 0x00000000024c042b in mysql_parse (thd=0x7ff4b3019000, parser_state=0x7ff4fa3062f0)
    at /git/mysql-server_dbg/sql/sql_parse.cc:5414
#17 0x00000000024b68e7 in dispatch_command (thd=0x7ff4b3019000, com_data=0x7ff4fa306b80, command=COM_QUERY)
    at /git/mysql-server_dbg/sql/sql_parse.cc:1708
#18 0x00000000024b53f5 in do_command (thd=0x7ff4b3019000) at /git/mysql-server_dbg/sql/sql_parse.cc:1291
#19 0x000000000285b2d6 in handle_connection (arg=0x7ff4e62eb3c0)
    at /git/mysql-server_dbg/sql/conn_handler/connection_handler_per_thread.cc:328
#20 0x00000000036ec54d in pfs_spawn_thread (arg=0x7ff4e6391620) at /git/mysql-server_dbg/storage/perfschema/pfs.cc:2985
#21 0x00007ff4f9d5be25 in start_thread (arg=0x7ff4fa307700) at pthread_create.c:308
#22 0x00007ff4f813b34d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

How to repeat:
CREATE DATABASE transforms;
CREATE DATABASE test;
USE test;
CREATE TABLE t3 (c1 DECIMAL(65) UNSIGNED,c2 INTEGER(254) UNSIGNED,c3 CHAR(254) CHARACTER SET 'utf8' COLLATE 'utf8_bin') ENGINE=CSV;#ERROR: 1178 - The storage engine for the table doesn't support nullable columns
CREATE TABLE IF NOT EXISTS t3 (c1 BINARY,c2 VARCHAR(2049) CHARACTER SET 'utf8' COLLATE 'utf8_bin',c3 INTEGER(254) ZEROFILL, PRIMARY KEY(c1)) ENGINE=InnoDB;#NOERROR
INSERT INTO t3 SELECT * FROM t2;#NOERROR
SET @@GLOBAL.innodb_trx_rseg_n_slots_debug=1;#NOERROR
TRUNCATE t3; ;

You may need to execute the testcase several times (may be sporadic)
[2 Nov 2017 6:58] MySQL Verification Team
Hello Roel ,

Thank you for the report and test case.
Observed that 8.0.3(8.0.4) debug build is affected.

Thanks,
Umesh
[2 Nov 2017 7:02] MySQL Verification Team
-- 8.0.3/8.0.4 debug build affected

rm -rf 88324
bin/mysqld-debug --initialize-insecure --basedir=$PWD --datadir=$PWD/88324 
bin/mysqld-debug --no-defaults --basedir=$PWD --datadir=$PWD/88324 --core-file --socket=/tmp/mysql_ushastry.sock --port=3306 --log-error=$PWD/88324/log.err 2>&1 &

-- 8.0.3

(gdb) bt
#0  0x00007f2e9f9ec771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000034fb0bb in my_write_core (sig=11) at ../../mysqlcom-pro-8.0.3-rc/mysys/stacktrace.cc:291
#2  0x00000000026d704a in handle_fatal_signal (sig=11) at ../../mysqlcom-pro-8.0.3-rc/sql/signal_handler.cc:234
#3  <signal handler called>
#4  0x00000000036780b3 in ha_innobase::update_thd (this=0x7f2e00023950, thd=0x7f2e00000be0) at ../../../mysqlcom-pro-8.0.3-rc/storage/innobase/handler/ha_innodb.cc:3041
#5  0x0000000003696c7e in ha_innobase::external_lock (this=0x7f2e00023950, thd=0x7f2e00000be0, lock_type=2)
    at ../../../mysqlcom-pro-8.0.3-rc/storage/innobase/handler/ha_innodb.cc:17588
#6  0x0000000002840f72 in handler::ha_external_lock (this=0x7f2e00023950, thd=0x7f2e00000be0, lock_type=2) at ../../mysqlcom-pro-8.0.3-rc/sql/handler.cc:8267
#7  0x00000000029d0264 in unlock_external (thd=0x7f2e00000be0, table=0x7f2e00151518, count=1) at ../../mysqlcom-pro-8.0.3-rc/sql/lock.cc:676
#8  0x00000000029cf9b6 in mysql_unlock_tables (thd=0x7f2e00000be0, sql_lock=0x7f2e00151500) at ../../mysqlcom-pro-8.0.3-rc/sql/lock.cc:442
#9  0x00000000029cfa24 in mysql_unlock_some_tables (thd=0x7f2e00000be0, table=0x7f2e91860d88, count=1) at ../../mysqlcom-pro-8.0.3-rc/sql/lock.cc:457
#10 0x00000000029cfcfb in mysql_lock_remove (thd=0x7f2e00000be0, locked=0x7f2e000e9500, table=0x7f2e0015b2a0) at ../../mysqlcom-pro-8.0.3-rc/sql/lock.cc:548
#11 0x000000000227e2e2 in close_all_tables_for_name (thd=0x7f2e00000be0, key=0x7f2e91860e50 "test", key_length=8, db=0x7f2e91860e50 "test",
    table_name=0x7f2e91860e55 "t3", remove_from_locked_tables=false, skip_table=0x0) at ../../mysqlcom-pro-8.0.3-rc/sql/sql_base.cc:1524
#12 0x000000000227e41c in close_all_tables_for_name (thd=0x7f2e00000be0, share=0x7f2e00027ac0, remove_from_locked_tables=false, skip_table=0x0)
    at ../../mysqlcom-pro-8.0.3-rc/sql/sql_base.cc:1561
#13 0x0000000002a99e0b in Sql_cmd_truncate_table::truncate_table (this=0x7f2e00009c60, thd=0x7f2e00000be0, table_ref=0x7f2e00009c88)
    at ../../mysqlcom-pro-8.0.3-rc/sql/sql_truncate.cc:690
#14 0x0000000002a9a0da in Sql_cmd_truncate_table::execute (this=0x7f2e00009c60, thd=0x7f2e00000be0) at ../../mysqlcom-pro-8.0.3-rc/sql/sql_truncate.cc:751
#15 0x0000000002325839 in mysql_execute_command (thd=0x7f2e00000be0, first_level=true) at ../../mysqlcom-pro-8.0.3-rc/sql/sql_parse.cc:4628
#16 0x0000000002327c0e in mysql_parse (thd=0x7f2e00000be0, parser_state=0x7f2e91863420) at ../../mysqlcom-pro-8.0.3-rc/sql/sql_parse.cc:5414
#17 0x000000000231dead in dispatch_command (thd=0x7f2e00000be0, com_data=0x7f2e91863d10, command=COM_QUERY) at ../../mysqlcom-pro-8.0.3-rc/sql/sql_parse.cc:1708
#18 0x000000000231c9ac in do_command (thd=0x7f2e00000be0) at ../../mysqlcom-pro-8.0.3-rc/sql/sql_parse.cc:1291
#19 0x00000000026c69c3 in handle_connection (arg=0x949f410) at ../../mysqlcom-pro-8.0.3-rc/sql/conn_handler/connection_handler_per_thread.cc:328
#20 0x000000000352d230 in pfs_spawn_thread (arg=0x95aa910) at ../../../mysqlcom-pro-8.0.3-rc/storage/perfschema/pfs.cc:2985
#21 0x00007f2e9f9e7df5 in start_thread () from /lib64/libpthread.so.0
#22 0x00007f2e9e4a760d in clone () from /lib64/libc.so.6
(gdb)

-- 8.0.4

(gdb) bt
#0  0x00007ff965e73771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000003632c99 in my_write_core (sig=6) at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/mysys/stacktrace.cc:291
#2  0x00000000028fa2d9 in handle_fatal_signal (sig=6) at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/signal_handler.cc:234
#3  <signal handler called>
#4  0x00007ff96486d5d7 in raise () from /lib64/libc.so.6
#5  0x00007ff96486ecc8 in abort () from /lib64/libc.so.6
#6  0x00000000038cee21 in ut_dbg_assertion_failed (expr=0x481cd9f "error == DB_SUCCESS",
    file=0x481cb60 "/export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/storage/innobase/log/log0ddl.cc", line=1434)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/storage/innobase/ut/ut0dbg.cc:71
#7  0x000000000376cad9 in Log_DDL::delete_by_id (this=0x7ff954cbcbd8, trx=0x7ff9580768d0, id=5)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/storage/innobase/log/log0ddl.cc:1434
#8  0x000000000376b9dd in Log_DDL::write_rename_space_log (this=0x7ff954cbcbd8, space_id=2, old_file_path=0x7ff8c8034f58 "./test/#sql-ib1055-125468117.ibd",
    new_file_path=0x7ff8c80d38a8 "./test/t3.ibd") at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/storage/innobase/log/log0ddl.cc:1167
#9  0x0000000003a005c3 in fil_rename_tablespace (id=2, old_path=0x7ff8c810c2b8 "./test/t3.ibd", new_name=0x7ff8c810dae0 "test/#sql-ib1055-125468117",
    new_path_in=0x7ff8c8034618 "./test/#sql-ib1055-125468117.ibd")
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/storage/innobase/fil/fil0fil.cc:4079
#10 0x00000000036972eb in ha_innobase::truncate_rename_tablespace (this=0x7ff8c81319c0, name=0x7ff8c8160d88 "./test/t3")
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/storage/innobase/handler/ha_innodb.cc:14354
#11 0x000000000369782c in ha_innobase::truncate (this=0x7ff8c81319c0, table_def=0x7ff8c811a4d0)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/storage/innobase/handler/ha_innodb.cc:14460
#12 0x0000000002a4354e in handler::ha_truncate (this=0x7ff8c81319c0, table_def=0x7ff8c811a4d0)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/handler.cc:4948
#13 0x0000000002c76933 in handler_truncate_base (thd=0x7ff8c8000be0, table_ref=0x7ff8c8009c40, table_def=0x7ff8c811a4d0)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/sql_truncate.cc:282
#14 0x0000000002c777a4 in Sql_cmd_truncate_table::truncate_table (this=0x7ff8c8009c18, thd=0x7ff8c8000be0, table_ref=0x7ff8c8009c40)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/sql_truncate.cc:667
#15 0x0000000002c77ade in Sql_cmd_truncate_table::execute (this=0x7ff8c8009c18, thd=0x7ff8c8000be0)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/sql_truncate.cc:757
#16 0x00000000025b0427 in mysql_execute_command (thd=0x7ff8c8000be0, first_level=true)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/sql_parse.cc:4614
#17 0x00000000025b2837 in mysql_parse (thd=0x7ff8c8000be0, parser_state=0x7ff94967f420)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/sql_parse.cc:5407
#18 0x00000000025a8c20 in dispatch_command (thd=0x7ff8c8000be0, com_data=0x7ff94967fd10, command=COM_QUERY)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/sql_parse.cc:1706
#19 0x00000000025a7761 in do_command (thd=0x7ff8c8000be0) at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/sql_parse.cc:1292
#20 0x00000000028eadeb in handle_connection (arg=0x820c240)
    at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/sql/conn_handler/connection_handler_per_thread.cc:328
#21 0x0000000003b21b5e in pfs_spawn_thread (arg=0x836c7b0) at /export/umesh/server/binaries/Trunk/bug/mysql-8.0-export-12033604/storage/perfschema/pfs.cc:2987
#22 0x00007ff965e6edf5 in start_thread () from /lib64/libpthread.so.0
#23 0x00007ff96492e60d in clone () from /lib64/libc.so.6
(gdb)
[16 Nov 2017 9:41] Erlend Dahl
Duplicate of

Bug#88325 InnoDB: Assertion failure: log0ddl.cc:1424:error == DB_SUCCESS
[16 Nov 2017 9:45] Roel Van de Paar
* This is a crash whereas 88325 is an assert.
* 5.7.19 produces;
  
  5.7.19>TRUNCATE t3; ;
  ERROR 1637 (HY000): Too many active concurrent transactions

  Instead. 

How was this bug verified to be a duplicate?
[29 Nov 2017 5:32] Roel Van de Paar
Erlend, Umesh, ping
[4 Dec 2017 22:52] Roel Van de Paar
Erlend, Umesh, this bug has been open for quite some time - any updates?
[5 Dec 2017 12:19] MySQL Verification Team
Hi Roel,

Sorry, some how we lost track of this.
I spoke to Erlend and he will get back to you on this.

Thanks,
Umesh
[22 Dec 2017 8:57] Erlend Dahl
It's a duplicate because it's the same kind of variable misuse. Comment from the InnoDB devs.

Same for this bug, innodb_trx_rseg_n_slots_debug should not be set to 1. As I
mentioned in bug#88325, setting it to 1 is really unexpected, all kinds of
crashes/failures can happen.