[MDEV-28804] Increased lock objects in 10.6+ leading to significant slowdown when using a limited InnoDB buffer pool, including in release builds - Jira

Details

Type: Bug
Status: Stalled (View Workflow)
Priority: Major
Resolution: Unresolved
Affects Version/s: 10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL), 10.10(EOL), 10.11, 11.0(EOL), 11.1(EOL), 11.2(EOL), 11.3(EOL), 11.4
Fix Version/s: 10.6, 10.11
Component/s: Locking, Storage Engine - InnoDB
Labels:
- regression-10.6
- thread_hang

Description

NOTE: the following description is obsolete. See these comments for the current description of the bug:

Found while working on MDEV-28803. Performance regression after 10.3 for debug builds:

SET GLOBAL innodb_buffer_pool_size=12*1024*1024;

CREATE TABLE t1 (d DOUBLE);

INSERT INTO t1 VALUES (0x0061),(0x0041),(0x00E0),(0x00C0),(0x1EA3),(0x1EA2),(0x00E3),(0x00C3),(0x00E1),(0x00C1),(0x1EA1),(0x1EA0);

INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;

Will complete quite quickly on 10.3 (less than 30 sec):

10.3.36 9d10b7107cf022b939dc61cedf8fc8985443c880 (Debug)
10.3.36-dbg>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
Query OK, 2985984 rows affected (29.357 sec)
Records: 2985984 Duplicates: 0 Warnings: 0

But is much slower on other releases, with varying results (in order of "speed"):

10.7.5 61727fa40f914370e843ff89a76eba7ef785c5fe (Debug)
10.7.5-dbg>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
Query OK, 2985984 rows affected (3 min 4.646 sec)
Records: 2985984 Duplicates: 0 Warnings: 0

10.6.9 05d049bdbe6814aee8f011fbd0d915f9d82a30ee (Debug)
10.6.9-dbg>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
Query OK, 2985984 rows affected (3 min 10.007 sec)
Records: 2985984 Duplicates: 0 Warnings: 0

10.4.26 ebbd5ef6e2902a51a46e47dbb8a8667593cb25e7 (Debug)
10.4.26-dbg>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
Query OK, 2985984 rows affected (4 min 25.718 sec)
Records: 2985984 Duplicates: 0 Warnings: 0

10.5.17 2840d7750db11a8d2ab3f212a05f5afefaef6d4d (Debug)
10.5.17-dbg>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
Query OK, 2985984 rows affected (4 min 34.130 sec)
Records: 2985984 Duplicates: 0 Warnings: 0

10.8 to 10.9: I gave up waiting after 3000 seconds (100x slowdown compared with 10.3):

10.8.4 0e0a3580efdae313fab340bbb308d371fa36c021 (Debug)
10.8.4-dbg>show processlist;
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
\| Id \| User \| Host \| db \| Command \| Time \| State \| Info \| Progress \|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
\| 4 \| root \| localhost \| test \| Query \| 3023 \| Sending data \| INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6 \| 0.000 \|
\| 5 \| root \| localhost \| test \| Query \| 0 \| starting \| show processlist \| 0.000 \|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
2 rows in set (0.000 sec)

10.9.2 6ec17142dcfb1e9d9f41211ed1b6d82e062d1541 (Debug)
10.9.2-dbg>show processlist;
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
\| Id \| User \| Host \| db \| Command \| Time \| State \| Info \| Progress \|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
\| 4 \| root \| localhost \| test \| Query \| 3070 \| Sending data \| INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6 \| 0.000 \|
\| 5 \| root \| localhost \| test \| Query \| 0 \| starting \| show processlist \| 0.000 \|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
2 rows in set (0.001 sec)

Same for 10.10

10.10.0 081a284712bb661349e2e3802077b12211cede3e (Debug)
10.10.0-dbg>show processlist;
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
\| Id \| User \| Host \| db \| Command \| Time \| State \| Info \| Progress \|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
\| 4 \| root \| localhost \| test \| Query \| 512 \| Sending data \| INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6 \| 0.000 \|
\| 5 \| root \| localhost \| test \| Query \| 0 \| starting \| show processlist \| 0.000 \|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
2 rows in set (0.000 sec)

In regards 10.8 to 10.10, potentially researching ~~MDEV-28805~~ can provide a clue.

Attachments

Issue Links

blocks

MDEV-33324 insert ... select from joins hangs or result in 1206: The total number of locks exceeds the lock table size

Open

relates to

MDEV-24813 Locking full table scan fails to use table-level locking

In Review

MDEV-28803 ERROR 1206 (HY000): The total number of locks exceeds the lock table size

Confirmed

MDEV-28805 SET GLOBAL innodb_buffer_pool_size=12*1024*1024 has different outcomes depending on version

Closed

MDEV-28800 SIGABRT due to running out of memory for InnoDB locks

Closed

Activity

Ascending order - Click to sort in descending order

View 29 older comments

Yuchen Pei added a comment - 2024-01-31 06:44 - edited

I compared the 2^3 case between 10.5 and 10.6. The extra lock created
in 10.6 is a record gap lock created about half-way through the
while (rc == NESTED_LOOP_OK) loop in AGGR_OP::end_send().

In 10.5 there is one such lock, created at the first iteration in the
loop. In 10.6 there are two. The first one is also created in the
first iteration. Below is where it happens in 10.6.

ut_list_append<ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> ib_lock_t::*>, GenericGetNode<ib_lock_t> > > ut_list_append<ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> ib_lock_t::*> > > lock_rec_create_low > lock_rec_add_to_queue > lock_rec_inherit_to_gap_if_gap_lock > lock_update_insert > btr_cur_optimistic_insert > row_ins_clust_index_entry_low > row_ins_clust_index_entry > row_ins_index_entry > row_ins_index_entry_step > row_ins > row_ins_step > row_insert_for_mysql > ha_innobase::write_row > handler::ha_write_row > write_record > select_insert::send_data > select_result_sink::send_data_with_check > end_send > evaluate_join_record > AGGR_OP::end_send > sub_select_postjoin_aggr > sub_select > sub_select_cache > sub_select > sub_select_cache > sub_select > do_select > JOIN::exec_inner > JOIN::exec > mysql_select

Yuchen Pei added a comment - 2024-01-31 06:44 - edited I compared the 2^3 case between 10.5 and 10.6. The extra lock created in 10.6 is a record gap lock created about half-way through the while (rc == NESTED_LOOP_OK) loop in AGGR_OP::end_send() . In 10.5 there is one such lock, created at the first iteration in the loop. In 10.6 there are two. The first one is also created in the first iteration. Below is where it happens in 10.6. ut_list_append<ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> ib_lock_t::*>, GenericGetNode<ib_lock_t> > > ut_list_append<ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> ib_lock_t::*> > > lock_rec_create_low > lock_rec_add_to_queue > lock_rec_inherit_to_gap_if_gap_lock > lock_update_insert > btr_cur_optimistic_insert > row_ins_clust_index_entry_low > row_ins_clust_index_entry > row_ins_index_entry > row_ins_index_entry_step > row_ins > row_ins_step > row_insert_for_mysql > ha_innobase::write_row > handler::ha_write_row > write_record > select_insert::send_data > select_result_sink::send_data_with_check > end_send > evaluate_join_record > AGGR_OP::end_send > sub_select_postjoin_aggr > sub_select > sub_select_cache > sub_select > sub_select_cache > sub_select > do_select > JOIN::exec_inner > JOIN::exec > mysql_select

Roel Van de Paar added a comment - 2024-02-01 20:17

I have updated the title to reflect the now-current status and findings
Was: Debug builds: 5x+ Performance regression for INSERT ... JOIN in 10.4 to 10.7 and 100x+ regression in 10.8-10.10 with smaller buffer pool. Optimized builds: 1.8x
Now: Increased lock objects in 10.6+ leading to significant slowdown when using a limited InnoDB buffer pool, including in release builds

Roel Van de Paar added a comment - 2024-02-01 20:17 I have updated the title to reflect the now-current status and findings Was: Debug builds: 5x+ Performance regression for INSERT ... JOIN in 10.4 to 10.7 and 100x+ regression in 10.8-10.10 with smaller buffer pool. Optimized builds: 1.8x Now: Increased lock objects in 10.6+ leading to significant slowdown when using a limited InnoDB buffer pool, including in release builds

Marko Mäkelä added a comment - 2025-02-27 14:26

Roel, has fixing ~~MDEV-28800~~ significantly limited the impact of this bug?

Marko Mäkelä added a comment - 2025-02-27 14:26 Roel , has fixing MDEV-28800 significantly limited the impact of this bug?

Roel Van de Paar added a comment - 2025-02-28 22:52

Thank you Marko. Will do some re-testing, likely next week.

Roel Van de Paar added a comment - 2025-02-28 22:52 Thank you Marko. Will do some re-testing, likely next week.

Roel Van de Paar added a comment - 2025-03-06 10:16 - edited

Using an otherwise idle server, fresh server intances for each run, and the CLI, with this previous testcase:

# mysqld options required for replay: --innodb_buffer_pool_chunk_size=2097152 --innodb_buffer_pool_size=12582912

SHOW GLOBAL VARIABLES LIKE '%innodb_buffer_pool_%';   # To verify settings given / equality between versions

CREATE TABLE t1 (d DOUBLE) ENGINE=InnoDB;

INSERT INTO t1 VALUES (0x0061),(0x0041),(0x00E0),(0x00C0),(0x1EA3),(0x1EA2),(0x00E3),(0x00C3),(0x00E1),(0x00C1),(0x1EA1),(0x1EA0);

INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;

We see:

Optimized/Release
MD 10.3.39 opt ca001cf2048f0152689e1895e2dc15486dd0b1af \| 5.943 sec, rerun 5.929 sec
MD 10.5.29 opt c43d0a015f974c5a0142e6779332089a7a979853 \| 7.724 sec, rerun 7.845 sec
MD 10.6.22 opt f1d7e0c17e33f77278e6226dd94aeb30fc856bf0 \| 7.062 sec, rerun 7.068 sec
MD 10.11.12 opt 43c5d1303f5c7c726db276815c459436110f342f \| 7.161 sec, rerun 7.111 sec
MD 11.4.6 opt ef966af801afc2a07222b5df65dddd52c77431dd \| 7.099 sec, rerun 6.835 sec
MD 11.8.1 opt 33e0796e7a154e02a5e53c55cefc5d6feb4f5e6d \| 6.236 sec, rerun 6.247 sec
MD 12.0.0 opt c92add291e636c797e6d6ddca605905541b2a441 \| 6.247 sec, rerun 6.257 sec

MS 5.7.44 opt f7680e98b6bbe3500399fbad465d08a6b75d7a5c \| 7.020 sec
MS 8.0.36 opt 49ef33f7edadef3ae04665e73d1babd40179a4f1 \| 14.180 sec
MS 9.1.0 opt 61a3a1d8ef15512396b4c2af46e922a19bf2b174 \| 13.270 sec

Debug
MD 10.4.25 dbg da03d8d99f7ff441cc1079dc074fde204751ef63 \| 52.941 sec
MD 10.4.34 dbg 16394f1aa1b4097f897b8ab01ea2064726cca059 \| 161.296 sec
MD 10.5.29 dbg c43d0a015f974c5a0142e6779332089a7a979853 \| 244.837 sec
MD 10.6.22 dbg f1d7e0c17e33f77278e6226dd94aeb30fc856bf0 \| 152.316 sec
MD 10.11.12 dbg 43c5d1303f5c7c726db276815c459436110f342f \| 158.139 sec
MD 11.4.6 dbg ef966af801afc2a07222b5df65dddd52c77431dd \| 182.324 sec
MD 11.8.1 dbg 33e0796e7a154e02a5e53c55cefc5d6feb4f5e6d \| 173.221 sec
MD 12.0.0 dbg c92add291e636c797e6d6ddca605905541b2a441 \| 173.510 sec

MS 5.7.44 dbg f7680e98b6bbe3500399fbad465d08a6b75d7a5c \| 40.63 sec
MS 8.0.36 dbg 49ef33f7edadef3ae04665e73d1babd40179a4f1 \| 95.81 sec
MS 9.1.0 dbg 61a3a1d8ef15512396b4c2af46e922a19bf2b174 \| 126.44 sec

Summary:

For MD 11.8 and 12.0 release build performance is very close to 10.3, which is excellent imho.
MD 10.5 to 11.4 still have a small amount of slowdown in release builds. Not sure if this requires fixing.
MS (MySQL) builds have a significant performance regression in later versions (8.0/9.1) over 5.7 for this testcase.
MS release builds are generally slower than MD for this testcase (older versions do not support all options required).
MS debug builds are less affected than MD debug builds.
State of INSERT query in processlist of 10.5.29 at 239 sec capture is 'Sending data'.
Debug builds still show very slow performance in various cases (starting with newer 10.4 versions).

Assigning to marko for decision/thoughts on debug builds.

Roel Van de Paar added a comment - 2025-03-06 10:16 - edited Using an otherwise idle server, fresh server intances for each run, and the CLI, with this previous testcase: # mysqld options required for replay: --innodb_buffer_pool_chunk_size=2097152 --innodb_buffer_pool_size=12582912 SHOW GLOBAL VARIABLES LIKE '%innodb_buffer_pool_%' ; # To verify settings given / equality between versions CREATE TABLE t1 (d DOUBLE ) ENGINE=InnoDB; INSERT INTO t1 VALUES (0x0061),(0x0041),(0x00E0),(0x00C0),(0x1EA3),(0x1EA2),(0x00E3),(0x00C3),(0x00E1),(0x00C1),(0x1EA1),(0x1EA0); INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6; We see: Optimized/Release MD 10.3.39 opt ca001cf2048f0152689e1895e2dc15486dd0b1af | 5.943 sec, rerun 5.929 sec MD 10.5.29 opt c43d0a015f974c5a0142e6779332089a7a979853 | 7.724 sec, rerun 7.845 sec MD 10.6.22 opt f1d7e0c17e33f77278e6226dd94aeb30fc856bf0 | 7.062 sec, rerun 7.068 sec MD 10.11.12 opt 43c5d1303f5c7c726db276815c459436110f342f | 7.161 sec, rerun 7.111 sec MD 11.4.6 opt ef966af801afc2a07222b5df65dddd52c77431dd | 7.099 sec, rerun 6.835 sec MD 11.8.1 opt 33e0796e7a154e02a5e53c55cefc5d6feb4f5e6d | 6.236 sec, rerun 6.247 sec MD 12.0.0 opt c92add291e636c797e6d6ddca605905541b2a441 | 6.247 sec, rerun 6.257 sec MS 5.7.44 opt f7680e98b6bbe3500399fbad465d08a6b75d7a5c | 7.020 sec MS 8.0.36 opt 49ef33f7edadef3ae04665e73d1babd40179a4f1 | 14.180 sec MS 9.1.0 opt 61a3a1d8ef15512396b4c2af46e922a19bf2b174 | 13.270 sec Debug MD 10.4.25 dbg da03d8d99f7ff441cc1079dc074fde204751ef63 | 52.941 sec MD 10.4.34 dbg 16394f1aa1b4097f897b8ab01ea2064726cca059 | 161.296 sec MD 10.5.29 dbg c43d0a015f974c5a0142e6779332089a7a979853 | 244.837 sec MD 10.6.22 dbg f1d7e0c17e33f77278e6226dd94aeb30fc856bf0 | 152.316 sec MD 10.11.12 dbg 43c5d1303f5c7c726db276815c459436110f342f | 158.139 sec MD 11.4.6 dbg ef966af801afc2a07222b5df65dddd52c77431dd | 182.324 sec MD 11.8.1 dbg 33e0796e7a154e02a5e53c55cefc5d6feb4f5e6d | 173.221 sec MD 12.0.0 dbg c92add291e636c797e6d6ddca605905541b2a441 | 173.510 sec MS 5.7.44 dbg f7680e98b6bbe3500399fbad465d08a6b75d7a5c | 40.63 sec MS 8.0.36 dbg 49ef33f7edadef3ae04665e73d1babd40179a4f1 | 95.81 sec MS 9.1.0 dbg 61a3a1d8ef15512396b4c2af46e922a19bf2b174 | 126.44 sec Summary: For MD 11.8 and 12.0 release build performance is very close to 10.3, which is excellent imho. MD 10.5 to 11.4 still have a small amount of slowdown in release builds. Not sure if this requires fixing. MS (MySQL) builds have a significant performance regression in later versions (8.0/9.1) over 5.7 for this testcase. MS release builds are generally slower than MD for this testcase (older versions do not support all options required). MS debug builds are less affected than MD debug builds. State of INSERT query in processlist of 10.5.29 at 239 sec capture is 'Sending data'. Debug builds still show very slow performance in various cases (starting with newer 10.4 versions). Assigning to marko for decision/thoughts on debug builds.

People

Assignee:: Marko Mäkelä

Reporter:: Roel Van de Paar

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2022-06-11 07:26

Updated:: 2025-03-06 10:27

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server