Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Not a Bug
-
10.0(EOL), 10.1(EOL)
-
ppc64el
-
10.0.22
Description
With the attached SQL and psdoit script to run queries concurrently, you can see that the CREATE TEMPORARY TABLE part of the query causes concurrency to tank. The related issue of MDEV-8684 is for problems in the InnoDB mutex code, while this bug is for the fact that InnoDB is down in lock_rec_convert_impl_to_exp() when it probably shouldn't be.
It appears that CREATE TEMPORARY TABLE is triggering InnoDB to go and do a whole bunch of locking that it doesn't do when you just run a plain SELECT.
The addition of CREATE TEMPORARY TABLE makes performance 280x worse.
# mysql -u root < sql
|
|
# time ./psdoit 1
|
0.022s
|
|
# time ./psdoit 10
|
0.112s
|
|
# time ./psdoit 100
|
7.150s
|
|
# time ./psdoit 200
|
30.422s
|
|
# time ./psdoit 400
|
190.378s
|
Things get very bad, very fast. We spend almost all our time in a locking
food fight:
37.42% mysqld mysqld [.] ut_delay(unsigned long)
|
|
|
---ut_delay(unsigned long)
|
|
|
|--99.74%-- mutex_spin_wait(void*, bool, char const*, unsigned long)
|
| |
|
| |--74.70%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.71]
|
| | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*)
|
| | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const
|
| | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*, unsigned long, unsigned long,
|
| | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
|
| | |
|
| | |--76.07%-- ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)
|
| | | handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function)
|
| | | handler::ha_index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function)
|
| | | join_read_key2(THD*, st_join_table*, TABLE*, st_table_ref*)
|
| | | sub_select(JOIN*, st_join_table*, bool)
|
| | |
|
and:
27.96% mysqld [kernel.kallsyms] [k] _raw_spin_lock
|
|
|
---_raw_spin_lock
|
|
|
|--58.11%-- futex_wait_setup
|
| |
|
| |--99.96%-- 0
|
| | futex_wait
|
| | do_futex
|
| | sys_futex
|
| | system_call
|
| | |
|
| | |--64.91%-- __lll_lock_wait
|
| | | |
|
| | | |--83.30%-- pthread_mutex_lock
|
| | | | |
|
| | | | |--52.72%-- os_event_reset(os_event*)
|
| | | | | sync_array_reserve_cell(sync_array_t*, void*, unsigned long, char const*, unsigned long, unsi
|
| | | | | mutex_spin_wait(void*, bool, char const*, unsigned long)
|
| | | | | |
|
| | | | | |--75.08%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.7
|
| | | | | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index
|
| | | | | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned cha
|
| | | | | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned
|
| | | | | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long
|
Attachments
Issue Links
- relates to
-
MDEV-8684 UT_RELAX_CPU isn't at all relaxing
-
- Closed
-
Activity
Description |
With the attached SQL and psdoit script to run queries concurrently, you can see that the CREATE TEMPORARY TABLE part of the query causes concurrency to *tank*. The related issue of It appears that CREATE TEMPORARY TABLE is triggering InnoDB to go and do a whole bunch of locking that it doesn't do when you just run a plain SELECT. The addition of CREATE TEMPORARY TABLE makes performance 280x worse. {{ # mysql -u root < sql # time ./psdoit 1 0.022s # time ./psdoit 10 0.112s # time ./psdoit 100 7.150s # time ./psdoit 200 30.422s # time ./psdoit 400 190.378s Things get very bad, very fast. We spend almost all our time in a locking food fight: 37.42% mysqld mysqld [.] ut_delay(unsigned long) | ---ut_delay(unsigned long) | |--99.74%-- mutex_spin_wait(void*, bool, char const*, unsigned long) | | | |--74.70%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.71] | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*) | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*, unsigned long, unsigned long, | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long) | | | | | |--76.07%-- ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) | | | handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) | | | handler::ha_index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) | | | join_read_key2(THD*, st_join_table*, TABLE*, st_table_ref*) | | | sub_select(JOIN*, st_join_table*, bool) | | | and: 27.96% mysqld [kernel.kallsyms] [k] _raw_spin_lock | ---_raw_spin_lock | |--58.11%-- futex_wait_setup | | | |--99.96%-- 0 | | futex_wait | | do_futex | | sys_futex | | system_call | | | | | |--64.91%-- __lll_lock_wait | | | | | | | |--83.30%-- pthread_mutex_lock | | | | | | | | | |--52.72%-- os_event_reset(os_event*) | | | | | sync_array_reserve_cell(sync_array_t*, void*, unsigned long, char const*, unsigned long, unsi | | | | | mutex_spin_wait(void*, bool, char const*, unsigned long) | | | | | | | | | | | |--75.08%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.7 | | | | | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index | | | | | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned cha | | | | | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned | | | | | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long }} |
With the attached SQL and psdoit script to run queries concurrently, you can see that the CREATE TEMPORARY TABLE part of the query causes concurrency to *tank*. The related issue of It appears that CREATE TEMPORARY TABLE is triggering InnoDB to go and do a whole bunch of locking that it doesn't do when you just run a plain SELECT. The addition of CREATE TEMPORARY TABLE makes performance 280x worse. {{ # mysql -u root < sql # time ./psdoit 1 0.022s # time ./psdoit 10 0.112s # time ./psdoit 100 7.150s # time ./psdoit 200 30.422s # time ./psdoit 400 190.378s Things get very bad, very fast. We spend almost all our time in a locking food fight: 37.42% mysqld mysqld [.] ut_delay(unsigned long) | ---ut_delay(unsigned long) | |--99.74%-- mutex_spin_wait(void*, bool, char const*, unsigned long) | | | |--74.70%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.71] | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*) | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*, unsigned long, unsigned long, | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long) | | | | | |--76.07%-- ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) | | | handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) | | | handler::ha_index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) | | | join_read_key2(THD*, st_join_table*, TABLE*, st_table_ref*) | | | sub_select(JOIN*, st_join_table*, bool) | | | and: 27.96% mysqld [kernel.kallsyms] [k] _raw_spin_lock | ---_raw_spin_lock | |--58.11%-- futex_wait_setup | | | |--99.96%-- 0 | | futex_wait | | do_futex | | sys_futex | | system_call | | | | | |--64.91%-- __lll_lock_wait | | | | | | | |--83.30%-- pthread_mutex_lock | | | | | | | | | |--52.72%-- os_event_reset(os_event*) | | | | | sync_array_reserve_cell(sync_array_t*, void*, unsigned long, char const*, unsigned long, unsi | | | | | mutex_spin_wait(void*, bool, char const*, unsigned long) | | | | | | | | | | | |--75.08%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.7 | | | | | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index | | | | | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned cha | | | | | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned | | | | | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long }} |
Description |
With the attached SQL and psdoit script to run queries concurrently, you can see that the CREATE TEMPORARY TABLE part of the query causes concurrency to *tank*. The related issue of It appears that CREATE TEMPORARY TABLE is triggering InnoDB to go and do a whole bunch of locking that it doesn't do when you just run a plain SELECT. The addition of CREATE TEMPORARY TABLE makes performance 280x worse. {{ # mysql -u root < sql # time ./psdoit 1 0.022s # time ./psdoit 10 0.112s # time ./psdoit 100 7.150s # time ./psdoit 200 30.422s # time ./psdoit 400 190.378s Things get very bad, very fast. We spend almost all our time in a locking food fight: 37.42% mysqld mysqld [.] ut_delay(unsigned long) | ---ut_delay(unsigned long) | |--99.74%-- mutex_spin_wait(void*, bool, char const*, unsigned long) | | | |--74.70%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.71] | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*) | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*, unsigned long, unsigned long, | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long) | | | | | |--76.07%-- ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) | | | handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) | | | handler::ha_index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) | | | join_read_key2(THD*, st_join_table*, TABLE*, st_table_ref*) | | | sub_select(JOIN*, st_join_table*, bool) | | | and: 27.96% mysqld [kernel.kallsyms] [k] _raw_spin_lock | ---_raw_spin_lock | |--58.11%-- futex_wait_setup | | | |--99.96%-- 0 | | futex_wait | | do_futex | | sys_futex | | system_call | | | | | |--64.91%-- __lll_lock_wait | | | | | | | |--83.30%-- pthread_mutex_lock | | | | | | | | | |--52.72%-- os_event_reset(os_event*) | | | | | sync_array_reserve_cell(sync_array_t*, void*, unsigned long, char const*, unsigned long, unsi | | | | | mutex_spin_wait(void*, bool, char const*, unsigned long) | | | | | | | | | | | |--75.08%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.7 | | | | | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index | | | | | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned cha | | | | | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned | | | | | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long }} |
With the attached SQL and psdoit script to run queries concurrently, you can see that the CREATE TEMPORARY TABLE part of the query causes concurrency to *tank*. The related issue of It appears that CREATE TEMPORARY TABLE is triggering InnoDB to go and do a whole bunch of locking that it doesn't do when you just run a plain SELECT. The addition of CREATE TEMPORARY TABLE makes performance 280x worse. {noformat} # mysql -u root < sql # time ./psdoit 1 0.022s # time ./psdoit 10 0.112s # time ./psdoit 100 7.150s # time ./psdoit 200 30.422s # time ./psdoit 400 190.378s {noformat} Things get very bad, very fast. We spend almost all our time in a locking food fight: {noformat} 37.42% mysqld mysqld [.] ut_delay(unsigned long) | ---ut_delay(unsigned long) | |--99.74%-- mutex_spin_wait(void*, bool, char const*, unsigned long) | | | |--74.70%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.71] | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*) | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*, unsigned long, unsigned long, | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long) | | | | | |--76.07%-- ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) | | | handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) | | | handler::ha_index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) | | | join_read_key2(THD*, st_join_table*, TABLE*, st_table_ref*) | | | sub_select(JOIN*, st_join_table*, bool) | | | {noformat} and: {noformat} 27.96% mysqld [kernel.kallsyms] [k] _raw_spin_lock | ---_raw_spin_lock | |--58.11%-- futex_wait_setup | | | |--99.96%-- 0 | | futex_wait | | do_futex | | sys_futex | | system_call | | | | | |--64.91%-- __lll_lock_wait | | | | | | | |--83.30%-- pthread_mutex_lock | | | | | | | | | |--52.72%-- os_event_reset(os_event*) | | | | | sync_array_reserve_cell(sync_array_t*, void*, unsigned long, char const*, unsigned long, unsi | | | | | mutex_spin_wait(void*, bool, char const*, unsigned long) | | | | | | | | | | | |--75.08%-- pfs_mutex_enter_func(ib_mutex_t*, char const*, unsigned long) [clone .constprop.7 | | | | | | lock_rec_convert_impl_to_expl(buf_block_t const*, unsigned char const*, dict_index | | | | | | lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned cha | | | | | | sel_set_rec_lock(buf_block_t const*, unsigned char const*, dict_index_t*, unsigned | | | | | | row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long {noformat} |
Status | Open [ 1 ] | Confirmed [ 10101 ] |
Fix Version/s | 10.1 [ 16100 ] | |
Fix Version/s | 10.0 [ 16000 ] | |
Affects Version/s | 10.1 [ 16100 ] | |
Affects Version/s | 10.0 [ 16000 ] | |
Affects Version/s | 10.0.17 [ 18300 ] | |
Assignee | Sergey Vojtovich [ svoj ] |
Assignee | Sergey Vojtovich [ svoj ] | Jan Lindström [ jplindst ] |
Sprint | 10.0.22 [ 17 ] |
Rank | Ranked higher |
Comment | [ Can you share your my.cnf file, I could not repeat this problem using Linux j35-jan-1 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt11-1+deb8u3 (2015-08-04) x86_64 GNU/Linux and log-bin, mixed, innodb-locks-unsafe-for-binlog=0. I used MySQL 5.6.27 and MariaDB 10.0.21 (development version). ] |
Component/s | Storage Engine - XtraDB [ 10135 ] | |
Fix Version/s | N/A [ 14700 ] | |
Fix Version/s | 10.0 [ 16000 ] | |
Fix Version/s | 10.1 [ 16100 ] | |
Resolution | Not a Bug [ 6 ] | |
Status | Confirmed [ 10101 ] | Closed [ 6 ] |
Workflow | MariaDB v3 [ 71230 ] | MariaDB v4 [ 149523 ] |
One possibility as to what's going on is that InnoDB is taking locks as if statement based binary logging is enabled.
I'd argue that in this day and age, it should do so based on mixed mode replication rather than statement based, although I haven't looked at what the default binlog-format is in modern MariaDB (although there's probably a strong case for mixed mode if it isn't already)