Bug #61401 UPDATE performance degrades gradually if a trigger exists
Submitted: 3 Jun 2011 17:47 Modified: 16 Jun 2011 19:49
Reporter: Aurimas Mikalauskas Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Locking Severity:S5 (Performance)
Version:MySQL 5.5.3+ OS:Any
Assigned to: CPU Architecture:Any
Tags: innodb, mdl, metadata locks, performance, regression, trigger, UPDATE
Triage: Needs Triage: D2 (Serious)

[3 Jun 2011 17:47] Aurimas Mikalauskas
Description:
UPDATE on an InnoDB table in a single transaction gets gradually slower if table has a trigger, even if it is a trigger on INSERT. oprofile shows 90% of time is spent in MDL_context::find_ticket:

CPU: P4 / Xeon with 2 hyper-threads, speed 3000 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during which processor is not stopped) with a unit mask of 0x01 (mandatory) count 100000
samples  %        image name               symbol name
78774    89.9288  mysqld                   MDL_context::find_ticket(MDL_request*, enum_mdl_duration*)
876       1.0000  mysqld                   MYSQLparse(void*)
219       0.2500  mysqld                   dirname_length
179       0.2043  mysqld                   mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, enum_duplicates, bool, unsigned long long*, unsigned long long*)
162       0.1849  mysqld                   trx_undo_report_row_operation
139       0.1587  mysqld                   lex_one_token(void*, void*)
...

The problem does not exist on MySQL 5.5.2-m2 which was the last 5.5 release before metadata locks were introduced. MySQL 5.1 and earlier do not have this problem, so this is a MySQL 5.5 performance regression.

Verified on RHEL6 x86_64 running MySQL 5.5.11 and Mac OS X 10.6.7 running MySQL 5.5.10

How to repeat:
mysql> USE test
mysql> CREATE TABLE repro (
  id INT NOT NULL,
  value INT, 
  PRIMARY KEY (id)
) ENGINE=INNODB;

mysql> INSERT INTO repro (id, value) VALUES (1, 1);
mysql> CREATE TRIGGER repro_insert AFTER INSERT ON `repro` FOR EACH ROW SET @var = "a";

#!/bin/bash
(echo "BEGIN;"
for ((i=0;i<200000;i++)); do
    echo "update repro set value = value + 1 where id = 1;"
done
echo "ROLLBACK;") >> load.sql

# mysql test < load.sql &

then monitor Innodb_rows_updated:

mysqladmin -ri1 ext | grep Innodb_rows_updated

| Innodb_rows_updated                      | 5516         |
| Innodb_rows_updated                      | 3753         |
| Innodb_rows_updated                      | 2215         |
| Innodb_rows_updated                      | 1696         |
| Innodb_rows_updated                      | 1316         |
| Innodb_rows_updated                      | 1003         |
| Innodb_rows_updated                      | 870          |
| Innodb_rows_updated                      | 754          |
| Innodb_rows_updated                      | 686          |
| Innodb_rows_updated                      | 637          |
| Innodb_rows_updated                      | 524          |
| Innodb_rows_updated                      | 569          |
| Innodb_rows_updated                      | 534          |
| Innodb_rows_updated                      | 509          |
| Innodb_rows_updated                      | 444          |
...

without the trigger:

| Innodb_rows_updated                      | 7145         |
| Innodb_rows_updated                      | 7523         |
| Innodb_rows_updated                      | 7570         |
| Innodb_rows_updated                      | 7527         |
| Innodb_rows_updated                      | 7535         |
[3 Jun 2011 18:36] Aurimas Mikalauskas
For the record, just checked it with MySQL 5.5.13 on Mac OS X 10.6, the problem is still there:

$ mysqladmin -ri1 ext | grep Innodb_rows_updated
| Innodb_rows_updated                      | 0           |
| Innodb_rows_updated                      | 0           |

| Innodb_rows_updated                      | 9142        |
| Innodb_rows_updated                      | 6715        |
| Innodb_rows_updated                      | 5634        |
| Innodb_rows_updated                      | 4875        |
| Innodb_rows_updated                      | 4315        |
| Innodb_rows_updated                      | 3913        |
...

| Innodb_rows_updated                      | 546         |
| Innodb_rows_updated                      | 546         |
| Innodb_rows_updated                      | 519         |
| Innodb_rows_updated                      | 539         |
| Innodb_rows_updated                      | 538         |
| Innodb_rows_updated                      | 534         |

| Innodb_rows_updated                      | 55          |
| Innodb_rows_updated                      | 0           |
| Innodb_rows_updated                      | 0           |
| Innodb_rows_updated                      | 0           |
[9 Jun 2011 12:26] Sveta Smirnova
Thank you for the report.

Verified as described. Problem is not repeatable with version 5.1
[16 Jun 2011 19:49] Paul Dubois
Noted in 5.5.15, 5.6.3 changelogs.

Incorrect handling of metadata locking for FLUSH TABLES WITH READ
LOCK for statements requiring prelocking caused two problems:

1)  Execution of any data-changing statement that required prelocking
   (that is, involved a stored function or trigger) as part of
   transaction slowed down somewhat all subsequent statements in the
   transaction. Performance in a transaction that periodically involved
   such statements gradually degraded over time.

2) Execution of any data-changing statement that required prelocking as
   part of transaction prevented a concurrent FLUSH TABLES WITH READ
   LOCK from proceeding until the end of transaction rather than at the
   end of the particular statement.

CHANGESET - http://lists.mysql.com/commits/139357