transaction keeps on refreshing fake-change setting even during its lifetime (where-in trx should honor and lock setting at start only as per the semantics)

[Roel Van de Paar]

2013-09-16 17:14:17 14022 [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_4/tmp/master.sock' port: 13060 Percona Server with XtraDB (GPL), Release rc60.5, Revision 437-debug
InnoDB: error in sec index entry update in
InnoDB: index `c23` of table `test`.`table1_innodb_default_char`
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 1; hex 8f; asc ;;
 1: len 1; hex 20; asc ;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 1; hex 80; asc ;;
 1: len 1; hex 20; asc ;;

TRANSACTION 29504, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 16, OS thread handle 0x7f4e3a54a700, query id 5470 127.0.0.1 root update
REPLACE INTO `view_table1_innodb_default_char` ( `c3` ) VALUES ( 'for' )

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
2013-09-16 17:16:07 7f4e3a54a700 InnoDB: Assertion failure in thread 139973962802944 in file row0upd.cc line 1803
InnoDB: Failing assertion: 0
InnoDB: We intentionally generate a memory trap.
[...]
Query (7f4dd8004c50): REPLACE INTO `view_table1_innodb_default_char` ( `c3` ) VALUES ( 'for' )
Connection ID (thread ID): 16
Status: NOT_KILLED

===========

Thread 1 (LWP 14270):
+bt
#0 0x000000363720c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000006874ae in handle_fatal_signal (sig=6) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/signal_handler.cc:251
#2 <signal handler called>
#3 0x0000003636e328a5 in raise () from /lib64/libc.so.6
#4 0x0000003636e34085 in abort () from /lib64/libc.so.6
#5 0x0000000000af951e in row_upd_sec_index_entry (node=<optimized out>, thr=0x7f4dd805a310) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0upd.cc:1803
#6 0x0000000000afbe77 in row_upd_sec_step (thr=0x7f4dd805a310, node=0x7f4dd8052100) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0upd.cc:1875
#7 row_upd (thr=0x7f4dd805a310, node=0x7f4dd8052100) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0upd.cc:2607
#8 row_upd_step (thr=0x7f4dd805a310) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0upd.cc:2724
#9 0x0000000000acce5b in row_update_for_mysql (mysql_rec=<optimized out>, prebuilt=0x7f4dd80506e8) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0mysql.cc:1729
#10 0x0000000000a04e87 in ha_innobase::delete_row (this=0x7f4dd804aef0, record=0x7f4dd800c098 "\377\377\377\377\217") at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/handler/ha_innodb.cc:7529
#11 0x00000000005c1375 in handler::ha_delete_row (this=0x7f4dd804aef0, buf=0x7f4dd800c098 "\377\377\377\377\217") at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/handler.cc:7508
#12 0x00000000007050ed in write_record (thd=0x3168880, table=0x7f4dd804a600, info=0x7f4e3a548260, update=0x7f4e3a5481e0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_insert.cc:1890
#13 0x000000000070c949 in mysql_insert (thd=0x3168880, table_list=0x7f4dd8004e28, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_REPLACE, ignore=false) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_insert.cc:1073
#14 0x0000000000724bf9 in mysql_execute_command (thd=0x3168880) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_parse.cc:3649
#15 0x0000000000728628 in mysql_parse (thd=0x3168880, rawbuf=0x316ac40 "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
#16 0x000000000072978c in dispatch_command (command=COM_QUERY, thd=0x3168880, packet=0x7f4e3a549a90 "\200\210\026\003", packet_length=72) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_parse.cc:1355
#17 0x000000000072a987 in do_command (thd=0x3168880) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_parse.cc:1049
#18 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
#19 0x00000000006ee2d7 in handle_one_connection (arg=0x3168880) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/sql/sql_connect.cc:1526
#20 0x00000000009e033a in pfs_spawn_thread (arg=0x3133d30) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/perfschema/pfs.cc:1858
#21 0x0000003637207851 in start_thread () from /lib64/libpthread.so.0
#22 0x0000003636ee890d in clone () from /lib64/libc.so.6

[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 5
#5 0x0000000000af951e in row_upd_sec_index_entry (node=<optimized out>, thr=0x7f4dd805a310) at /bzr/5.6-QA_dbg/Percona-Server-5.6.13-rc60.5/storage/innobase/row/row0upd.cc:1803
1803 ut_ad(0);
(gdb) p trx->fake_changes
$1 = 0

[Roel Van de Paar (roel11)]

Adding a second occurrence, which is preceded with errors like these:

----------------------------
2013-09-16 17:13:06 12583 [Warning] InnoDB could not find index c4 key no 0 for table tmp/#sql3127_9_19 through its index translation table
2013-09-16 17:13:06 12583 [ERROR] Cannot find index c4 in InnoDB index translation table.
[...]
2013-09-16 17:13:12 12583 [Warning] InnoDB could not find index c4 key no 0 for table tmp/#sql3127_9_1c through its index translation table
InnoDB: error in sec index entry update in
InnoDB: index `c16` of table `test`.`table1_innodb_compressed_char`
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 1; hex ff; asc ;;
 1: len 1; hex 20; asc ;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 1; hex 00; asc ;;
 1: len 1; hex 20; asc ;;

TRANSACTION 93340, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 9, OS thread handle 0x7f07e4855700, query id 8688 127.0.0.1 root update
REPLACE INTO `table1_innodb_compressed_char` ( `c33` ) VALUES ( 'q' )

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
2013-09-16 17:13:20 7f07e4855700 InnoDB: Assertion failure in thread 139671875442432 in file row0upd.cc line 1803
InnoDB: Failing assertion: 0
[...]
Query (7f07c00ecce0): REPLACE INTO `table1_innodb_compressed_char` ( `c33` ) VALUES ( 'q' )
Connection ID (thread ID): 9
Status: NOT_KILLED
----------------------------

The aforementioned errors are a like those in bug 1226525, however the final assert (and final preceding errors) are like the ones in this bug.

[Roel Van de Paar (roel11)]

Hmm, duplicate of bug 1225824 ?

[Roel Van de Paar (roel11)]

From comment #9, as far as these are concerned:

2013-09-16 17:13:06 12583 [Warning] InnoDB could not find index c4 key no 0 for table tmp/#sql3127_9_19 through its index translation table
2013-09-16 17:13:06 12583 [ERROR] Cannot find index c4 in InnoDB index translation table.

These are now logged as bug 1233431 with a full testcase. This may be completely unrelated to DATA TUPLE errors.

[Roel Van de Paar (roel11)]

Marked bug 1225824 as a duplicate of this one

[Roel Van de Paar (roel11)]

REPLACE INTO `view_table1_innodb_default_char` ( `c3` ) VALUES ( 'for' )
REPLACE INTO `table1_innodb_compressed_char` ( `c33` ) VALUES ( 'q' )

It's on compressed and non-compressed tables, apparently always on REPLACE INTO.

[Ramesh Sivaraman (rameshvs02)]

Got testcase ****

DROP DATABASE test;CREATE DATABASE test;USE test;
xa start'','';
CREATE TEMPORARY TABLE t1(a INT,b INT,INDEX z(a));
savepoint x;
INSERT INTO t1 VALUES(3,2);
update t1 set a=a + 5;
SET innodb_fake_changes=1;
rollback to savepoint x;
UPDATE t1 SET a=2;

Seems it is similar assertion.

***** GDB info

#0 0x00007f8988d3b771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000ab7586 in my_write_core (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/mysys/stacktrace.c:422
#2 0x000000000072f9ff in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x00007f898793f5c9 in raise () from /lib64/libc.so.6
#5 0x00007f8987940cd8 in abort () from /lib64/libc.so.6
#6 0x0000000000c1864e in row_upd_sec_index_entry (node=0x7f88cb077ad0, thr=0x7f88cb077d80) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/row/row0upd.cc:1794
#7 0x0000000000c18929 in row_upd_sec_step (node=0x7f88cb077ad0, thr=0x7f88cb077d80) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/row/row0upd.cc:1866
#8 0x0000000000c1a2b6 in row_upd (node=0x7f88cb077ad0, thr=0x7f88cb077d80) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/row/row0upd.cc:2569
#9 0x0000000000c1a5b5 in row_upd_step (thr=0x7f88cb077d80) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/row/row0upd.cc:2686
#10 0x0000000000bdaa0a in row_update_for_mysql (mysql_rec=0x7f88cb09a820 "\371\b", prebuilt=0x7f88cb077078) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/row/row0mysql.cc:1791
#11 0x0000000000ad7990 in ha_innobase::update_row (this=0x7f88cb0aa510, old_row=0x7f88cb09a820 "\371\b", new_row=0x7f88cb09a810 "\371\002") at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/storage/innobase/handler/ha_innodb.cc:7768
#12 0x000000000064cc99 in handler::ha_update_row (this=0x7f88cb0aa510, old_data=0x7f88cb09a820 "\371\b", new_data=0x7f88cb09a810 "\371\002") at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/handler.cc:7680
#13 0x0000000000879052 in mysql_update (thd=0x7f88f43f2000, table_list=0x7f88cb01f0e8, fields=..., values=..., conds=0x0, order_num=0, order=0x0, limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7f898932c8d0, updated_return=0x7f898932c8c8) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_update.cc:818
#14 0x00000000007e4d76 in mysql_execute_command (thd=0x7f88f43f2000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.21-69.0/sql/sql_parse.cc:3715
#15 0x0000...

[Krunal Bauskar (krunal-bauskar)]

"The effective unit is each transaction. The behavior is decided at the start of the each one and never changed during the transaction " ... this was being missed and so the issue.