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

[15 Jun 2007 23:18] Arjen Lentz
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.
[22 Jun 2007 6:51] Sveta Smirnova
test case

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

[22 Jun 2007 6:53] Sveta Smirnova
master options

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

[22 Jun 2007 6:54] Sveta Smirnova
slave options file

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

[22 Jun 2007 6:56] Sveta Smirnova
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
[27 Jun 2007 8:28] Sveta Smirnova
Bug exists in 5.1 BK as well if master started with option --binlog-format=STATEMENT
[30 Jul 2007 23:21] Arjen Lentz
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
[31 Jul 2007 2:48] Valeriy Kravchuk
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.
[31 Jul 2007 3:41] Arjen Lentz
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 ?
[31 Jul 2007 8:42] Sergey Vojtovich
Stealing this one per discussion with Mats.
[31 Jul 2007 10:49] Bugs System
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.
[31 Jul 2007 13:13] Sinisa Milivojevic
Arjen,

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

So, don't worry ....... ;o)
[2 Aug 2007 4:25] Arjen Lentz
Added regression tag.
[2 Aug 2007 4:28] Arjen Lentz
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
[6 Aug 2007 18:13] Bugs System
Pushed into 5.1.21-beta
[7 Aug 2007 14:41] Paul Dubois
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?
[14 Aug 2007 7:59] Bugs System
Pushed into 5.0.48
[24 Aug 2007 9:42] Jon Stephens
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.