Bug #79416 InnoDB: Failing assertion: total_trx >= trx_sys->n_prepared_trx
Submitted: 26 Nov 2015 6:33 Modified: 30 Dec 2015 15:51
Reporter: Roel Van de Paar Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: XA transactions Severity:S6 (Debug Builds)
Version:5.7.9 GA, 5.7.11 OS:Any
Assigned to: CPU Architecture:Any

[26 Nov 2015 6:33] Roel Van de Paar 
Description:
2015-11-26T06:20:56.813831Z 0 [Note] InnoDB: Starting shutdown...
2015-11-26T06:20:56.913949Z 0 [Note] InnoDB: Dumping buffer pool(s) to /sda/MS-mysql-5.7.9-linux-x86_64-debug/data/ib_buffer_pool
2015-11-26T06:20:56.914239Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 151126 17:20:56
2015-11-26 17:20:57 0x7f6083505780  InnoDB: Assertion failure in thread 140052496668544 in file trx0sys.cc line 1265
InnoDB: Failing assertion: total_trx >= trx_sys->n_prepared_trx

+bt
#0  0x00007f6082eaf771 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1  0x0000000001796a78 in my_write_core (sig=6) at /git/mysql-server_dbg/mysys/stacktrace.c:247
#2  0x0000000000e1dc70 in handle_fatal_signal (sig=6) at /git/mysql-server_dbg/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007f6081ab35d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5  0x00007f6081ab4cc8 in __GI_abort () at abort.c:90
#6  0x0000000001aedf9b in ut_dbg_assertion_failed (expr=0x20d1cd0 "total_trx >= trx_sys->n_prepared_trx", file=0x20d1648 "/git/mysql-server_dbg/storage/innobase/trx/trx0sys.cc", line=1265) at /git/mysql-server_dbg/storage/innobase/ut/ut0dbg.cc:67
#7  0x0000000001ad3e70 in trx_sys_any_active_transactions () at /git/mysql-server_dbg/storage/innobase/trx/trx0sys.cc:1265
#8  0x0000000001965d16 in logs_empty_and_mark_files_at_shutdown () at /git/mysql-server_dbg/storage/innobase/log/log0log.cc:2047
#9  0x0000000001a8fe99 in innobase_shutdown_for_mysql () at /git/mysql-server_dbg/storage/innobase/srv/srv0start.cc:2670
#10 0x00000000018c56a0 in innobase_end (hton=0x7f607afdf4a0, type=HA_PANIC_CLOSE) at /git/mysql-server_dbg/storage/innobase/handler/ha_innodb.cc:3797
#11 0x0000000000e8b5be in ha_finalize_handlerton (plugin=0x7f60783eb650) at /git/mysql-server_dbg/sql/handler.cc:780
#12 0x00000000014b9363 in plugin_deinitialize (plugin=0x7f60783eb650, ref_check=true) at /git/mysql-server_dbg/sql/sql_plugin.cc:980
#13 0x00000000014b9761 in reap_plugins () at /git/mysql-server_dbg/sql/sql_plugin.cc:1062
#14 0x00000000014bb578 in plugin_shutdown () at /git/mysql-server_dbg/sql/sql_plugin.cc:1781
#15 0x0000000000e0868f in clean_up (print_message=true) at /git/mysql-server_dbg/sql/mysqld.cc:1291
#16 0x0000000000e0f062 in mysqld_main (argc=10, argv=0x7f6081022300) at /git/mysql-server_dbg/sql/mysqld.cc:4951
#17 0x0000000000e06700 in main (argc=10, argv=0x7fff35cbb9b8) at /git/mysql-server_dbg/sql/main.cc:25

How to repeat:
DROP DATABASE test;CREATE DATABASE test;USE test;
SET @session_start_value=@@session.sql_log_off;
SET @@session.innodb_support_xa=@session_start_value;
xa start 'test2';
CREATE TEMPORARY TABLE t1(c1 TIMESTAMP);
INSERT INTO t1 VALUES(0xAAE9);
xa end 'test2';
SET @@session.pseudo_slave_mode=1;
xa prepare 'test2';

Then exit the client and shutdown mysqld.
[26 Nov 2015 6:38] Roel Van de Paar 
The same testcase will immediately crash on the last line, with a different assertion, if you add this mysqld option: --sql_mode=

Crash details:
Version: '5.7.9-debug'  socket: '/sda/MS-mysql-5.7.9-linux-x86_64-debug/socket.sock'  port: 15079  MySQL Community Server (GPL)
2015-11-26 17:26:01 0x7fb127637700  InnoDB: Assertion failure in thread 140398846768896 in file ha_innodb.cc line 2444
InnoDB: Failing assertion: trx_state_eq(trx, TRX_STATE_PREPARED)

+bt
#0  0x00007fb12703d771 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1  0x0000000001796a78 in my_write_core (sig=6) at /git/mysql-server_dbg/mysys/stacktrace.c:247
#2  0x0000000000e1dc70 in handle_fatal_signal (sig=6) at /git/mysql-server_dbg/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007fb125c415d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5  0x00007fb125c42cc8 in __GI_abort () at abort.c:90
#6  0x0000000001aedf9b in ut_dbg_assertion_failed (expr=0x2063a70 "trx_state_eq(trx, TRX_STATE_PREPARED)", file=0x2062848 "/git/mysql-server_dbg/storage/innobase/handler/ha_innodb.cc", line=2444) at /git/mysql-server_dbg/storage/innobase/ut/ut0dbg.cc:67
#7  0x00000000018c310a in innodb_replace_trx_in_thd (thd=0x7fb05c419000, new_trx_arg=0x0, ptr_trx_arg=0x0) at /git/mysql-server_dbg/storage/innobase/handler/ha_innodb.cc:2444
#8  0x000000000159c948 in attach_native_trx (thd=0x7fb05c419000) at /git/mysql-server_dbg/sql/xa.cc:1192
#9  0x000000000159c7ce in applier_reset_xa_trans (thd=0x7fb05c419000) at /git/mysql-server_dbg/sql/xa.cc:1131
#10 0x000000000159b81e in Sql_cmd_xa_prepare::execute (this=0x7fb05c42ba48, thd=0x7fb05c419000) at /git/mysql-server_dbg/sql/xa.cc:685
#11 0x0000000001492535 in mysql_execute_command (thd=0x7fb05c419000, first_level=true) at /git/mysql-server_dbg/sql/sql_parse.cc:4645
#12 0x0000000001494305 in mysql_parse (thd=0x7fb05c419000, parser_state=0x7fb127636670) at /git/mysql-server_dbg/sql/sql_parse.cc:5357
#13 0x0000000001489caa in dispatch_command (thd=0x7fb05c419000, com_data=0x7fb127636dc0, command=COM_QUERY) at /git/mysql-server_dbg/sql/sql_parse.cc:1284
#14 0x0000000001488b76 in do_command (thd=0x7fb05c419000) at /git/mysql-server_dbg/sql/sql_parse.cc:852
#15 0x00000000015b2cdb in handle_connection (arg=0x7fb0647ff240) at /git/mysql-server_dbg/sql/conn_handler/connection_handler_per_thread.cc:295
#16 0x00000000017c3aa0 in pfs_spawn_thread (arg=0x7fb0757e7820) at /git/mysql-server_dbg/storage/perfschema/pfs.cc:2192
#17 0x00007fb127038df5 in start_thread (arg=0x7fb127637700) at pthread_create.c:308
#18 0x00007fb125d021ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
[26 Nov 2015 7:37] MySQL Verification Team 
Hello Roel,

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

Thanks,
Umesh
[26 Nov 2015 7:37] MySQL Verification Team 
// 5.7.9  only debug build affected

rm -rf 79417
bin/mysql_install_db --insecure --basedir=/export/umesh/server/binaries/mysql-5.7.9 --datadir=/export/umesh/server/binaries/mysql-5.7.9/79417 -v
bin/mysqld-debug --no-defaults --basedir=/export/umesh/server/binaries/mysql-5.7.9 --datadir=/export/umesh/server/binaries/mysql-5.7.9/79417 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.7.9/79417/log.err 2>&1 &

(gdb) bt
#0  0x00007f64ed7fb771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000001803885 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/mysys/stacktrace.c:247
#2  0x0000000000e45850 in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007f64ec4015d7 in raise () from /lib64/libc.so.6
#5  0x00007f64ec402cc8 in abort () from /lib64/libc.so.6
#6  0x0000000001b4a31b in ut_dbg_assertion_failed (expr=0x22529b8 "total_trx >= trx_sys->n_prepared_trx",
    file=0x2252300 "/export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/storage/innobase/trx/trx0sys.cc", line=1265)
    at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/storage/innobase/ut/ut0dbg.cc:67
#7  0x0000000001b30151 in trx_sys_any_active_transactions () at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/storage/innobase/trx/trx0sys.cc:1265
#8  0x00000000019bcf63 in logs_empty_and_mark_files_at_shutdown () at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/storage/innobase/log/log0log.cc:2047
#9  0x0000000001aea1c3 in innobase_shutdown_for_mysql () at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/storage/innobase/srv/srv0start.cc:2670
#10 0x000000000191cbc0 in innobase_end (hton=0x2f925a0, type=HA_PANIC_CLOSE) at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/storage/innobase/handler/ha_innodb.cc:3797
#11 0x0000000000eb4b03 in ha_finalize_handlerton (plugin=0x30c93d8) at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/sql/handler.cc:780
#12 0x0000000001515489 in plugin_deinitialize (plugin=0x30c93d8, ref_check=true) at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/sql/sql_plugin.cc:980
#13 0x000000000151583b in reap_plugins () at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/sql/sql_plugin.cc:1062
#14 0x0000000001517605 in plugin_shutdown () at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/sql/sql_plugin.cc:1781
#15 0x0000000000e2ff3f in clean_up (print_message=true) at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/sql/mysqld.cc:1291
#16 0x0000000000e3688c in mysqld_main (argc=8, argv=0x2f90a90) at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/sql/mysqld.cc:4951
#17 0x0000000000e2dda4 in main (argc=8, argv=0x7ffe25386a28) at /export/home/pb2/build/sb_0-16729453-1444633651.02/mysql-5.7.9/sql/main.cc:25
(gdb)
[26 Nov 2015 7:38] MySQL Verification Team 
// 5.7.11 - only debug build affected

[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.11: cat docs/INFO_SRC
commit: 6097f7cbf5ac4b4db62696a1e95a76230f884cd3
date: 2015-11-23 21:49:50 +0530
build-date: 2015-11-23 17:29:29 +0100
short: 6097f7c
branch: mysql-5.7

MySQL source 5.7.11

rm -rf 79417
bin/mysql_install_db --insecure --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.11 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.11/79417 -v
bin/mysqld-debug --no-defaults --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.11 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.11/79417 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-advanced-5.7.11/79417/log.err 2>&1 &

(gdb) bt
#0  0x00007fcd92a6c771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000018a36cd in my_write_core (sig=6) at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/mysys/stacktrace.c:247
#2  0x0000000000ebbe1c in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007fcd916725d7 in raise () from /lib64/libc.so.6
#5  0x00007fcd91673cc8 in abort () from /lib64/libc.so.6
#6  0x0000000001bebb23 in ut_dbg_assertion_failed (expr=0x239c388 "total_trx >= trx_sys->n_prepared_trx",
    file=0x239bcc8 "/export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/storage/innobase/trx/trx0sys.cc", line=1265)
    at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/storage/innobase/ut/ut0dbg.cc:67
#7  0x0000000001bd281d in trx_sys_any_active_transactions () at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/storage/innobase/trx/trx0sys.cc:1265
#8  0x0000000001a5dfbd in logs_empty_and_mark_files_at_shutdown () at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/storage/innobase/log/log0log.cc:2080
#9  0x0000000001b8c5da in innobase_shutdown_for_mysql () at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/storage/innobase/srv/srv0start.cc:2669
#10 0x00000000019bce95 in innobase_end (hton=0x3a579c0, type=HA_PANIC_CLOSE) at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/storage/innobase/handler/ha_innodb.cc:3959
#11 0x0000000000f357ef in ha_finalize_handlerton (plugin=0x3b8f500) at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/sql/handler.cc:780
#12 0x00000000015b2e35 in plugin_deinitialize (plugin=0x3b8f500, ref_check=true) at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/sql/sql_plugin.cc:980
#13 0x00000000015b31e7 in reap_plugins () at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/sql/sql_plugin.cc:1062
#14 0x00000000015b4fb1 in plugin_shutdown () at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/sql/sql_plugin.cc:1781
#15 0x0000000000ea60ef in clean_up (print_message=true) at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/sql/mysqld.cc:1296
#16 0x0000000000eaccfd in mysqld_main (argc=8, argv=0x3a55eb0) at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/sql/mysqld.cc:4984
#17 0x0000000000ea3f54 in main (argc=8, argv=0x7ffe19d1dee8) at /export/home/pb2/build/sb_0-17148744-1448296996.98/mysqlcom-pro-5.7.11/sql/main.cc:25
(gdb)
[26 Nov 2015 7:44] MySQL Verification Team 
// 5.6.27 debug/release not affected
[30 Dec 2015 15:51] David Moss 
Thanks for your feedback. This has been fixed in upcoming versions and the following was added to the 5.7.11 change log:

If pseudo_slave_mode was set to 1 while an XA transaction was in the prepare stage, an assert was generated. The fix ensures that changes from 0 to 1 can be made during XA transactions. Note that this variable is solely for internal use by the server.