MySQL Bugs: #100537: Performance degradation caused by monitoring sys.innodb_lock

Bug #100537	Performance degradation caused by monitoring sys.innodb_lock_waits in MySQL 8.0
Submitted:	15 Aug 2020 8:11	Modified:	19 Sep 9:44
Reporter:	Sho Iizuka	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S5 (Performance)
Version:	8.0.21	OS:	Ubuntu (18.04 LTS)
Assigned to:		CPU Architecture:	x86
Tags:	regression

Description:
We have a monitoring process that periodically retrieves blocking and waiting transactions from sys.innodb_lock_waits.

In MySQL 5.7, we have been able to use this monitoring process with slight performance degradation.
However, in MySQL 8.0, with a large number of waiting transactions, observation of sys.innodb_lock_waits by the monitoring process can cause significant performance degradation to blocking transactions.

The following are the results of a test script that shows the performance degradation with and without the monitoring process.

MySQL 5.7.30
w/o monitor: test in 12.853 sec.
w/ monitor: test in 13.680 sec.

MySQL 8.0.21
w/o monitor: 12.629 sec.
w/ monitor: 110.889 sec.

How to repeat:
* Prepare a table:

  CREATE TABLE `test` (`id` bigint NOT NULL, `value` bigint NOT NULL, PRIMARY KEY (`id`));

* [optional] Prepare a monitoring process that executes the following query at 1 second intervals:

  SELECT blocking_lock_id, wait_age_secs, blocking_query, waiting_query FROM sys.innodb_lock_waits;

* Initialize a table:

  TRUNCATE test;
  INSERT INTO test (id, value) VALUES (0, 1), (1, 1), (2, 1), ..., (999999, 1);
  COMMIT;

* Start a blocking transaction t0:

  BEGIN;
  UPDATE test SET value = 2 WHERE id in (0, 1, 2, ..., 9999);
  UPDATE test SET value = 2 WHERE id in (10000, 10001, 10002, ..., 19999);
  UPDATE test SET value = 2 WHERE id in (20000, 20001, 20002, ..., 29999);
  ...
  UPDATE test SET value = 2 WHERE id in (990000, 990001, 990002, ..., 999999);
  COMMIT;

* Start waiting transactions t1, t2, t3, ..., t100 in parallel with t0:

  t1: BEGIN; UPDATE test SET value = 3 WHERE id = 0; COMMIT;
  t2: BEGIN; UPDATE test SET value = 3 WHERE id = 10000; COMMIT;
  t3: BEGIN; UPDATE test SET value = 3 WHERE id = 20000; COMMIT;
  ...
  t100: BEGIN; UPDATE test SET value = 3 WHERE id = 990000; COMMIT;

* Measure the execution time of transaction t0

# Environment:

* Ubuntu 20.04 LTS, 2 vCPUs, 2 GiB Mem, 1000 IOPS disk on Hyper-V
* MySQL 8.0.21 or MySQL 5.7.30 from Debian packages from Oracle

# Configuration

[mysqld]
pid-file        = /var/run/mysqld/mysqld.pid
socket          = /var/run/mysqld/mysqld.sock
datadir         = /var/lib/mysql
log-error       = /var/log/mysql/error.log

character_set_server = utf8mb4
collation_server = utf8mb4_bin

default-authentication-plugin = mysql_native_password
max_connections = 1024
max_allowed_packet = 1GB
skip_name_resolve

innodb_autoinc_lock_mode = 2

innodb_buffer_pool_size = 1GB
innodb_buffer_pool_instances = 1
innodb_log_file_size = 512MB
innodb_log_files_in_group = 2
innodb_flush_method = O_DIRECT

skip_log_bin

test script

Attachment: lock_test.py (application/octet-stream, text), 2.22 KiB.

monitoring process

Attachment: monitor.py (application/octet-stream, text), 673 bytes.

monitor.py is the monitoring process written in Python 3.

  CREATE USER `monitor`@`localhost`;
  GRANT SELECT ON sys.* TO `monitor`@`localhost`;
  GRANT EXECUTE ON sys.* TO `monitor`@`localhost`;
  GRANT SELECT ON performance_schema.* TO `monitor`@`localhost`;
  GRANT PROCESS ON *.* TO `monitor`@`localhost`;

lock_test.py is the test script written in Python 3.

  CREATE USER test@localhost;
  CREATE DATABASE test;
  GRANT ALL ON test.* TO test@localhost;

Hello Sho Iizuka-San,

Thank you for the report and test case.

regards,
Umesh

Posted by developer:
 
Added the following note to the MySQL Server 8.0.40, 8.4.3, and 9.1.0 release notes:
	
Running SELECT * FROM sys.innodb_lock_waits; on an instance which was under heavy load affected the performance of the server.
As of this release, SELECT * FROM sys.innodb_lock_waits; fetches only 2 locks for each wait, instead of scanning all locks twice for each wait.
As part of this fix, primary keys were added to the DATA_LOCKS and DATA_LOCK_WAITS Performance Schema tables.

Thank you for the bug report.