MySQL Bugs: #61401: UPDATE performance degrades gradually if a trigger exists

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

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         |

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           |

Thank you for the report.

Verified as described. Problem is not repeatable with version 5.1

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