MySQL Bugs: #35817: read_set not updated correctly by trigger for some queries

Bug #35817	read_set not updated correctly by trigger for some queries
Submitted:	3 Apr 2008 20:48	Modified:	26 Apr 2013 12:23
Reporter:	Tim Clark	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S2 (Serious)
Version:	5.1.23, 5.1.67, 5.7.1	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	primary key, read_set, trigger

Description:
The table->read_set bitmap is not updated correctly when optimization based on a primary key is done and a trigger is invoked. This is a problem for storage engines which rely on read_set to optimize record fetches, because they may not know to read the fields which are required by the trigger. Instead, they only fetch the fields that are needed to satisfy the original query.

Please see "How to repeat:" for the detailed logic involved.

How to repeat:
This was discovered when running against a storage engine that is still under development. However, the following queries can be executed against MyISAM, and a debugger can be used to see the incorrect flow.

Incorrect:
Set a breakpoint in ha_myisam::index_read_idx_map(). When t1.id is a PRIMARY KEY, and the DELETE statement below is executed, (after two spurious halts for the "proc" table), it can be seen that table->read_set->bitmap is equal to 0x0001 indicating only the first field (t1.id) is requested. Storage engines which honor read_set will not retrieve the value of t1.operation and thus will not have the data needed to satisfy the trigger.

Correct:
Set a breakpoint in ha_myisam::index_read_map(). When t1.id is not a primary key (but covered by an index), and the DELETE statement is executed, it can be seen that table->read_set->bitmap is equal to 0x0003 indicating both fields are requested.

This can be further confirmed by executing the DELETE statement with a breakpoint also in Table_triggers_list::mark_fields_used(). It can be seen that when t1.id is a primary key, mark_fields_used() is called *after* index_read_idx_map() has been called. When t1.id is a normal index, mark_fields_used() is called *before* index_read_map(). Clearly, the latter behavior is correct.

# Incorrect logic
create table t1 (id int primary key , operation varchar(255));
# -- OR --
# Correct logic
create table t1 (id int , operation varchar(255), index(id));

create table t2 (id int primary key);
create table t1_op_log(operation varchar(255));
create trigger trg_bd before delete on t1
for each row insert into t1_op_log (operation)
  values (concat("Before DELETE, old=", old.operation));
create trigger trg_ad after delete on t1
for each row insert into t1_op_log (operation)
  values (concat("After DELETE, old=", old.operation));

insert into t1 (id, operation) values (1, "INSERT for multi-DELETE");
insert into t1 values(2,""),(3,""),(4,""),(5,""),(6,""),(7,""),(8,""),(9,""),(10,""),(11,""),(12,""),(13,""),(14,"");
insert into t2 (id) values (1);

delete t1.*, t2.* from t1, t2 where t1.id=1;

Suggested fix:
Table_triggers_list::mark_fields_used() should always be called before doing any reads from a table participating in a trigger.

Verified as described.

Simplified test case:

--disable_warnings
drop table if exists t1;
drop table if exists t1_op_log;
drop trigger if exists trg_bd;
--enable_warnings

create table t1 (id int primary key , operation varchar(255));
#create table t1 (id int, operation varchar(255), index(id));
create table t1_op_log(operation varchar(255));

create trigger trg_bd before delete on t1
for each row insert into t1_op_log (operation)
  values (concat("Before DELETE, old=", old.operation));

insert into t1 values (1, "INSERT for multi-DELETE"), (2, "");

delete t1.* from t1 where t1.id=1;

drop trigger trg_bd;
drop table t1_op_log;
drop table t1;

Timour, I don't know how to fix it. Either join_read_const shouldn't be run
in presence of triggers, or it should read all involved columns.
Jon Olav will provide background information.
Let's discuss on IRC after that.

This problem concerns the optimizer, more specifically the optimization of queries using constant tables.

In the initial phase of optimization, constant tables are evaluated to find the constant value in order to put that value into the query. This happens in make_join_statistics() called from sql_select.cc:1613

At this point in time, the read_set bitmap has not been completely set up to cover triggers. This happens in mark_fields_used() which is called from initialize_tables() which is again called from sql_select.cc:1623 (i.e. after 
make_join_statistics())

This bug is much easily repeatable if use one of supported storage engines which use read_set. For example, Federated.

Slightly modified test case:

--source include/federated.inc
connection slave;

create table federated.t1 (id int primary key , operation varchar(255));
#create table t1 (id int , operation varchar(255), index(id));

create table federated.t2 (id int primary key);
create table federated.t1_op_log(operation varchar(255));

connection master;

--eval create table t1 (id int primary key , operation varchar(255)) ENGINE=FEDERATED DEFAULT CHARSET=utf8 CONNECTION='mysql://root@127.0.0.1:$SLAVE_MYPORT/federated/t1'
#create table t1 (id int , operation varchar(255), index(id));

--eval create table t2 (id int primary key) ENGINE=FEDERATED DEFAULT CHARSET=utf8 CONNECTION='mysql://root@127.0.0.1:$SLAVE_MYPORT/federated/t2'
--eval create table t1_op_log(operation varchar(255)) ENGINE=FEDERATED DEFAULT CHARSET=utf8 CONNECTION='mysql://root@127.0.0.1:$SLAVE_MYPORT/federated/t1_op_log'
create trigger trg_bd before delete on t1
for each row insert into t1_op_log (operation)
  values (concat("Before DELETE, old=", old.operation));
create trigger trg_ad after delete on t1
for each row insert into t1_op_log (operation)
  values (concat("After DELETE, old=", old.operation));

insert into t1 (id, operation) values (1, "INSERT for multi-DELETE");
insert into t1 values(2,""),(3,""),(4,""),(5,""),(6,""),(7,""),(8,""),(9,""),(10,""),(11,""),(12,""),(13,""),(14,"");
insert into t2 (id) values (1);

delete t1.*, t2.* from t1, t2 where t1.id=1;

select * from t1_op_log;

Other storage engines, which follow read_set are Archive and Perfschema

5.7.1 fails with following backtrace:

Core was generated by `/home/sveta/src/mysql-trunk/sql/mysqld --defaults-group-suffix=.1 --defaults-fi'.
Program terminated with signal 6, Aborted.
#0  0x0000003a8540c69c in pthread_kill () from /lib64/libpthread.so.0
#0  0x0000003a8540c69c in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000a7f6d7 in my_write_core (sig=6) at /home/sveta/src/mysql-trunk/mysys/stacktrace.c:258
#2  0x000000000071cbab in handle_fatal_signal (sig=6) at /home/sveta/src/mysql-trunk/sql/signal_handler.cc:248
#3  <signal handler called>
#4  0x0000003a850328a5 in raise () from /lib64/libc.so.6
#5  0x0000003a85034085 in abort () from /lib64/libc.so.6
#6  0x0000003a8502ba1e in __assert_fail_base () from /lib64/libc.so.6
#7  0x0000003a8502bae0 in __assert_fail () from /lib64/libc.so.6
#8  0x0000000000aa014a in ha_federated::position (this=0x7f00fc00a4d0, record=0x7f00fc00a930 "\376\001") at /home/sveta/src/mysql-trunk/storage/federated/ha_federated.cc:2716
#9  0x00000000009750c4 in multi_delete::send_data (this=0x7f00fc006b80, values=...) at /home/sveta/src/mysql-trunk/sql/sql_delete.cc:799
#10 0x000000000079a548 in end_send (join=0x7f00fc034830, join_tab=0x7f00fc03af70, end_of_records=false) at /home/sveta/src/mysql-trunk/sql/sql_executor.cc:2750
#11 0x0000000000797a0a in evaluate_join_record (join=0x7f00fc034830, join_tab=0x7f00fc03ac70) at /home/sveta/src/mysql-trunk/sql/sql_executor.cc:1601
#12 0x0000000000796f7d in sub_select (join=0x7f00fc034830, join_tab=0x7f00fc03ac70, end_of_records=false) at /home/sveta/src/mysql-trunk/sql/sql_executor.cc:1276
#13 0x00000000007968c1 in do_select (join=0x7f00fc034830) at /home/sveta/src/mysql-trunk/sql/sql_executor.cc:941
#14 0x00000000007947fa in JOIN::exec (this=0x7f00fc034830) at /home/sveta/src/mysql-trunk/sql/sql_executor.cc:191
#15 0x00000000007e63b4 in mysql_execute_select (thd=0x3320c60, select_lex=0x3323510, free_join=true) at /home/sveta/src/mysql-trunk/sql/sql_select.cc:1100
#16 0x00000000007e66cb in mysql_select (thd=0x3320c60, tables=0x7f00fc0058b8, wild_num=0, fields=..., conds=0x7f00fc006580, order=0x0, group=0x0, having=0x0, select_options=3489926016, result=0x7f00fc006b80, unit=0x3322ed8, select_lex=0x3323510) at /home/sveta/src/mysql-trunk/sql/sql_select.cc:1221
#17 0x00000000007baee9 in mysql_execute_command (thd=0x3320c60) at /home/sveta/src/mysql-trunk/sql/sql_parse.cc:3537
#18 0x00000000007c1d49 in mysql_parse (thd=0x3320c60, rawbuf=0x7f00fc004c90 "delete t1.*, t2.* from t1, t2 where t1.id=1", length=43, parser_state=0x7f013018e670) at /home/sveta/src/mysql-trunk/sql/sql_parse.cc:6123
#19 0x00000000007b5601 in dispatch_command (command=COM_QUERY, thd=0x3320c60, packet=0x3324951 "delete t1.*, t2.* from t1, t2 where t1.id=1", packet_length=43) at /home/sveta/src/mysql-trunk/sql/sql_parse.cc:1336
#20 0x00000000007b4766 in do_command (thd=0x3320c60) at /home/sveta/src/mysql-trunk/sql/sql_parse.cc:1034
#21 0x000000000078a4ec in do_handle_one_connection (thd_arg=0x3320c60) at /home/sveta/src/mysql-trunk/sql/sql_connect.cc:976
#22 0x0000000000789fc8 in handle_one_connection (arg=0x3320c60) at /home/sveta/src/mysql-trunk/sql/sql_connect.cc:892
#23 0x0000000000d66b59 in pfs_spawn_thread (arg=0x317a710) at /home/sveta/src/mysql-trunk/storage/perfschema/pfs.cc:1852
#24 0x0000003a85407851 in start_thread () from /lib64/libpthread.so.0
#25 0x0000003a850e811d in clone () from /lib64/libc.so.6

Neeraj X Bisht:

The reason for the test case crash is different and has been reported elsewhere.

Not able to reproduce with NDB.