MySQL Bugs: #30278: InnoDB: performance regression for update_with_key

Bug #30278	InnoDB: performance regression for update_with_key_prefix operation(mysql-bench)
Submitted:	7 Aug 2007 16:47	Modified:	24 Sep 2009 13:21
Reporter:	Alexey Stroganov	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S5 (Performance)
Version:	5.1.20	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
I ran the mysql-bench test for MySQL/InnoDB 5.0.45 vs 5.1.20 and found that 'update_with_key_prefix' operation is slower in 5-6 times in 5.1.20.

Further investigation shown that 'update_with_key_prefix' operation has the same performance for both 5.0.45 and 5.1.20 if it was run as standalone test, but if this operation was run after 'update_with_key' operation we get a slowdown.

table definition:

CREATE TABLE `bench1` (
  `id` int(11) NOT NULL,
  `id2` int(11) NOT NULL,
  `id3` int(11) NOT NULL,
  `dummy1` char(30) default NULL,
  PRIMARY KEY  (`id`,`id2`),
  KEY `ix_id3` (`id3`)
) ENGINE=InnoDB;

- 'update_with_key' operation is loop with following statement:

   update bench1 set dummy1='updated' where id=$i and id2=$i 

- 'update_with_key_prefix' operation is loop with following statement:

   update bench1 set dummy1='updated' where id=$i

From handler statistic it looks like optimizer uses index scan for 'update_with_key_prefix' operation for both 5.0 and 5.1.

Handler_read_next,300000

'update_with_key_prefix' loop(1-100000):
  update bench1 set dummy1='updated' where id=$i

Handler_read_next,400000

Results:

5.0.45
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 32 wallclock secs ( 0.87 usr  0.64 sys +  0.00 cusr  0.00 csys =  1.51 CPU)

Testing update with key
Time for update_with_key (100000):  28 wallclock secs ( 0.69 usr  0.67 sys +  0.00 cusr  0.00 csys =  1.36 CPU)
Testing update with key prefix
Time for update_with_key_prefix (100000):   5 wallclock secs ( 0.70 usr  0.61 sys +  0.00 cusr  0.00 csys =  1.31 CPU)

5.1.20
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 31 wallclock secs ( 0.78 usr  0.80 sys +  0.00 cusr  0.00 csys =  1.58 CPU)

Testing update with key
Time for update_with_key (100000):  29 wallclock secs ( 0.62 usr  0.80 sys +  0.00 cusr  0.00 csys =  1.42 CPU)
Testing update with key prefix
Time for update_with_key_prefix (100000):  33 wallclock secs ( 0.69 usr  0.77 sys +  0.00 cusr  0.00 csys =  1.46 CPU)

How to repeat:
run MySQL server from 5.0.45/5.1.20 disrto

cd mysql-5.0.45-linux-x86_64-glibc23
./bin/mysqld --no-defaults --datadir=<your datadir> --basedir=.

run attached perl script - just customize db_host, db_socket, db_name and number of loops(rows).

Test case for bug 30278

Attachment: bug30278.pl (application/x-perl, text), 2.37 KiB.

Reran attached test case on another box for 5.0.45, 5.0.58, 5.1.24

5.0.45
------
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 13 wallclock secs ( 0.96 usr  1.22 sys +  0.00 cusr  0.00 csys =  2.18 CPU)

Testing update with key
Time for update_with_key (100000):  16 wallclock secs ( 0.75 usr  1.31 sys +  0.00 cusr  0.00 csys =  2.06 CPU)
Testing update with key prefix
Time for update_with_key_prefix (100000):   7 wallclock secs ( 0.72 usr  1.20 sys +  0.00 cusr  0.00 csys =  1.92 CPU)

5.0.58
------
perl bug30278.pl
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 13 wallclock secs ( 0.83 usr  1.20 sys +  0.00 cusr  0.00 csys =  2.03 CPU)

Testing update with key
Time for update_with_key (100000):  16 wallclock secs ( 0.68 usr  1.32 sys +  0.00 cusr  0.00 csys =  2.00 CPU)
Testing update with key prefix
Time for update_with_key_prefix (100000):   7 wallclock secs ( 0.74 usr  1.43 sys +  0.00 cusr  0.00 csys =  2.17 CPU)

5.1.24
------
perl bug30278.pl
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 13 wallclock secs ( 0.85 usr  1.44 sys +  0.00 cusr  0.00 csys =  2.29 CPU)

Testing update with key
Time for update_with_key (100000):  16 wallclock secs ( 0.74 usr  1.52 sys +  0.00 cusr  0.00 csys =  2.26 CPU)

Testing update with key prefix
Time for update_with_key_prefix (100000):  17 wallclock secs ( 0.78 usr  1.18 sys +  0.00 cusr  0.00 csys =  1.96 CPU)

There is still 2x slowdown for update_with_key_prefix test.

The similar slowdown was observed between 6.0.5 and 6.0.6 releases for Falcon engine. I've improved test case in such way that it is possible now to run 
several related tests individually that should help to debug issues.

For Falcon:
6.0.5:

perl bug30278v2.pl --db-socket=/tmp/605.sock  --update_with_key_prefix --insert_duplicates
MySQL 6.0.5 alpha, ENGINE: Falcon
Generating random keys
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 14 wallclock secs ( 0.88 usr  1.11 sys +  0.00 cusr  0.00 csys =  1.99 CPU)
Inserting 100000 rows in reverse order
Time for insert_reverse_order (100000): 17 wallclock secs ( 0.84 usr  1.24 sys +  0.00 cusr  0.00 csys =  2.08 CPU)
Inserting 100000 rows in random order
Time for insert_random_order (100000): 17 wallclock secs ( 1.47 usr  1.32 sys +  0.00 cusr  0.00 csys =  2.79 CPU)

Testing insert of duplicates
Time for insert_duplicates (100000): 14 wallclock secs ( 1.09 usr  1.27 sys +  0.00 cusr  0.00 csys =  2.36 CPU)

Time for update_with_key_prefix (100000):  19 wallclock secs ( 1.33 usr  1.19 sys +  0.00 cusr  0.00 csys =  2.52 CPU)

6.0.6:

perl bug30278.pl --db-socket=/tmp/606.sock  --update_with_key_prefix --insert_duplicates
MySQL 6.0.6 alpha, ENGINE: Falcon
Generating random keys
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 16 wallclock secs ( 0.87 usr  0.90 sys +  0.00 cusr  0.00 csys =  1.77 CPU)
Inserting 100000 rows in reverse order
Time for insert_reverse_order (100000): 19 wallclock secs ( 0.81 usr  1.20 sys +  0.00 cusr  0.00 csys =  2.01 CPU)
Inserting 100000 rows in random order
Time for insert_random_order (100000): 18 wallclock secs ( 1.44 usr  1.27 sys +  0.00 cusr  0.00 csys =  2.71 CPU)

Testing insert of duplicates
Time for insert_duplicates (100000): 23 wallclock secs ( 1.08 usr  1.31 sys +  0.00 cusr  0.00 csys =  2.39 CPU)

Time for update_with_key_prefix (100000):  25 wallclock secs ( 1.44 usr  1.35 sys +  0.00 cusr  0.00 csys =  2.79 CPU)

Updated test case for the issue

Attachment: bug30278v2.pl (application/octet-stream, text), 5.65 KiB.

Re-checked the issue with the latest releases (5.0.72 vs 5.1.30-pre vs 6.0.8), on InnoDB:

MySQL 5.1.30 advanced, ENGINE: InnoDB
Generating random keys
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 32 wallclock secs ( 0.69 usr  0.87 sys +  0.00 cusr  0.00 csys =  1.56 CPU)
Inserting 100000 rows in reverse order
Time for insert_reverse_order (100000): 32 wallclock secs ( 0.67 usr  0.79 sys +  0.00 cusr  0.00 csys =  1.46 CPU)
Inserting 100000 rows in random order
Time for insert_random_order (100000): 46 wallclock secs ( 1.19 usr  0.78 sys +  0.00 cusr  0.00 csys =  1.97 CPU)

Testing update with key
Time for update_with_key (300000):  89 wallclock secs ( 2.27 usr  2.34 sys +  0.00 cusr  0.00 csys =  4.61 CPU)
Time for update_with_key_prefix (100000):  40 wallclock secs ( 1.32 usr  0.81 sys +  0.00 cusr  0.00 csys =  2.13 CPU)

MySQL 5.0.72 enterprise, ENGINE: InnoDB
Generating random keys
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 31 wallclock secs ( 0.81 usr  0.86 sys +  0.00 cusr  0.00 csys =  1.67 CPU)
Inserting 100000 rows in reverse order
Time for insert_reverse_order (100000): 32 wallclock secs ( 0.98 usr  0.62 sys +  0.00 cusr  0.00 csys =  1.60 CPU)
Inserting 100000 rows in random order
Time for insert_random_order (100000): 48 wallclock secs ( 1.40 usr  0.77 sys +  0.00 cusr  0.00 csys =  2.17 CPU)

Testing update with key
Time for update_with_key (300000):  87 wallclock secs ( 2.17 usr  2.32 sys +  0.00 cusr  0.00 csys =  4.49 CPU)
Time for update_with_key_prefix (100000):   6 wallclock secs ( 1.02 usr  0.70 sys +  0.00 cusr  0.00 csys =  1.72 CPU)

MySQL 6.0.8 alpha, ENGINE: InnoDB
Generating random keys
Creating table bench1
Inserting 100000 rows in order
Time for insert_in_order (100000): 31 wallclock secs ( 0.66 usr  0.87 sys +  0.00 cusr  0.00 csys =  1.53 CPU)
Inserting 100000 rows in reverse order
Time for insert_reverse_order (100000): 32 wallclock secs ( 0.83 usr  0.90 sys +  0.00 cusr  0.00 csys =  1.73 CPU)
Inserting 100000 rows in random order
Time for insert_random_order (100000): 48 wallclock secs ( 1.26 usr  0.78 sys +  0.00 cusr  0.00 csys =  2.04 CPU)

Testing update with key
Time for update_with_key (300000):  93 wallclock secs ( 2.27 usr  2.25 sys +  0.00 cusr  0.00 csys =  4.52 CPU)
Time for update_with_key_prefix (100000):  40 wallclock secs ( 1.13 usr  0.75 sys +  0.00 cusr  0.00 csys =  1.88 CPU)

Elena, can you please run this same test vs. Falcon?  As I've noted, if the problem reproduces on both InnoDB and Falcon, it is not (likley) an InnoDB-specific issue.

Ken,

Actually this is my fault that I mixed two different issues in one bug
report only because the test operation that exposes problem had the same
name.

For InnoDB the issue is the difference between 5.0 and 5.1 when the
'update_with_key_prefix' test  is executing right after the
'update_with_key' test.

InnoDB                       | 5.0.70| 5.1.29| 6.0.5 |  6.0.8 |
---------------------------------------------------------------
Test: update_with_key        |  47   |   48  |  48   |   49   |
Test: update_with_key_prefix |   9   |   18  |  19   |   18   |

I rechecked the same combination for Falcon:

Falcon                       | 6.0.5 | 6.0.8 |
----------------------------------------------
Test: update_with_key        |  60   |  61   |
Test: update_with_key_prefix |  25   |  20   |

For Falcon the issue is the difference between 6.0.5 and later 6.0.x. when
the 'update_with_key_prefix' is executing  after 'insert_duplicate' test:

Falcon                       | 6.0.5 | 6.0.6 | 6.0.7 | 6.0.8 |
--------------------------------------------------------------
Test: insert_duplicates      |  19   |   23  |  22   |   25  |
Test: update_with_key_prefix |  18   |   24  |  26   |   26  |

For InnoDB such combination of tests didn't have any impact:

InnoDB                       | 5.0.70| 5.1.29| 6.0.8 |
--------------------- --------------------------------
Test: insert_duplicates      |   8   |    9  |   9   |
Test: update_with_key_prefix |  17   |   17  |  18   |

Let's separate these two issues and continue work on InnoDB issue here and
Falcon issue I will file as another one.

Again, sorry for confusion.

it would seem that what is needed is to check if there's a similar regression, between 5.0.x and 5.1.y, for Falcon and MyISAM.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".