Details
-
Bug
-
Status: Stalled (View Workflow)
-
Major
-
Resolution: Unresolved
-
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
Description
NOTE: the following description is obsolete. See these comments for the current description of the bug:
- https://jira.mariadb.org/browse/MDEV-28804?focusedCommentId=278951&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-278951
- https://jira.mariadb.org/browse/MDEV-28804?focusedCommentId=278955&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-278955
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
-
-
- Open
-
- relates to
-
-
- In Review
-
-
-
- Confirmed
-
-
-
- Closed
-
-
-
- Closed
-
Activity
For optimized builds, there is a somewhat similar pattern of slowdowns with max diff slowdown of 1.8x. It is likely (given the debug results) that the slowdown in 10.8-10.10 (which could not be tested) is more.
10.3.36-opt>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
Query OK, 2985984 rows affected (30.820 sec)
|
10.4.26-opt>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
Query OK, 2985984 rows affected (34.055 sec)
|
10.5.17-opt>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
Query OK, 2985984 rows affected (44.685 sec)
|
10.6.9-opt>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
Query OK, 2985984 rows affected (55.158 sec)
|
10.7.5-opt>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
Query OK, 2985984 rows affected (53.704 sec)
|
10.8 to 10.10 could not be tested due to MDEV-28803
Regrettably LOCK TABLES test failed, and no immediate workaround obvious.
10.9.2-dbg>LOCK TABLES t1 WRITE;
|
Query OK, 0 rows affected (0.000 sec)
|
|
|
10.9.2-dbg>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
ERROR 1100 (HY000): Table 't1' was not locked with LOCK TABLES
|
Using a secondary table defeats the purpose as the LOCK would still need to happen on the secondary table before the INSERT.
There are quite a few more oddities in this area. For example:
SET GLOBAL innodb_buffer_pool_size=12*1024*1024; |
CREATE TABLE t1 (d DOUBLE); |
CREATE TABLE t2 (d DOUBLE); |
INSERT INTO t1 VALUES (0x0061),(0x0041),(0x00E0),(0x00C0),(0x1EA3),(0x1EA2),(0x00E3),(0x00C3),(0x00E1),(0x00C1),(0x1EA1),(0x1EA0); |
INSERT INTO t2 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6; |
LOCK TABLES t1 WRITE, t2 READ; |
INSERT INTO t1 SELECT * FROM t2; |
Will lead to very different numbers compared with the 10.4 optimized result (34 seconds) above:
|
10.4.26 ebbd5ef6e2902a51a46e47dbb8a8667593cb25e7 (Optimized) |
10.4.26-opt>INSERT INTO t2 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
Query OK, 2985984 rows affected (18.858 sec)
|
Records: 2985984 Duplicates: 0 Warnings: 0
|
|
|
10.4.26-opt>LOCK TABLES t1 WRITE, t2 READ;
|
Query OK, 0 rows affected (0.000 sec)
|
|
|
10.4.26-opt>INSERT INTO t1 SELECT * FROM t2;
|
Query OK, 2985984 rows affected (1 min 20.029 sec)
|
Records: 2985984 Duplicates: 0 Warnings: 0
|
i.e. 19 seconds for the same insert but to a secondary (same DDL) table, and then 80 seconds for insert into t1 of the same result: there may be 2-3 optimizations possible.
Realized that for 10.8-10.10 only, innodb_buffer_pool_chunk_size (MDEV-25342) is smaller by default, thus allowing the first query to make a 10x smaller buffer pool for those versions (unlike 10.3-10.7). Retested 10.3-10.7 using the following modified testcase:
# mysqld options required for replay: --innodb_buffer_pool_chunk_size=2097152 |
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; |
Interestingly, using this testcase, 10.4 can be set to a smaller innodb_buffer_pool_size (unlike what is seen without innodb_buffer_pool_chunk_size ref MDEV-28805).
The results are:
Optimized: 10.3: 37.0 sec, 10.4: 37.7 sec, 10.5: 52.9 sec (1.4x), 10.6+: could not be tested due to MDEV-28803 in this case
Debug: 10.3: 37.7 sec, 10.4: 4 min 59 sec (7.9x), 10.5: 5 min 9 sec (8.2x), 10.6+: could not be tested due to MDEV-28803 in this case
Did one more test:
# mysqld options required for replay: --innodb_buffer_pool_chunk_size=2097152 |
SET GLOBAL innodb_buffer_pool_size=12*1024*1024; |
CREATE TABLE t1 (d DOUBLE); |
CREATE TABLE t2 (d DOUBLE); |
INSERT INTO t1 VALUES (0x0061),(0x0041),(0x00E0),(0x00C0),(0x1EA3),(0x1EA2),(0x00E3),(0x00C3),(0x00E1),(0x00C1),(0x1EA1),(0x1EA0); |
INSERT INTO t2 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6; |
LOCK TABLES t1 WRITE, t2 READ; |
INSERT INTO t1 SELECT * FROM t2; |
All optimized versions show very different results (though at least for first query pattern is the same):
First insert: 10.3: 21.1 sec, 10.4: 24.5 sec , 10,5: 29.0 sec, 10.6: 36.9 sec, 10.7: 37.3 sec, 10.8: 37.4 sec, 10.9: 33.7 sec, 10.10: 36 sec
Second insert: 10.3: 1m 14.8 sec, 10.4: 1min 13.5 sec, 10.5: 41.9 sec, 10.6: 53.5 sec, 10.7: 51.7 sec, 10.8: 51.7 sec, 10.9: 54.3 sec, 10.10: 55.1 sec
- The difference between 10.3 optimized and 10.10 optimized for the first query is 1.7x
- The difference between 10.5 optimized and 10.10 optimized for the 2nd query is 1.3x
- The difference between the first query on 10.6 optimized and the second query on the same version is 1.45x
- It is really strange that the second INSERT would take much longer (no JOIN is necessary, just a copy of the table)?
For debug builds:
- current 11.4 8bf9f21855606ddeb0fe90fb1e70165adbec6746 I get 8.834s
- current 10.5 9e9e0b99ade0e6ccd34abc3bc3abaf7bbd5ecf4e I get 17.485s
- current 10.4 7e8e51eb3ad1ffd1bf8ec9c5dc23038e0e2e4b9c I get 8.429s
- latest 10.3 ca001cf2048f0152689e1895e2dc15486dd0b1af I get 2.873s
^ but these use myisam as the engine which is the default in mtr.
If we explicitly use innodb as the engine then we get more dramatic
amount of time (Roel: the tables are meant to be created using
innodb, right?):
- current 10.5 9e9e0b99ade0e6ccd34abc3bc3abaf7bbd5ecf4e I get 8m49.92s
perf record -p $(pgrep mariadbd) shows top cpu use being debug
related functions (for debug builds):
|
10.5 9e9e0b99ade0e6ccd34abc3bc3abaf7bbd5ecf4e |
10.10% mariadbd mariadbd [.] DoTrace
|
8.51% mariadbd mariadbd [.] _db_enter_
|
8.04% mariadbd mariadbd [.] _db_return_
|
5.04% mariadbd mariadbd [.] JOIN_CACHE::read_all_record_fields
|
3.77% mariadbd mariadbd [.] my_thread_var_dbug
|
3.20% mariadbd mariadbd [.] JOIN_CACHE::read_flag_fields
|
3.07% mariadbd mariadbd [.] JOIN_CACHE::get_record_by_pos
|
2.71% mariadbd mariadbd [.] code_state
|
2.51% mariadbd mariadbd [.] JOIN_CACHE::get_record
|
1.86% mariadbd mariadbd [.] maria_write
|
1.70% mariadbd mariadbd [.] InList
|
1.69% mariadbd mariadbd [.] JOIN_CACHE::join_matching_records
|
1.52% mariadbd mariadbd [.] JOIN_CACHE::get_rec_ref
|
1.37% mariadbd mariadbd [.] _ma_write_static_record
|
1.16% mariadbd mariadbd [.] _db_pargs_
|
1.11% mariadbd mariadbd [.] select_insert::send_data
|
1.07% mariadbd mariadbd [.] JOIN_CACHE::generate_full_extensions
|
1.00% mariadbd libc.so.6 [.] pthread_getspecific@@GLIBC_2.34
|
0.97% mariadbd mariadbd [.] end_write
|
0.89% mariadbd mariadbd [.] JOIN_CACHE::check_match
|
0.88% mariadbd mariadbd [.] handler::ha_write_row
|
InnoDB yes. Interesting to see the differences in MyISAM as well. Perhaps proves that there is more than one thing at play.
Roel, ycp, can you please build cmake -DWITH_DBUG_TRACE=OFF (MDEV-29613) to concentrate on a more interesting part of the regression? I think that when it comes to InnoDB, the INSERT…SELECT performance here would be vastly improved by fixing MDEV-24813.
My builds should have already been with -DWITH_DBUG_TRACE=OFF, though it has been a while.
I tried reprod again. At the 10.3 (both the latest
ca001cf2048f0152689e1895e2dc15486dd0b1af and the one
9d10b7107cf022b939dc61cedf8fc8985443c880 mentioned in the description
of this ticket) vs a 10.4 7e8e51eb3ad1ffd1bf8ec9c5dc23038e0e2e4b9c.
At 10.3 I cannot execute {{set global
innodb_buffer_pool_size=12*1024*1024;}} without getting an error
ERROR 1231 (42000): Variable 'innodb_buffer_pool_size' can't be set to the value of '12582912'
|
So I ran the server with --innodb-buffer-pool-size=12M and ran the
queries (with innodb engine), and got 1m6s (ca001cf2) and 1m0s
(9d10b710). I did the same at 10.4, and got 1m42s.
Both Debug build.
I do not think that it is meaningful to test the performance of debug builds, because there are different amounts of debug assertions in different major versions.
Setting innodb_buffer_pool_size while the server is running is quite different from setting it at server startup. This could be cleaned up in MDEV-29445 at some point.
To work around MDEV-24813, you could make the source table(s) of INSERT…SELECT a temporary table, or create it/them in a different storage engine than InnoDB.
> Setting innodb_buffer_pool_size while the server is running is
> quite different from setting it at server startup.
In that case, how do I reproduce this regression? The original
description did not mention whether the set global statement
should result in an error.
The outcome of SET GLOBAL innodb_buffer_pool_size depends on innodb_buffer_pool_chunk_size and also sizeof(buf_block_t), which in turn depends on the build parameters and major version (in 10.6, the block descriptor is much smaller than in 10.4). What should matter is the actual buffer pool size in pages, after subtracting the space that is occupied by block descriptors.
As per discussions with marko, I built the server with
RelWithDebugInfo and started it with innodb_buffer_pool_size=5m
and ran the testcase in mtr. I get {{1206: The total number of locks
exceeds the lock table size}} for 10.3
9d10b7107cf022b939dc61cedf8fc8985443c880 and 10.4
3699a7e1a90e17cfc016518fc4922b94d2dbe6be, and either 1206 or hang for
10.5 a7ee3bc58bc23ad7ac5ced54dc745d0e65bee524.
I could perf record 10.3 and 10.5, but for 10.4 it reached 1206 very
quickly. The top functions are different, but neither works without
failure or hang. So there does not seem to be a regression to me. I
will close this as not reproducible if no opposition. If the hang in
10.5 is not the same as MDEV-24813 I will open a new ticket. marko
can we conclude from the 10.5 perf below that it is the same as
MDEV-24813 (see also the trace below)?
|
10.3 9d10b7107cf022b939dc61cedf8fc8985443c880 |
8.69% mysqld mysqld [.] buf_page_get_low
|
6.23% mysqld mysqld [.] rec_get_offsets_func
|
3.85% mysqld mysqld [.] rec_init_offsets_comp_ordinary
|
3.09% mysqld mysqld [.] btr_cur_search_to_nth_level_func
|
2.87% mysqld mysqld [.] cmp_dtuple_rec_with_match_bytes
|
2.76% mysqld mysqld [.] rw_lock_s_lock_spin
|
2.73% mysqld mysqld [.] cmp_data
|
2.43% mysqld mysqld [.] cmp_dtuple_rec_with_match_low
|
2.37% mysqld mysqld [.] rw_lock_x_lock_func
|
2.20% mysqld mysqld [.] rw_lock_x_lock_wait_func
|
2.20% mysqld mysqld [.] mtr_buf_t::for_each_block_in_reverse<CIterate<ReleaseBlocks const> >
|
2.13% mysqld mysqld [.] mtr_buf_t::for_each_block_in_reverse<CIterate<ReleaseLatches> >
|
2.10% mysqld mysqld [.] page_cur_search_with_match
|
1.72% mysqld mysqld [.] page_cur_search_with_match_bytes
|
1.53% mysqld mysqld [.] lock_rec_add_to_queue
|
1.40% mysqld mysqld [.] btr_search_guess_on_hash
|
1.31% mysqld mysqld [.] buf_page_mtr_lock
|
1.10% mysqld libc.so.6 [.] _int_free
|
1.08% mysqld mysqld [.] btr_search_check_free_space_in_heap
|
1.05% mysqld mysqld [.] mtr_t::commit
|
1.04% mysqld mysqld [.] buf_page_make_young_if_needed
|
0.96% mysqld mysqld [.] my_timer_cycles
|
0.83% mysqld libc.so.6 [.] malloc
|
0.80% mysqld mysqld [.] buf_LRU_get_free_block
|
0.80% mysqld mysqld [.] row_ins_step
|
0.76% mysqld mysqld [.] mlog_open_and_write_index
|
0.74% mysqld mysqld [.] buf_page_optimistic_get
|
0.74% mysqld mysqld [.] memo_slot_release
|
0.71% mysqld mysqld [.] btr_search_info_update_slow
|
0.70% mysqld mysqld [.] mtr_t::prepare_write
|
0.69% mysqld mysqld [.] buf::Block_hint::buffer_fix_block_if_still_valid
|
0.67% mysqld mysqld [.] lock_rec_reset_and_release_wait_low
|
0.64% mysqld mysqld [.] buf_LRU_get_free_only
|
0.63% mysqld libc.so.6 [.] _int_malloc
|
0.62% mysqld mysqld [.] lock_update_insert
|
0.62% mysqld mysqld [.] mtr_t::release_block_at_savepoint
|
|
10.5 a7ee3bc58bc23ad7ac5ced54dc745d0e65bee524 |
86.28% mariadbd mariadbd [.] buf_LRU_free_page
|
8.13% mariadbd mariadbd [.] buf_LRU_scan_and_free_block
|
1.23% mariadbd mariadbd [.] insert_events_waits_history_long
|
0.62% mariadbd mariadbd [.] pfs_end_mutex_wait_v1
|
0.53% mariadbd libc.so.6 [.] __GI___pthread_mutex_unlock_usercnt
|
0.52% mariadbd mariadbd [.] pfs_start_mutex_wait_v1
|
0.49% mariadbd libc.so.6 [.] pthread_mutex_lock@@GLIBC_2.2.5
|
0.44% mariadbd mariadbd [.] my_timer_cycles
|
0.39% mariadbd mariadbd [.] buf_LRU_get_free_block
|
0.27% mariadbd mariadbd [.] get_timer_raw_value_and_function
|
0.19% mariadbd mariadbd [.] insert_events_waits_history
|
0.17% mariadbd mariadbd [.] buf_flush_LRU
|
0.16% mariadbd mariadbd [.] buf_dblwr_t::flush_buffered_writes
|
0.12% mariadbd mariadbd [.] buf_LRU_evict_from_unzip_LRU
|
0.07% mariadbd mariadbd [.] buf_LRU_get_free_only
|
0.06% mariadbd libc.so.6 [.] pthread_getspecific@@GLIBC_2.34
|
0.05% mariadbd mariadbd [.] buf_dblwr_t::flush_buffered_writes
|
0.05% mariadbd libc.so.6 [.] pthread_cond_broadcast@@GLIBC_2.3.2
|
0.03% mariadbd mariadbd [.] pfs_unlock_mutex_v1
|
0.03% mariadbd mariadbd [.] pthread_mutex_unlock@plt
|
0.02% mariadbd libc.so.6 [.] pthread_mutex_unlock@@GLIBC_2.2.5
|
0.02% mariadbd mariadbd [.] pthread_mutex_lock@plt
|
0.01% mariadbd mariadbd [.] pthread_getspecific@plt
|
0.01% mariadbd mariadbd [.] pthread_cond_broadcast@plt
|
0.01% mariadbd [kernel.kallsyms] [k] perf_event_task_tick
|
0.01% mariadbd [kernel.kallsyms] [k] native_write_msr
|
0.00% mariadbd [kernel.kallsyms] [k] check_preemption_disabled
|
0.00% mariadbd [kernel.kallsyms] [k] native_irq_return_iret
|
0.00% mariadbd [kernel.kallsyms] [k] sync_regs
|
0.00% mariadbd [kernel.kallsyms] [k] __update_load_avg_cfs_rq
|
0.00% mariadbd [kernel.kallsyms] [k] futex_wake
|
0.00% mariadbd libc.so.6 [.] __GI___lll_lock_wait
|
0.00% mariadbd [kernel.kallsyms] [k] __update_load_avg_se
|
0.00% mariadbd [kernel.kallsyms] [k] _raw_spin_lock
|
0.00% mariadbd [kernel.kallsyms] [k] psi_group_change
|
0.00% mariadbd [kernel.kallsyms] [k] timekeeping_advance
|
0.00% mariadbd [kernel.kallsyms] [k] try_to_wake_up
|
0.00% mariadbd [kernel.kallsyms] [k] update_curr
|
0.00% mariadbd [kernel.kallsyms] [k] preempt_count_add
|
0.00% mariadbd [kernel.kallsyms] [k] entry_SYSCALL_64
|
buf_LRU_free_page > buf_LRU_free_from_common_LRU_list > buf_LRU_scan_and_free_block > buf_LRU_get_free_block > buf_page_init_for_read > buf_read_page_low > buf_read_page > buf_page_get_low > buf_page_get_gen > ibuf_bitmap_get_map_page_func > ibuf_merge_or_delete_for_page > buf_page_create > fsp_page_create > fseg_alloc_free_page_general > btr_page_split_and_insert > btr_cur_pessimistic_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 > select_result_sink::send_data_with_check > end_send > evaluate_join_record > AGGR_OP::end_send > sub_select_postjoin_aggr > do_select > JOIN::exec_inner > JOIN::exec
For completeness here's the testcase (the blackhole and t2 are
irrelevant artefacts from previous iterations of the testcase):
--source include/have_blackhole.inc
|
--source include/have_innodb.inc
|
CREATE TABLE t1 (d DOUBLE) engine=innodb; |
INSERT INTO t1 VALUES (0x0061),(0x0041),(0x00E0),(0x00C0),(0x1EA3),(0x1EA2),(0x00E3),(0x00C3),(0x00E1),(0x00C1),(0x1EA1),(0x1EA0); |
|
|
create table t2(a double)engine=innodb; # (1) |
SET profiling = 1; |
INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6; # (2) |
show profiles;
|
|
|
drop table t1, t2; |
For 10.5, if we change (1) to use blackhole and the destination
table in (2) to t2, or if we just change the destination in (2) to
t2, the query completes within seconds.
I think that the problem is that a large portion of the buffer pool will be used for explicit InnoDB record locks. We should see the size of those data structures in the output of SHOW ENGINE INNODB STATUS, like this:
1
|
--source include/have_innodb.inc
|
2
|
CREATE TABLE t1 (d DOUBLE) engine=innodb; |
3
|
INSERT INTO t1 VALUES (0x0061),(0x0041),(0x00E0),(0x00C0),(0x1EA3),(0x1EA2),(0x00E3),(0x00C3),(0x00E1),(0x00C1),(0x1EA1),(0x1EA0); |
4
|
create temporary table t2(a double)engine=innodb; |
5
|
BEGIN; |
6
|
--enable_info
|
7
|
INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6; |
8
|
--disable_info
|
9
|
SHOW ENGINE INNODB STATUS;
|
10
|
COMMIT; |
11
|
drop table t1, t2; |
To make the test run faster, I gave it innodb_buffer_pool_size=32g. But, the debug build is spending a lot of time in some validation functions, so I tested it in cmake -DCMAKE_BUILD_TYPE=RelWithDebInfo. The relevant section of the output is as follows:
|
10.6 9d88c5b8b40cce897b0a718584289f8ca331381e |
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 29
|
Purge done for trx's n:o < 28 undo n:o < 0 state: running but idle
|
History list length 0
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 28, ACTIVE 12 sec
|
381476 lock struct(s), heap size 46194808, 2992574 row lock(s), undo log entries 2985984
|
MariaDB thread id 4, OS thread handle 140541765830336, query id 28 localhost root starting
|
SHOW ENGINE INNODB STATUS
|
This appears to use 46,194,808 bytes of buffer pool for 2,992,574 row locks.
If I make the test INSERT into t2 instead of t1, the output will be as follows:
|
10.6 9d88c5b8b40cce897b0a718584289f8ca331381e |
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 26
|
Purge done for trx's n:o < 25 undo n:o < 0 state: running but idle
|
History list length 0
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 25, ACTIVE 6 sec
|
2 lock struct(s), heap size 1128, 13 row lock(s), undo log entries 2985984
|
MariaDB thread id 4, OS thread handle 140518994699968, query id 28 localhost root starting
|
SHOW ENGINE INNODB STATUS
|
Each time, we get 2,985,984 inserted rows reported, both from InnoDB (the number of undo log entries) and from the SQL layer.
If I make t2 a persistent table and t1 a temporary table, there will be no row locks.
Apparently the bug here is that the INSERT INTO t1 SELECT t1… is acquiring duplicate locks on the records, or it is creating more than the minimum necessary number (13) of explicit record locks. Here is a bit simplified version of the test:
1
|
--source include/have_innodb.inc
|
2
|
CREATE TABLE t1 (a INT PRIMARY KEY AUTO_INCREMENT) engine=innodb; |
3
|
CREATE TEMPORARY TABLE t2(a INT PRIMARY KEY AUTO_INCREMENT) engine=innodb; |
4
|
INSERT INTO t1 VALUES (1),(2); |
5
|
BEGIN; |
6
|
--enable_info
|
7
|
INSERT INTO t1 SELECT NULL FROM t1,t1 t2,t1 t3,t1 t4; |
8
|
--disable_info
|
9
|
SHOW ENGINE INNODB STATUS;
|
10
|
COMMIT; |
11
|
DROP TABLE t1; |
This will insert 2⁴=16 records and create 19 explicit record lock objects. If I insert into the temporary table, only 3 record locks will be created, in 2 lock objects (one table IX lock and another, with 8-bit bitmap. We can find more details easily by setting a breakpoint on lock_release_try after ./mtr --rr:
|
10.6 9d88c5b8b40cce897b0a718584289f8ca331381e |
(rr) p *lock
|
$1 = {trx = 0x7f83baa5cb80, trx_locks = {prev = 0x7f83baa5d080, next = 0x0}, index = 0x7f8394142cb0, hash = 0x0, requested_time = 0,
|
wait_time = 0, un_member = {tab_lock = {table = 0x500000003, locks = {prev = 0x8, next = 0x0}}, rec_lock = {page_id = {m_id = 21474836483},
|
n_bits = 8}}, type_mode = 2}
|
(rr) p/x *(char*)(lock+1)
|
$2 = 0xe
|
(rr) watch -l *(char*)(lock+1)
|
Hardware watchpoint 2: -location *(char*)(lock+1)
|
(rr) disable 1
|
(rr) reverse-continue
|
Thread 5 hit Hardware watchpoint 2: -location *(char*)(lock+1)
|
|
|
Old value = 14 '\016'
|
New value = 12 '\f'
|
0x000055f640b698c7 in lock_rec_set_nth_bit (i=<optimized out>, lock=0x7f83baa5cc80) at /mariadb/10.6/storage/innobase/include/lock0priv.inl:90
|
90 ((byte*) &lock[1])[byte_index] |= static_cast<byte>(1 << bit_index);
|
(rr) bt
|
#0 0x000055f640b698c7 in lock_rec_set_nth_bit (i=<optimized out>, lock=0x7f83baa5cc80)
|
at /mariadb/10.6/storage/innobase/include/lock0priv.inl:90
|
#1 lock_rec_lock (impl=impl@entry=false, mode=2, block=0x7f83ba267900, heap_no=<optimized out>, index=0x7f8394142cb0, thr=0x7f83941b1380)
|
at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:1682
|
#2 0x000055f640b6ab7c in lock_clust_rec_read_check_and_lock (flags=<optimized out>, block=<optimized out>, rec=<optimized out>,
|
index=<optimized out>, offsets=<optimized out>, mode=<optimized out>, gap_mode=0, thr=0x7f83941b1380)
|
at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:5895
|
#3 0x000055f640bfbd3c in sel_set_rec_lock (mtr=0x7f83b814c360, thr=0x7f83941b1380, type=0, mode=<optimized out>, offsets=<optimized out>,
|
index=0x7f8394142cb0, rec=0x7f83ba710070 "supremum", pcur=0x7f83941b0c60) at /mariadb/10.6/storage/innobase/row/row0sel.cc:1349
|
#4 row_search_mvcc (buf=buf@entry=0x7f83941afe18 "\377", mode=PAGE_CUR_G, mode@entry=PAGE_CUR_UNSUPP, prebuilt=0x7f83941b0a90,
|
match_mode=match_mode@entry=0, direction=direction@entry=1) at /mariadb/10.6/storage/innobase/row/row0sel.cc:4942
|
#5 0x000055f640a61f25 in ha_innobase::general_fetch (this=0x7f83941b0210, buf=0x7f83941afe18 "\377", direction=1, match_mode=0)
|
at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:9368
|
#6 0x000055f64054a0ab in handler::ha_index_next (this=0x7f83941b0210, buf=0x7f83941afe18 "\377") at /mariadb/10.6/sql/handler.cc:3571
|
…
|
For the exponential case (inserting into the same table), we got more lock objects:
|
10.6 9d88c5b8b40cce897b0a718584289f8ca331381e |
---TRANSACTION 25, ACTIVE 0 sec
|
6 lock struct(s), heap size 1128, 19 row lock(s), undo log entries 16
|
MariaDB thread id 4, OS thread handle 139984027457216, query id 28 localhost root starting
|
SHOW ENGINE INNODB STATUS
|
I leave it as an exercise to you to find out where these lock objects are being created, and how to optimize this. This does not seem to be an exact duplicate of MDEV-24813.
Thanks marko. I think we need to first agree on what is the bug/problem, including what is the testcase and what is the expected behaviour. The description of this ticket was that there's a 10.4 regression in performance. As I mentioned above[1], there's no reproduction of the regression any more. So I will close this ticket. What is the main test case now? My understanding is that the testcase is the one in my comment[1], with --innodb_buffer_pool_size=5m. And the expected behaviour is that it should not hang or result in 1206: The total number of locks exceeds the lock table size, agree? I have opened MDEV-33324 with this description, and we can update it there if it is not accurate.
I also note some experiments done last Thursday. If I add begin; and commit; then I get a hang that lasts longer than the default mtr timeout of 15min:
CREATE TABLE t1 (d DOUBLE) engine=innodb;
|
INSERT INTO t1 VALUES (0x0061),(0x0041),(0x00E0),(0x00C0),(0x1EA3),(0x1EA2),(0x00E3),(0x00C3),(0x00E1),(0x00C1),(0x1EA1),(0x1EA0);
|
SET profiling = 1;
|
begin;
|
INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
worker[01] Test still running: main.mdev_28804
|
worker[01] Test still running: main.mdev_28804
|
worker[01] Test still running: main.mdev_28804
|
The bug still exists, including in optimized builds. For example (using a fresh MariaDB instance + the CLI):
(And using a free server, not running anything else):
# 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; |
Leads to:
|
11.4.0 8bf9f21855606ddeb0fe90fb1e70165adbec6746 (Optimized) |
11.4.0-opt>SHOW PROCESSLIST;
|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
|
| Id | User | Host | db | Command | Time | State | Info | Progress |
|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
|
| 4 | root | localhost | test | Query | 423 | 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)
|
Did not wait longer than 7 minutes; terminated instance.
And:
|
10.11.7 09049fe496eea1c19cd3ce80a788fa4b75d9609e (Optimized) |
10.11.7-opt>SHOW PROCESSLIST;
|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
|
| Id | User | Host | db | Command | Time | State | Info | Progress |
|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
|
| 4 | root | localhost | test | Query | 360 | Sending data | INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6 | 0.000 |
|
| 6 | root | localhost | test | Query | 0 | starting | SHOW PROCESSLIST | 0.000 |
|
+----+------+-----------+------+---------+------+--------------+------------------------------------------------------------------+----------+
|
2 rows in set (0.000 sec)
|
|
|
10.11.7-opt>SHOW ENGINE INNODB STATUS\G
|
*************************** 1. row ***************************
|
Type: InnoDB
|
Name:
|
Status:
|
=====================================
|
2024-01-29 17:07:36 0x14e7980bd640 INNODB MONITOR OUTPUT
|
=====================================
|
Per second averages calculated from the last 9 seconds
|
-----------------
|
BACKGROUND THREAD
|
-----------------
|
srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 447 srv_idle
|
srv_master_thread log flush and writes: 447
|
----------
|
SEMAPHORES
|
----------
|
------------
|
TRANSACTIONS
|
------------
|
Trx id counter 26
|
Purge done for trx's n:o < 25 undo n:o < 0 state: running but idle
|
History list length 0
|
LIST OF TRANSACTIONS FOR EACH SESSION:
|
---TRANSACTION 25, ACTIVE 437 sec inserting
|
mysql tables in use 7, locked 7
|
75085 lock struct(s), heap size 9101432, 588998 row lock(s), undo log entries 587691
|
MariaDB thread id 4, OS thread handle 22984927524416, query id 6 localhost root Sending data
|
INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6
|
--------
|
FILE I/O
|
--------
|
Pending flushes (fsync): 0
|
232 OS file reads, 1928 OS file writes, 233 OS fsyncs
|
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
|
---
|
LOG
|
---
|
Log sequence number 36596533
|
Log flushed up to 36596533
|
Pages flushed up to 27787478
|
Last checkpoint at 27787478
|
----------------------
|
BUFFER POOL AND MEMORY
|
----------------------
|
Total large memory allocated 46137344
|
Dictionary memory allocated 102552
|
Buffer pool size 756
|
Free buffers 0
|
Database pages 201
|
Old database pages 0
|
Modified db pages 199
|
Percent of dirty pages(LRU & free pages): 98.515
|
Max dirty pages percent: 90.000
|
Pending reads 0
|
Pending writes: LRU 1, flush list 0
|
Pages made young 3, not young 0
|
0.00 youngs/s, 0.00 non-youngs/s
|
Pages read 218, created 2009, written 1875
|
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
|
No buffer pool page gets since the last printout
|
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
|
LRU len: 201, unzip_LRU len: 0
|
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
|
--------------
|
ROW OPERATIONS
|
--------------
|
0 read views open inside InnoDB
|
state: sleeping
|
----------------------------
|
END OF INNODB MONITOR OUTPUT
|
============================
|
|
|
1 row in set (0.000 sec)
|
Did not wait longer than ~6-7 minutes; terminated instance.
Versus:
|
10.3.39 ca001cf2048f0152689e1895e2dc15486dd0b1af (Optimized) |
10.3.39-opt>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
Query OK, 2985984 rows affected (10.892 sec)
|
Records: 2985984 Duplicates: 0 Warnings: 0
|
And:
|
10.4.33 1b747ffd05dd524f8d43b35a2b583dc4c00d767b (Optimized) |
10.4.33-opt>INSERT INTO t1 SELECT t1.* FROM t1,t1 t2,t1 t3,t1 t4,t1 t5,t1 t6;
|
Query OK, 2985984 rows affected (10.738 sec)
|
Records: 2985984 Duplicates: 0 Warnings: 0
|
10.4 Seems about equal to 10.3 now, whereas 10.11 and 11.4 get stuck.
What is the relevant part of SHOW ENGINE INNODB STATUS output of my test on 10.4 or 10.5?
Thanks Roel, from your examples of 10.3, 10.4, 10.11, and 11.4 it
looks like it is no longer a 10.4-regression as 10.3 and 10.4 have
similar times. Could you update the ticket which version causes the
regression now?
Note: except for 11.4 (20 Jan 2024 build), all other builds tested were from 27 Dec 2023.
10.5 is ~12.8 seconds, about the same though still ~1.2x
10.6+ Shows the >10 sec runtime/thread-hang.
With the new description I confirm that I can reprod at current 10.5 354e97cd722c6b8721f05e75084a6843e32b6b74 and 10.6 4dbf55bbfcdffb495ea25c6fcfe6c04b624b9654.
ycp That is interesting. You are seeing the >10 sec duration/semi-thread-hang for 10.5 also? Or just factor 1.2x ?
Roel, I meant 10.5 was ok (~<10s), but 10.6 not ok (>10min).
Also I recorded the SHOW ENGINE INNODB STATUS; which shows a 10.6-regression:
- in marko's reduced test case (2^4) I get 4 lock structs for 10.4/5 and 6 for 10.6
- in the original case I get 52622 lock struct(s), heap size 6643832 for 10.4/5 and 381476 lock struct(s), heap size 46194808 for 10.6 (using 32g)
I tested this once more. There is not that much difference in the output of the following:
--source include/have_innodb.inc
|
CREATE TABLE t1 (a INT PRIMARY KEY AUTO_INCREMENT) engine=innodb; |
CREATE TEMPORARY TABLE t2(a INT PRIMARY KEY AUTO_INCREMENT) engine=innodb; |
INSERT INTO t1 VALUES (1),(2); |
BEGIN; |
--enable_info
|
INSERT INTO t1 SELECT NULL FROM t1,t1 t2,t1 t3,t1 t4; |
--disable_info
|
--replace_regex /.*---TRANSACTION \d+, ACTIVE \d+ sec\n(.*)\n(MySQL|MariaDB) thread id.*/\1/
|
SHOW ENGINE INNODB STATUS;
|
COMMIT; |
SELECT COUNT(*) FROM t1; |
DROP TABLE t1; |
|
10.4 ee1407f74dc063a851e1fe41b980ccc1ce4c01bb |
CREATE TABLE t1 (a INT PRIMARY KEY AUTO_INCREMENT) engine=innodb;
|
INSERT INTO t1 VALUES (1),(2);
|
BEGIN;
|
INSERT INTO t1 SELECT NULL FROM t1,t1 t2,t1 t3,t1 t4;
|
affected rows: 16
|
info: Records: 16 Duplicates: 0 Warnings: 0
|
SHOW ENGINE INNODB STATUS;
|
Type Name Status
|
InnoDB 4 lock struct(s), heap size 1152, 19 row lock(s), undo log entries 16
|
COMMIT;
|
SELECT COUNT(*) FROM t1;
|
COUNT(*)
|
18
|
DROP TABLE t1;
|
|
10.6 12d05c8266567ea9a62ccabc3180a90129bf81e0 |
CREATE TABLE t1 (a INT PRIMARY KEY AUTO_INCREMENT) engine=innodb;
|
INSERT INTO t1 VALUES (1),(2);
|
BEGIN;
|
INSERT INTO t1 SELECT NULL FROM t1,t1 t2,t1 t3,t1 t4;
|
affected rows: 16
|
info: Records: 16 Duplicates: 0 Warnings: 0
|
SHOW ENGINE INNODB STATUS;
|
Type Name Status
|
InnoDB 6 lock struct(s), heap size 1152, 19 row lock(s), undo log entries 16
|
COMMIT;
|
SELECT COUNT(*) FROM t1;
|
COUNT(*)
|
18
|
DROP TABLE t1;
|
If we reduce the Cartesian product to 2×2 rows:
INSERT INTO t1 SELECT NULL FROM t1,t1 t2; |
then we will see exactly the same output:
| version | log2(copied rows) | lock structs | row locks |
|---|---|---|---|
| 10.4&10.6 | 2 | 4 | 7 |
| 10.4 | 3 | 4 | 11 |
| 10.6 | 3 | 5 | 11 |
| 10.4 | 4 | 4 | 19 |
| 10.6 | 4 | 6 | 19 |
Already at 2³ records being copied, we see a difference in the number of lock structs between 10.4 and 10.6. That I think is a difference of interest. The SQL statement for that one would be as follows:
INSERT INTO t1 SELECT NULL FROM t1,t1 t2,t1 t3; |
> then we will see exactly the same output:
And the 10.5 output is the same as 10.4, as expected.
vlad.lesin, can you please find out exactly why 10.6 is creating more record lock objects than 10.5?
Also, would it be possible to discard some explicit lock objects when acquiring stronger locks? With a new data structure (MDEV-16406) this would be easier, but maybe we could do something here in special cases?
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
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, has fixing MDEV-28800 significantly limited the impact of this bug?
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.
The scenario looks like an exact duplicate of MDEV-24813. The record locks are being acquired on the records that are being visited while computing a Cartesian product of tables.
You could try LOCK TABLES t1 WRITE to work around MDEV-24813 and to explicitly escalate to table-level locking.
If something really changed between 10.3 and 10.4 with respect to this, I do not think that the relevant change was in InnoDB. InnoDB locking was improved in 10.6.