MySQL Bugs: #29152: INSERT DELAYED does not use concurrent

Bug #29152	INSERT DELAYED does not use concurrent_insert on slave
Submitted:	15 Jun 2007 23:18	Modified:	24 Aug 2007 9:42
Reporter:	Arjen Lentz	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.0.24, 5.0 BK, 5.1 BK	OS:	Linux (2.6.5 x86_64, all)
Assigned to:	Sergey Vojtovich	CPU Architecture:	Any
Tags:	bfsm_2007_06_28, concurrent, DELAYED, insert, myisam, regression, replication, slave

Description:
- Master uses INSERT DELAYED on MyISAM table.
- Slave executes query but ignores DELAYED (this makes sense, otherwise the slave data would not be consistent/serialized).
- INSERTs without DELAYED executes on the slave use concurrent insert (concurrent_insert=1 globally).
- INSERTs that had DELAYED (from the master) appear to not be using concurrent insert.

No updates/deletes are being done on the table.

How to repeat:
This is observable under load on a customer production system.

Suggested fix:
So there appears to be a logic but in there somewhere, so that when a master query had DELAYED, the server does not use the concurrent insert logic on the slave. Those two should not be related.

A peek in the source code may be quicker & more informative than manufacturing a setup to reproduce this.

test case

Attachment: rpl_bug29152.test (application/octet-stream, text), 276 bytes.

master options

Attachment: rpl_bug29152-master.opt (application/octet-stream, text), 22 bytes.

slave options file

Attachment: rpl_bug29152-slave.opt (application/octet-stream, text), 22 bytes.

Thank you for the report.

Verified as described using gdb.

To repeat copy attached test case and its options files to mysql-test/t dirctory. Then run `./mysql-test-run.pl --record --manual-gdb rpl_bug29152`

In slave gdb add 2 breakpoints: log_event.cc:1805 and sql_insert.cc:921

Then run as following:

6005      DBUG_ENTER("mysql_parse");
(gdb) b log_event.cc:1805
Breakpoint 2 at 0x14b489: file log_event.cc, line 1805.
(gdb) b sql_insert.cc:921
Breakpoint 3 at 0x1244a5: file sql_insert.cc, line 921.
(gdb) c
Continuing.
070622 10:49:50 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log '/Users/apple/bk/mysql-5.0/mysql-test/var/log/slave-relay-bin.000001' position: 4
070622 10:49:50 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:9306',  replication started in log 'FIRST' at position 4
070622 10:49:50 [Note] next log '/Users/apple/bk/mysql-5.0/mysql-test/var/log/slave-relay-bin.000002' is currently active
070622 10:49:50 [Note] next log '/Users/apple/bk/mysql-5.0/mysql-test/var/log/slave-relay-bin.000003' is currently active
[Switching to process 4745 thread 0x2703]

Breakpoint 2, Query_log_event::exec_event (this=0x41045f8, rli=0x4844e98, query_arg=0x41046a1 "DROP TABLE IF EXISTS test.t1", q_len_arg=28) at log_event.cc:1805
1805        thd->query= (char*)query_arg;
(gdb) c
Continuing.

Breakpoint 2, Query_log_event::exec_event (this=0x41045f8, rli=0x4844e98, query_arg=0x4104d31 "CREATE TABLE t1 (a VARCHAR(255))", q_len_arg=32) at log_event.cc:1805
1805        thd->query= (char*)query_arg;
(gdb) c
Continuing.

Breakpoint 2, Query_log_event::exec_event (this=0x41045f8, rli=0x4844e98, query_arg=0x41046a1 "insert into t1 values('foo'), ('bar'), ('baz')", q_len_arg=46) at log_event.cc:1805
1805        thd->query= (char*)query_arg;
(gdb) c
Continuing.

Breakpoint 3, mysql_insert (thd=0x485ac18, table_list=0x485c858, fields=@0x485bd38, values_list=@0x485bd5c, update_fields=@0x485bd50, update_values=@0x485bd44, duplic=DUP_ERROR, ignore=false) at sql_insert.cc:921
921           if (lock_type ==  TL_WRITE_CONCURRENT_INSERT && changed)
(gdb) print lock_type
$1 = TL_WRITE_CONCURRENT_INSERT
(gdb) c
Continuing.

Breakpoint 2, Query_log_event::exec_event (this=0x4104d28, rli=0x4844e98, query_arg=0x41046a1 "insert delayed into t1 values('oof'), ('rab'), ('zab')", q_len_arg=54) at log_event.cc:1805
1805        thd->query= (char*)query_arg;
(gdb) c
Continuing.

Program received signal SIGUSR1, User defined signal 1.
[Switching to process 4745 thread 0x2503]
0x9001038c in read ()
(gdb) c
Continuing.
[Switching to process 4745 thread 0x2703]

Breakpoint 2, Query_log_event::exec_event (this=0x4104d28, rli=0x4844e98, query_arg=0x41046a1 "insert delayed into t1 values('oof'), ('rab'), ('zab')", q_len_arg=54) at log_event.cc:1805
1805        thd->query= (char*)query_arg;
(gdb) c
Continuing.

Breakpoint 3, mysql_insert (thd=0x485ac18, table_list=0x485c858, fields=@0x485bd38, values_list=@0x485bd5c, update_fields=@0x485bd50, update_values=@0x485bd44, duplic=DUP_ERROR, ignore=false) at sql_insert.cc:921
921           if (lock_type ==  TL_WRITE_CONCURRENT_INSERT && changed)
(gdb) print lock_type
$2 = TL_WRITE
(gdb) c
Continuing.

Breakpoint 2, Query_log_event::exec_event (this=0x4104d28, rli=0x4844e98, query_arg=0x4104691 "insert into t1 values('foo'), ('bar'), ('baz')", q_len_arg=46) at log_event.cc:1805
1805        thd->query= (char*)query_arg;
(gdb) c
Continuing.

Breakpoint 3, mysql_insert (thd=0x485ac18, table_list=0x485c858, fields=@0x485bd38, values_list=@0x485bd5c, update_fields=@0x485bd50, update_values=@0x485bd44, duplic=DUP_ERROR, ignore=false) at sql_insert.cc:921
921           if (lock_type ==  TL_WRITE_CONCURRENT_INSERT && changed)
(gdb) print lock_type
$3 = TL_WRITE_CONCURRENT_INSERT
(gdb) 

You can see in case of INSERT DELAYED TL_WRITE is using instead of TL_WRITE_CONCURRENT_INSERT

Bug exists in 5.1 BK as well if master started with option --binlog-format=STATEMENT

May I inquire what the status of this bug is? It is a regression in 5.0, seriously impacts slave behaviour on busy systems...
thanks

Arjen,

This bug is still just verified, but it was already discussed, it is assigned, and should be fixed before MySQL announce 5.1 RC. I'd expect some status changes in August.

Valeriy, thanks for your answer - but I'm a tad confused.
Since this is a regression in 5.0, why is it not being fixed within 5.0 ?

Stealing this one per discussion with Mats.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/31883

ChangeSet@1.2487, 2007-07-31 19:40:36+05:00, svoj@mysql.com +1 -0
  BUG#29152 - INSERT DELAYED does not use concurrent_insert on slave
  
  INSERT DELAYED on a replication slave was converted to regular INSERT,
  whereas it should try concurrent INSERT first.
  
  With this patch we try to convert delayed insert to concurrent insert on
  a replication slave. If it is impossible for some reason, we fall back to
  regular insert.
  
  No test case for this fix. I do not see anything indicating this is
  regression - we behave this way since Nov 2000.

Arjen,

A fix for this bug has already be committed for 5.0.

So, don't worry ....... ;o)

Added regression tag.

Sorry Sinisa, but I can't see that. The bugs system says that the target version is 5.1.22
I expect any bugfix to also be pushed into later versions, but I can't presume backporting.
So if the system tells me 5.1.22, I take it that it will not be put in to 5.0.
If you say otherwise, please update the appropriate public fields for this bug.
Thanks

Pushed into 5.1.21-beta

Noted in 5.1.21 changelog.

INSERT DELAYED statements on a master server are replicated as
non-DELAYED inserts on slaves (which is normal, to preserve
serialization), but the inserts on the slave did not use concurrent 
inserts. Now INSERT DELAYED on a slave is converted to a concurrent
insert when possible, and to a normal insert otherwise.

Resetting report to NDI; will this fix get pushed to 5.0?

Pushed into 5.0.48

Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Now also documented in 5.0.48 changelog.