MySQL Bugs: #54914: InnoDB: performance drop with innodb_change

Bug #54914	InnoDB: performance drop with innodb_change_buffering=all
Submitted:	30 Jun 2010 13:08	Modified:	26 Oct 2010 21:52
Reporter:	Alexey Stroganov	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S5 (Performance)
Version:	5.5.5	OS:	Any
Assigned to:	Marko Mäkelä	CPU Architecture:	Any
Tags:	ibuf, ibuf, ibuf, ibuf, ibuf_mutex, ibuf_mutex, innodb, innodb, innodb, innodb

Description:
While running mysql-bench suite we observed drop in performance in several tests
that perform operations on tables that have many secondary keys:

CREATE TABLE bench1 (
  field1 tinyint(4) NOT NULL,
  field_search tinyint(4) NOT NULL,
  field2 mediumint(9) NOT NULL,
  field3 smallint(6) NOT NULL,
  field4 char(16) NOT NULL,
  field5 int(11) NOT NULL,
  field6 float NOT NULL,
  field7 double NOT NULL,
  field8 char(6) NOT NULL,
  field9 char(6) NOT NULL,
  field10 char(6) NOT NULL,
  field11 char(6) NOT NULL,
  field12 char(6) NOT NULL,
  field13 char(6) NOT NULL,
  field14 char(6) NOT NULL,
  field15 char(6) NOT NULL,
  field16 char(6) NOT NULL,
  PRIMARY KEY  (field1,field2,field3,field4,field5,field6,
                field7,field8,field9,field10,field11,field12,
                field13,field14,field15,field16),
  KEY index2 (field_search),
  KEY index3 (field3),
  KEY index4 (field4),
  KEY index5 (field5),
  KEY index6 (field6),
  KEY index7 (field7),
  KEY index8 (field8),
  KEY index9 (field9),
  KEY index10 (field10),
  KEY index11 (field11),
  KEY index12 (field12),
  KEY index13 (field13),
  KEY index14 (field14),
  KEY index15 (field15),
  KEY index16 (field16)
)
Query:
update bench1 set field5=$opt_num where field_search=$i

5.5.3/iplugin106
Time for update_of_primary_key_many_keys (none:50):    175 wallclock secs
Time for update_of_primary_key_many_keys (inserts:50): 185 wallclock secs

5.5.4/iplugin110
Time for update_of_primary_key_many_keys (none:50):    179 wallclock secs
Time for update_of_primary_key_many_keys (inserts:50): 170 wallclock secs
Time for update_of_primary_key_many_keys (deletes:50): 196 wallclock secs
Time for update_of_primary_key_many_keys (purges:50):  191 wallclock secs
Time for update_of_primary_key_many_keys (changes:50): 249 wallclock secs
Time for update_of_primary_key_many_keys (all:50):     250 wallclock secs

How to repeat:
Test case will be added later.

Profiling the test case shows that ibuf mutex becomes hot when 'all' change buffering is used. Alexey will soon upload the test case and I'll look into this after that.

Test case for the issue

Attachment: bug_icb.pl (application/octet-stream, text), 6.25 KiB.

test case usage:

a) create/populate table and run update scenario
perl bug_bci.pl --db-socket=/tmp/mysql.sock --create --update  --buffering=all 

b) create/populate table and run delete scenario
perl bug_bci.pl --db-socket=/tmp/mysql.sock --create --delete  --buffering=all 

 - it is possible to vary number of loops for update/delete with --coun=<>
 - it is possible to vary type of buffering with --buffering=<>
 - it is possible to show INSERT BUFFER STAT with --stat option

typo: option name =~ s/coun/count/

I wonder if we could split the ibuf mutex to have one per buffer pool instance.
This wouldn't help for the problem at hand, though, because the test 
uses single buffer pool.

Reproduced by running the test provided:

irana@dscczz01:~/downloads$ perl bug_icb.pl --db-socket=/home/irana/install/mysql.sock --create --update --buffering=inserts
MySQL 5.5.5 m3, ENGINE: InnoDB 

Set innodb_change_buffering=inserts

BUFFERING: inserts

Generating random keys
Inserting 100000 rows
Inserted 0 rows
Inserted 10000 rows
Inserted 20000 rows
Inserted 30000 rows
Inserted 40000 rows
Inserted 50000 rows
Inserted 60000 rows
Inserted 70000 rows
Inserted 80000 rows
Inserted 90000 rows
Time for insert (100000): 148 wallclock secs ( 1.06 usr  0.02 sys +  0.00 cusr  0.00 csys =  1.08 CPU)

Time for check table bench1(1):  7 wallclock secs ( 0.00 usr  0.00 sys +  0.00 cusr  0.00 csys =  0.00 CPU)

Testing update of keys: start:0 count:15 update with:1
Time for update_of_primary_key_many_keys (inserts:15): 70 wallclock secs ( 0.00 usr  0.00 sys +  0.00 cusr  0.00 csys =  0.00 CPU)

Time for check table bench1(1):  8 wallclock secs ( 0.00 usr  0.00 sys +  0.00 cusr  0.00 csys =  0.00 CPU)

+-------------------------------------------------------+------------+-------------------+----------------+
| EVENT_NAME                                            | COUNT_STAR | SUM_TIMER_WAIT_MS | AVG_TIMER_WAIT |
+-------------------------------------------------------+------------+-------------------+----------------+
| wait/synch/mutex/innodb/ibuf_mutex                    |     465648 |         3082.2474 |        6619264 |

irana@dscczz01:~/downloads$ perl bug_icb.pl --db-socket=/home/irana/install/mysql.sock --create --update --buffering=all
MySQL 5.5.5 m3, ENGINE: InnoDB 

Set innodb_change_buffering=all

BUFFERING: all

Generating random keys
Inserting 100000 rows
Inserted 0 rows
Inserted 10000 rows
Inserted 20000 rows
Inserted 30000 rows
Inserted 40000 rows
Inserted 50000 rows
Inserted 60000 rows
Inserted 70000 rows
Inserted 80000 rows
Inserted 90000 rows
Time for insert (100000): 165 wallclock secs ( 1.06 usr  0.02 sys +  0.00 cusr  0.00 csys =  1.08 CPU)

Time for check table bench1(1):  7 wallclock secs ( 0.00 usr  0.00 sys +  0.00 cusr  0.00 csys =  0.00 CPU)

Testing update of keys: start:0 count:15 update with:1
Time for update_of_primary_key_many_keys (all:15): 84 wallclock secs ( 0.01 usr  0.01 sys +  0.00 cusr  0.00 csys =  0.02 CPU)

Time for check table bench1(1):  6 wallclock secs ( 0.00 usr  0.00 sys +  0.00 cusr  0.00 csys =  0.00 CPU)

mysql> SELECT EVENT_NAME, COUNT_STAR, (SUM_TIMER_WAIT/1000000000) AS SUM_TIMER_WAIT_MS, AVG_TIMER_WAIT FROM EVENTS_WAITS_SUMMARY_BY_EVENT_NAME WHERE EVENT_NAME LIKE '%INNODB%' AND COUNT_STAR > 0 ORDER BY COUNT_STAR DESC;
+-------------------------------------------------------+------------+-------------------+----------------+
| EVENT_NAME                                            | COUNT_STAR | SUM_TIMER_WAIT_MS | AVG_TIMER_WAIT |
+-------------------------------------------------------+------------+-------------------+----------------+
| wait/synch/mutex/innodb/ibuf_mutex                    |     982711 |        12291.2528 |       12507494 |

Avg. wait for ibuf_mutex roughly doubles and the number of waits also doubles. The total time spend waiting is roughly four times greater when using change_buffering = all.

Slightly reduce ibuf_mutex contention. Update the merge counters too.

Attachment: bug54914-2.patch (text/x-diff), 5.18 KiB.

triage: Hard to follow the exact issue. Is the 'all option expected to be slower or the same? Is this a new feature or exists in 5.1. If so how does it compare to 5.1?
Please clarify

innodb_change_buffering=all is a new feature in 5.5. Before 5.5, InnoDB only buffered inserts (to leaf pages of secondary index B-trees that are not in the InnoDB buffer pool). With "all", it also buffers delete and purge operations. Under certain workloads, InnoDB is slower with innodb_change_buffering=all than with innodb_change_buffering=inserts. The problem appears to be ibuf_mutex contention.

Same as above, and invoke ibuf_entry_build() before acquiring ibuf_mutex.

Attachment: bug54914-3.patch (text/x-diff), 7.15 KiB.

I tried the patch posted by Marko. It doesn't help in reducing the update time. The insert time for building the table, however, shows some improvement (from 160 wall clock secs to 146 wall clock secs).

As suspected this patch won't alleviate the reported issue. But the patch in itself is a step in right direction and should be taken in 5.5 IMO.

Tried a suggestion by Marko to use row_format=redundant and see if it changes the equation. No significant change noticed.

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/115285

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/115286

Untested patch to reduce ibuf_mutex contention further. Perform some dirty reads on purpose.

Attachment: bug54914-4.patch (text/x-diff), 4.91 KiB.

With performance_schema monitoring on ibuf_mutex, I found two clear hotspots:

select SOURCE,COUNT(*) from EVENTS_WAITS_HISTORY_LONG GROUP BY SOURCE;
+------------------+----------+
| SOURCE           | COUNT(*) |
+------------------+----------+
| ibuf0ibuf.c:2494 |      283 |
| ibuf0ibuf.c:2632 |      119 |
| ibuf0ibuf.c:3326 |     4990 |
| ibuf0ibuf.c:3368 |      119 |
| ibuf0ibuf.c:3569 |     3832 |
| ibuf0ibuf.c:4104 |      657 |
+------------------+----------+

These are in ibuf_insert_low(). My latest patch eliminates the ibuf0ibuf.c:3326 by doing a dirty read of ibuf->size (which should not affect correctness). I did not figure out a way to avoid ibuf0ibuf.c:3569 completely. It is the ibuf->empty=FALSE that is protected by ibuf_mutex. (If this patch is not enough, we can try to protect this flag by something else than the ibuf_mutex.)

With bug54914-3.patch (committed) and bug54914-4.patch (not yet committed), I am seeing some improvement:

innodb_change_buffering=inserts:
insert: 229 sec
check: 34 sec
update: 164 sec

innodb_change_buffering=all:
insert: 248 sec
check: 25 sec
update: 134 sec

Next, I will investigate the insert regression. I did not enable performance_schema for this change yet.

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/115386

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/115385

triage: setting tag to SR55RC based on last comment

Bug #55035 is a likely duplicate of this.

Pushed into mysql-5.5 5.5.6-m3 (revid:alik@ibmvm-20100825092002-2yvkb3iwu43ycpnm) (version source revid:alik@ibmvm-20100825092002-2yvkb3iwu43ycpnm) (merge vers: 5.5.6-m3) (pib:20)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@sun.com-20100830082732-n2eyijnv86exc5ci) (version source revid:alik@sun.com-20100830082732-n2eyijnv86exc5ci) (merge vers: 5.6.1-m4) (pib:21)

Pushed into mysql-next-mr (revid:alik@sun.com-20100830082745-n6sh01wlwh3itasv) (version source revid:alik@sun.com-20100830082745-n6sh01wlwh3itasv) (pib:21)

Added to change log:

The setting innodb_change_buffering=all could produce slower
performance for some operations than the previous default,
innodb_change_buffering=inserts.

Added to change log:

The setting innodb_change_buffering=all could produce slower
performance for some operations than the previous default,
innodb_change_buffering=inserts.

Added to change log:

The setting innodb_change_buffering=all could produce slower
performance for some operations than the previous default,
innodb_change_buffering=inserts.

Added to change log:

The setting innodb_change_buffering=all could produce slower
performance for some operations than the previous default,
innodb_change_buffering=inserts.