handle_fatal_signal (sig=11) in rec_offs_n_fields on INSERT query

[Roel Van de Paar]

Thread 1 (LWP 18556):
+bt
#0 0x000000363720c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000006874ae in handle_fatal_signal (sig=11) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/signal_handler.cc:251
#2 <signal handler called>
#3 rec_offs_n_fields (offsets=0x0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/include/rem0rec.ic:940
#4 0x0000000000ad9092 in rec_offs_validate (rec=0x7ff7f1546cc0 "\b\324\036\314\367\177", index=0x7ff7b810db58, offsets=0x0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/include/rem0rec.ic:960
#5 0x0000000000add4e9 in row_log_table_low (rec=0x7ff7f1546cc0 "\b\324\036\314\367\177", index=0x7ff7b810db58, offsets=0x0, insert=true, old_pk=0x0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0log.cc:766
#6 0x0000000000aba764 in row_ins_clust_index_entry_low (flags=0, mode=<optimized out>, index=0x7ff7b810db58, n_uniq=<optimized out>, entry=0x7ff7cc1faa78, n_ext=0, thr=0x7ff7cc1ed408) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0ins.cc:2566
#7 0x0000000000abd685 in row_ins_clust_index_entry (index=0x7ff7b810db58, entry=0x7ff7cc1faa78, thr=0x7ff7cc1ed408, n_ext=0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0ins.cc:2918
#8 0x0000000000abdc67 in row_ins_index_entry (thr=0x7ff7cc1ed408, entry=0x7ff7cc1faa78, index=0x7ff7b810db58) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0ins.cc:3012
#9 row_ins_index_entry_step (thr=0x7ff7cc1ed408, node=0x7ff7cc1ed168) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0ins.cc:3089
#10 row_ins (thr=0x7ff7cc1ed408, node=0x7ff7cc1ed168) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0ins.cc:3229
#11 row_ins_step (thr=0x7ff7cc1ed408) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0ins.cc:3354
#12 0x0000000000ad090c in row_insert_for_mysql (mysql_rec=<optimized out>, prebuilt=<optimized out>) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0mysql.cc:1313
#13 0x0000000000a0dace in ha_innobase::write_row (this=0x7ff7cc00cac0, record=0x7ff7cc2601a0 "\374\004") at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/handler/ha_innodb.cc:6940
#14 0x00000000005ba824 in handler::ha_write_row (this=0x7ff7cc00cac0, buf=0x7ff7cc2601a0 "\374\004") at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/handler.cc:7448
#15 0x0000000000704e40 in write_record (thd=0x226ab80, table=0x7ff7cc00c1d0, info=0x7ff7f1547260, update=0x7ff7f15471e0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_insert.cc:1935
#16 0x000000000070c949 in mysql_insert (thd=0x226ab80, table_list=0x7ff7cc01c458, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_insert.cc:1073
#17 0x0000000000724bf9 in mysql_execute_command (thd=0x226ab80) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_parse.cc:3649
#18 0x0000000000728628 in mysql_parse (thd=0x226ab80, rawbuf=0x226cf40 "P\303\070\001", length=<optimized out>, parser_state=<optimized out>) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_parse.cc:6479
#19 0x000000000072978c in dispatch_command (command=COM_QUERY, thd=0x226ab80, packet=0x7ff7f1548a90 "\200\253&\002", packet_length=65) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_parse.cc:1355
#20 0x000000000072a987 in do_command (thd=0x226ab80) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_parse.cc:1049
#21 0x00000000006ee1ef in do_handle_one_connection (thd_arg=<optimized out>) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_connect.cc:1615
#22 0x00000000006ee2d7 in handle_one_connection (arg=0x226ab80) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_connect.cc:1526
#23 0x00000000009e033a in pfs_spawn_thread (arg=0x21ddc90) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/perfschema/pfs.cc:1858
#24 0x0000003637207851 in start_thread () from /lib64/libpthread.so.0
#25 0x0000003636ee890d in clone () from /lib64/libc.so.6

===========

2013-09-16 14:50:06 18529 [Note] /ssd/Percona-Server-5.6.13-rc60.5-437-debug.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.6.13-rc60.5-debug-log' socket: '/ssd//128776/current1_8/tmp/master.sock' port: 13140 Percona Server with XtraDB (GPL), Release rc60.5, Revision 437-debug
11:50:49 UTC - mysqld got signal 11 ;
[...]
Query (7ff7cc01c320): INSERT INTO t7 VALUES ( '2008' , '2008' , 4 , '09:06:16.057152' )
Connection ID (thread ID): 9
Status: NOT_KILLED

[Roel Van de Paar (roel11)]

RQG @ 909 <email address hidden>
PS @ Percona-Server-5.6.13-rc60.5-437-debug.Linux.x86_64 (5.6-QA)

[Roel Van de Paar (roel11)]

(gdb) f 11
#11 row_ins_step (thr=0x7ff7cc1ed408) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0ins.cc:3354
3354 err = row_ins(node, thr);
(gdb) p trx->fake_changes
$1 = 1

[Laurynas Biveinis (laurynas-biveinis)]

Pushing a provisional fix.

[Roel Van de Paar (roel11)]

fake changes in alpha, so no 56qual

[Ramesh Sivaraman (rameshvs02)]

Got the testcase for this issue, but we need to use multi thread pquery to reproduce the issue.

*** Testcase

DROP DATABASE test;CREATE DATABASE test;USE test;
CREATE TABLE t3(c1 BINARY(10) NOT NULL);
ALTER TABLE t3 ENGINE=InnoDB;
SET innodb_fake_changes=1;
INSERT INTO t3 () VALUES (); ;

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!)
$ ./{epoch}_init # Initializes the data dir
$ ./{epoch}_start # Starts mysqld
$ ./{epoch}_cl # To check mysqld is up
$ ./{epoch}_run_pquery # Run the testcase (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.

[Ramesh Sivaraman (rameshvs02)]

GDB info

[Ramesh Sivaraman (rameshvs02)]

Full stack

[Roel Van de Paar (roel11)]

Interestingly, executing the 2015-02-19 testcase directly at the CLI produces

mysql> INSERT INTO t3 () VALUES ();
ERROR 1180 (HY000): Got error 131 during COMMIT

[Roel Van de Paar (roel11)]

2015-02-19 testcase includes old pquery ({epoch}_pquery) binary which had memory alloc issues. New one can be used from lp:percona-qa/pquery/pquery-ps

[Krunal Bauskar (krunal-bauskar)]

commit 0c123f6749cb90e17a3aeb37db5f8861e116a20c
Author: Krunal Bauskar <email address hidden>
Date: Fri Sep 11 08:33:13 2015 +0530

    - bug#1226532 : handle_fatal_signal (sig=11) in rec_offs_n_fields on INSERT query

      A multi-threaded workload can cause a thread to become active doing insert when
      an index is marked for online-ddl activity.

      With fake-change enabled online-ddl logging should be avoided.
      Note: We just need to do bare minimum undo-logging for transaction to rollback

PR#159

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1419