Description:
Single-thread write performance, as tested with the "LOAD DATA" statement takes around 30% longer than the same query, with the same data, configuration and hardware on 5.7.
How to repeat:
* Hardware:
OS: CentOS Linux release 7.0.1406 (Core)
Kernel: 3.10.0-123.20.1.el7.x86_64
CPU: 8xIntel(R) Core(TM) i7-4770K CPU @ 3.50GHz
Memory: 16GB
Disk: SSD Samsung 850 Pro MZ-7KE512BW (512 Gb, SATA 600), using XFS
* Tab-separated file loaded:
Can be downloaded from http://dbahire.com/nodes.osm.7z
3,700,635,579 bytes uncompressed with 46,741,126 rows. Looks like this:
171773 38.6048402 -0.0489871 4 2012-08-25 00:37:46 12850816 472193 rubensd
171774 38.6061981 -0.0496867 2 2008-01-19 10:23:21 666916 9250 j3m
171775 38.6067166 -0.0498342 2 2008-01-19 10:23:21 666916 9250 j3m
171776 38.6028122 -0.0497136 5 2012-08-25 00:26:40 12850816 472193 rubensd
171933 40.4200658 -3.7016652 6 2011-11-29 05:37:42 9984625 33103 sergionaranja
* Table structure:
CREATE TABLE `nodes` (
`id` bigint PRIMARY KEY,
`lat` decimal(9,7),
`lon` decimal(10,7),
`version` int,
`timestamp` timestamp,
`changeset` bigint,
`uid` bigint,
`user` varchar(255)
)
* Query executed:
time ./sandboxes/msb_5_7_5/use -e "LOAD DATA INFILE '/home/jynus/nodes.csv' INTO TABLE test.nodes"
time ./sandboxes/msb_5_6_23/use -e "LOAD DATA INFILE '/home/jynus/nodes.csv' INTO TABLE test.nodes"
* MySQL server:
Downloaded from:
http://cdn.mysql.com/Downloads/MySQL-5.6/mysql-5.6.23-linux-glibc2.5-x86_64.tar.gz
http://cdn.mysql.com/Downloads/MySQL-5.7/mysql-5.7.5-m15-linux-glibc2.5-x86_64.tar.gz
Configuration:
(MySQL Sandbox defaults for 5.6)
# The MySQL Sandbox
# Copyright (C) 2006-2013 Giuseppe Maxia
# Contacts: http://datacharmer.org
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; version 2 of the License
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
[mysql]
prompt='mysql [\h] {\u} (\d) > '
#
[client]
user = msandbox
password = msandbox
port = 5623
socket = /tmp/mysql_sandbox5623.sock
[mysqld]
user = jynus
port = 5623
socket = /tmp/mysql_sandbox5623.sock
basedir = /home/jynus/5.6.23
datadir = /home/jynus/sandboxes/msb_5_6_23/data
tmpdir = /home/jynus/sandboxes/msb_5_6_23/tmp
lower_case_table_names = 0
pid-file = /home/jynus/sandboxes/msb_5_6_23/data/mysql_sandbox5623.pid
bind-address = 127.0.0.1
# slow-query-log = on
# slow-query-log-file=/home/jynus/sandboxes/msb_5_6_23/data/msandbox-slow.log
# general-log = on
# general-log-file=/home/jynus/sandboxes/msb_5_6_23/data/msandbox-general.log
#
# additional options passed through 'my_clause'
#
log-error=msandbox.err
(MySQL Sandbox defaults for 5.7)
# The MySQL Sandbox
# Copyright (C) 2006-2013 Giuseppe Maxia
# Contacts: http://datacharmer.org
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; version 2 of the License
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
[mysql]
prompt='mysql [\h] {\u} (\d) > '
#
[client]
user = msandbox
password = msandbox
port = 5705
socket = /tmp/mysql_sandbox5705.sock
[mysqld]
user = jynus
port = 5705
socket = /tmp/mysql_sandbox5705.sock
basedir = /home/jynus/5.7.5
datadir = /home/jynus/sandboxes/msb_5_7_5/data
tmpdir = /home/jynus/sandboxes/msb_5_7_5/tmp
lower_case_table_names = 0
pid-file = /home/jynus/sandboxes/msb_5_7_5/data/mysql_sandbox5705.pid
bind-address = 127.0.0.1
# slow-query-log = on
# slow-query-log-file=/home/jynus/sandboxes/msb_5_7_5/data/msandbox-slow.log
# general-log = on
# general-log-file=/home/jynus/sandboxes/msb_5_7_5/data/msandbox-general.log
#
# additional options passed through 'my_clause'
#
log-error=msandbox.err
* Results:
Load time in 5.6, defaults (s) 186.574
Load time in 5.7, defatuts (s) 256.898
Regression 1 - 5.7 time / 5.6 time, % 27.37%
Adding some or all of the following options improves the overall performance of the process, but the relative number stays the same:
innodb_buffer_pool_size = 8G
innodb_log_file_size = 2G
innodb_doublewrite = 0
innodb_checksum_algorithm=NONE
performance_schema = 0
innodb_change_buffering=NONE
innodb_flush_method=O_DIRECT
Load time in 5.6, buffer=8G,log=2G,no_p_s,no_dw,no_chksm,no_ibuf,o_dir (s) 129.886
Load time in 5.7, buffer=8G,log=2G,no_p_s,no_dw,no_chksm,no_ibuf,o_dir (s) 202.285
Regression 1 - 5.7 time / 5.6 time, % 35.79%
The different row insertion rates can be observed here:
http://dbahire.com/wp-content/uploads/2015/02/mysqladmin_ext-unoptimized.png
http://dbahire.com/wp-content/uploads/2015/02/mysqladmin_ext-odirect.png
SQL is not the reason for the change:
mysql> SELECT
-> REPLACE(event_name, 'stage/sql/', '') AS Status,
-> sys.format_time(timer_wait) as Duration
-> FROM
-> ps_57.events_stages_history_long
-> WHERE
-> NESTING_EVENT_ID=33 AND thread_id = 27
-> ORDER BY event_id;
+----------------------+-------------+
| Status | Duration |
+----------------------+-------------+
| starting | 18.08 us |
| checking permissions | 4.11 us |
| Opening tables | 141.36 us |
| System lock | 00:04:28.71 |
| query end | 20.69 ms |
| closing tables | 9.22 us |
| freeing items | 15.69 us |
| cleaning up | 1.05 us |
+----------------------+-------------+
8 rows in set (0.01 sec)
mysql> SELECT
-> REPLACE(event_name, 'stage/sql/', '') AS Status,
-> sys.format_time(timer_wait) as Duration
-> FROM
-> ps_56.events_stages_history_long
-> WHERE
-> NESTING_EVENT_ID=28 AND thread_id = 25
-> ORDER BY event_id;
+----------------------+-------------+
| Status | Duration |
+----------------------+-------------+
| init | 18.11 us |
| checking permissions | 1.59 us |
| Opening tables | 152.79 us |
| System lock | 00:03:15.63 |
| query end | 45.26 ms |
| closing tables | 7.87 us |
| freeing items | 11.61 us |
| logging slow query | 614.00 ns |
| cleaning up | 879.00 ns |
+----------------------+-------------+
9 rows in set (0.00 sec)
Relevant perf output (5.6):
CPU: Intel Haswell microarchitecture, speed 4.3e+06 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000
samples % image name symbol name
529359 11.5779 mysqld READ_INFO::read_field()
280632 6.1378 mysqld log_group_write_buf(log_group_t*, unsigned char*, unsigned long, unsigned long, unsigned long)
193192 4.2254 mysqld mysql_load(THD*, sql_exchange*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool)
170948 3.7389 mysqld rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, unsigned long, mem_block_info_t**)
142330 3.1130 mysqld str_to_datetime
131894 2.8847 no-vmlinux /no-vmlinux
111353 2.4355 mysqld rw_lock_x_lock_func(rw_lock_t*, unsigned long, char const*, unsigned long)
106904 2.3381 mysqld buf_page_get_gen(unsigned long, unsigned long, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*)
95138 2.0808 mysqld my_mbcharlen_8bit
89957 1.9675 mysqld Field_longlong::store(char const*, unsigned int, charset_info_st const*)
88553 1.9368 mysqld mtr_add_dirtied_pages_to_flush_list(mtr_t*)
88315 1.9316 mysqld rec_convert_dtuple_to_rec(unsigned char*, dict_index_t const*, dtuple_t const*, unsigned long)
88168 1.9284 mysqld trx_undo_report_row_operation(unsigned long, unsigned long, que_thr_t*, dict_index_t*, dtuple_t const*, upd_t const*, unsigned long, unsigned char const*, unsigned long const*, unsigned long*)
Relevant perf output (5.7):
CPU: Intel Haswell microarchitecture, speed 4.3e+06 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000
samples % image name symbol name
531638 6.7421 mysqld buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*, bool)
525699 6.6668 mysqld rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, unsigned long, mem_block_info_t**)
513852 6.5165 mysqld cmp_dtuple_rec_with_match_low(dtuple_t const*, unsigned char const*, unsigned long const*, unsigned long, unsigned long*)
400261 5.0760 mysqld page_cur_search_with_match(buf_block_t const*, dict_index_t const*, dtuple_t const*, unsigned long, unsigned long*, unsigned long*, page_cur_t*, rtr_info*)
383541 4.8640 mysqld READ_INFO::read_field()
263381 3.3401 mysqld log_write_up_to(unsigned long, bool)
231977 2.9419 mysqld mysql_load(THD*, sql_exchange*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool)
216547 2.7462 mysqld rw_lock_s_lock_func(rw_lock_t*, unsigned long, char const*, unsigned long) [clone .clone.1]
183326 2.3249 mysqld rw_lock_x_lock_func(rw_lock_t*, unsigned long, char const*, unsigned long)
181868 2.3064 mysqld btr_cur_search_to_nth_level(dict_index_t*, unsigned long, dtuple_t const*, unsigned long, unsigned long, btr_cur_t*, unsigned long, char const*, unsigned long, mtr_t*)
146386 1.8564 no-vmlinux /no-vmlinux
131885 1.6725 mysqld str_to_datetime
131225 1.6642 mysqld my_mbcharlen_8bit
117529 1.4905 libc-2.17.so __memcmp_sse4_1
105865 1.3426 libc-2.17.so __memmove_ssse3_back
105853 1.3424 mysqld internal_str2dec
99852 1.2663 libc-2.17.so __GI_strcmp
97351 1.2346 mysqld trx_undo_report_row_operation(unsigned long, unsigned long, que_thr_t*, dict_index_t*, dtuple_t const*, upd_t const*, unsigned long, unsigned char const*, unsigned long const*, unsigned long*)
89685 1.1374 mysqld row_insert_for_mysql_using_ins_graph(unsigned char const*, row_prebuilt_t*)
89555 1.1357 [vdso] (tgid:15030 range:0x7fff591b9000-0x7fff591bafff) [vdso] (tgid:15030 range:0x7fff591b9000-0x7fff591bafff)
86784 1.1006 mysqld Field_longlong::store(char const*, unsigned long, charset_info_st const*)
86134 1.0923 mysqld page_cur_insert_rec_write_log(unsigned char*, unsigned long, unsigned char*, dict_index_t*, mtr_t*)
Relevant gdb aggregated output (5.6):
Thu Feb 19 21:55:41 CET 2015
1999 __io_getevents_0_4(libaio.so.1),os_aio_linux_collect(os0file.cc:4956),os_aio_linux_handle(os0file.cc:4956),fil_aio_wait(fil0fil.cc:5753),io_handler_thread(srv0start.cc:485),start_thread(libpthread.so.0),clone(libc.so.6)
200 sigwait(libpthread.so.0),signal_hand(mysqld.cc:3185),pfs_spawn_thread(pfs.cc:1860),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_wait,os_cond_wait(os0sync.cc:214),os_event_wait_low(os0sync.cc:214),buf_dump_thread(buf0dump.cc:594),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:177),os_event_wait_time_low(os0sync.cc:177),srv_monitor_thread(srv0srv.cc:1534),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:177),os_event_wait_time_low(os0sync.cc:177),srv_error_monitor_thread(srv0srv.cc:1765),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:177),os_event_wait_time_low(os0sync.cc:177),lock_wait_timeout_thread(lock0wait.cc:503),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:177),os_event_wait_time_low(os0sync.cc:177),ib_wqueue_timedwait(ut0wqueue.cc:154),fts_optimize_thread(fts0opt.cc:3001),start_thread(libpthread.so.0),clone(libc.so.6)
200 poll(libc.so.6),handle_connections_sockets(mysqld.cc:6249),mysqld_main(mysqld.cc:5668),__libc_start_main(libc.so.6),_start
198 pthread_cond_wait,os_cond_wait(os0sync.cc:214),os_event_wait_low(os0sync.cc:214),srv_purge_coordinator_suspend(srv0srv.cc:2635),srv_purge_coordinator_thread(srv0srv.cc:2635),start_thread(libpthread.so.0),clone(libc.so.6)
198 pthread_cond_timedwait,os_cond_wait_timed(os0sync.cc:177),os_event_wait_time_low(os0sync.cc:177),dict_stats_thread(dict0stats_bg.cc:348),start_thread(libpthread.so.0),clone(libc.so.6)
187 select(libc.so.6),os_thread_sleep(os0thread.cc:261),srv_master_sleep(srv0srv.cc:2296),srv_master_thread(srv0srv.cc:2296),start_thread(libpthread.so.0),clone(libc.so.6)
183 select(libc.so.6),os_thread_sleep(os0thread.cc:261),page_cleaner_sleep_if_needed(buf0flu.cc:2375),buf_flush_page_cleaner_thread(buf0flu.cc:2375),start_thread(libpthread.so.0),clone(libc.so.6)
Relevant gdb aggregated output (5.7):
Thu Feb 19 22:01:10 CET 2015
2000 __io_getevents_0_4(libaio.so.1),LinuxAIOHandler::collect(os0file.cc:2031),LinuxAIOHandler::poll(os0file.cc:2163),os_aio_linux_handle(os0file.cc:2219),fil_aio_wait(fil0fil.cc:5487),io_handler_thread(srv0start.cc:282),start_thread(libpthread.so.0),clone(libc.so.6)
200 sigwait(libpthread.so.0),signal_hand(mysqld.cc:2183),pfs_spawn_thread(pfs.cc:2137),start_thread(libpthread.so.0),clone(libc.so.6)
200 sigwaitinfo(libc.so.6),timer_notify_thread_func(posix_timers.c:80),pfs_spawn_thread(pfs.cc:2137),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_wait,wait(os0event.cc:217),os_event::wait_low(os0event.cc:217),buf_resize_thread(buf0buf.cc:2700),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_wait,wait(os0event.cc:217),os_event::wait_low(os0event.cc:217),buf_dump_thread(buf0dump.cc:656),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:382),os_event::wait_time_low(os0event.cc:544),srv_monitor_thread(srv0srv.cc:1482),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:382),os_event::wait_time_low(os0event.cc:544),srv_error_monitor_thread(srv0srv.cc:1648),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:382),os_event::wait_time_low(os0event.cc:544),lock_wait_timeout_thread(lock0wait.cc:496),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:382),os_event::wait_time_low(os0event.cc:544),ib_wqueue_timedwait(ut0wqueue.cc:161),fts_optimize_thread(fts0opt.cc:3022),start_thread(libpthread.so.0),clone(libc.so.6)
200 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:382),os_event::wait_time_low(os0event.cc:544),dict_stats_thread(dict0stats_bg.cc:363),start_thread(libpthread.so.0),clone(libc.so.6)
200 poll(libc.so.6),Mysqld_socket_listener::listen_for_connection_event(socket_connection.cc:843),connection_event_loop(connection_acceptor.h:67),mysqld_main(connection_acceptor.h:67),__libc_start_main(libc.so.6),_start
200 nanosleep(libpthread.so.0),os_thread_sleep(os0thread.cc:258),srv_master_sleep(srv0srv.cc:2161),srv_master_thread(srv0srv.cc:2161),start_thread(libpthread.so.0),clone(libc.so.6)
199 pthread_cond_wait,wait(os0event.cc:217),os_event::wait_low(os0event.cc:217),srv_purge_coordinator_suspend(srv0srv.cc:2509),srv_purge_coordinator_thread(srv0srv.cc:2509),start_thread(libpthread.so.0),clone(libc.so.6)
199 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:382),os_event::wait_time_low(os0event.cc:544),pc_sleep_if_needed(buf0flu.cc:2390),buf_flush_page_cleaner_coordinator(buf0flu.cc:2390),start_thread(libpthread.so.0),clone(libc.so.6)
Suggested fix:
Make single-thread write performance in 5.7 as fast or at similar levels (- 0-5%) than 5.6.
Potentially related bug: http://bugs.mysql.com/bug.php?id=74342
I had a similar problem with 5.7.4 on a RAID of HD disks, but it was only of around 15% and it disappeared by disabling the doublewrite buffer. It is no longer the case.
