Bug #75981 MySQL 5.7.5 30% slower than 5.6.23 for 1 thread write
Submitted: 20 Feb 2015 13:56 Modified: 9 Apr 2015 4:35
Reporter: Jaime Crespo (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S5 (Performance)
Version:5.7.6 OS:Any
Assigned to: CPU Architecture:Any
Tags: innodb, performance, regression, single-thread

[20 Feb 2015 13:56] Jaime Crespo
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.
[20 Feb 2015 14:23] Jaime Crespo
More info, just in case it's useful:

mysql> SELECT EVENT_NAME, COUNT_STAR, sys.format_time(SUM_TIMER_WAIT) FROM ps_57.events_waits_summary_global_by_event_name WHERE COUNT_STAR > 0 ORDER BY SUM_TIMER_WAIT DESC;
+---------------------------------------------------+------------+---------------------------------+
| EVENT_NAME                                        | COUNT_STAR | sys.format_time(SUM_TIMER_WAIT) |
+---------------------------------------------------+------------+---------------------------------+
| wait/io/table/sql/handler                         |   46741126 | 00:03:29.81                     |
| wait/io/file/innodb/innodb_data_file              |     295845 | 00:01:34.28                     |
| idle                                              |       1456 | 00:01:07.42                     |
| wait/io/file/innodb/innodb_log_file               |       5169 | 24.58 s                         |
| wait/synch/sxlock/innodb/index_tree_rw_lock       |   46962348 | 2.00 s                          |
| wait/io/file/sql/load                             |      28239 | 591.59 ms                       |
| wait/synch/sxlock/innodb/fil_space_latch          |     442651 | 28.48 ms                        |
| wait/io/file/myisam/kfile                         |       4781 | 7.92 ms                         |
| wait/io/file/sql/FRM                              |       1456 | 6.47 ms                         |
| wait/io/file/csv/metadata                         |          8 | 3.91 ms                         |
| wait/io/file/myisam/dfile                         |       2345 | 3.51 ms                         |
| wait/io/socket/sql/client_connection              |       1185 | 2.63 ms                         |
| wait/synch/mutex/sql/THD::LOCK_thd_data           |       1134 | 70.98 us                        |
| wait/synch/mutex/sql/THD::LOCK_query_plan         |       1548 | 53.01 us                        |
| wait/io/file/sql/casetest                         |         10 | 49.20 us                        |
| wait/io/file/sql/dbopt                            |         11 | 43.41 us                        |
| wait/io/file/sql/pid                              |          3 | 41.75 us                        |
| wait/synch/mutex/sql/THD::LOCK_thd_query          |        979 | 41.25 us                        |
| wait/io/file/csv/data                             |          4 | 23.57 us                        |
| wait/io/file/sql/ERRMSG                           |          5 | 22.70 us                        |
| wait/io/file/mysys/charset                        |          3 | 11.79 us                        |
| wait/synch/mutex/myisam/MYISAM_SHARE::intern_lock |        303 | 10.61 us                        |
| wait/synch/sxlock/innodb/dict_table_stats         |         42 | 9.22 us                         |
| wait/io/file/sql/misc                             |          1 | 4.26 us                         |
| wait/io/file/archive/data                         |          2 | 3.55 us                         |
| wait/io/file/sql/global_ddl_log                   |          2 | 2.01 us                         |
| wait/lock/table/sql/handler                       |          1 | 835.34 ns                       |
| wait/synch/rwlock/sql/MDL_lock::rwlock            |          4 | 224.58 ns                       |
+---------------------------------------------------+------------+---------------------------------+
28 rows in set (0.00 sec)

mysql> SELECT EVENT_NAME, COUNT_STAR, sys.format_time(SUM_TIMER_WAIT) FROM ps_56.events_waits_summary_global_by_event_name WHERE COUNT_STAR > 0 ORDER BY SUM_TIMER_WAIT DESC;
+---------------------------------------------------+------------+---------------------------------+
| EVENT_NAME                                        | COUNT_STAR | sys.format_time(SUM_TIMER_WAIT) |
+---------------------------------------------------+------------+---------------------------------+
| idle                                              |       1169 | 00:14:04.33                     |
| wait/io/table/sql/handler                         |   46741126 | 00:02:15.50                     |
| wait/io/file/innodb/innodb_data_file              |     294361 | 00:01:36.01                     |
| wait/io/file/innodb/innodb_log_file               |       4147 | 23.52 s                         |
| wait/io/file/sql/load                             |      28239 | 8.90 s                          |
| wait/synch/mutex/innodb/trx_undo_mutex            |   46741143 | 1.29 s                          |
| wait/synch/rwlock/innodb/index_tree_rw_lock       |     887865 | 41.58 ms                        |
| wait/synch/rwlock/innodb/fil_space_latch          |     442597 | 14.92 ms                        |
| wait/io/file/sql/FRM                              |       1106 | 6.50 ms                         |
| wait/io/file/myisam/kfile                         |       4025 | 5.47 ms                         |
| wait/io/file/myisam/dfile                         |       1913 | 5.06 ms                         |
| wait/io/file/csv/metadata                         |          8 | 4.66 ms                         |
| wait/io/socket/sql/client_connection              |        874 | 1.24 ms                         |
| wait/synch/mutex/sql/THD::LOCK_thd_data           |       1512 | 64.64 us                        |
| wait/io/file/sql/pid                              |          3 | 62.78 us                        |
| wait/io/file/sql/casetest                         |         10 | 51.68 us                        |
| wait/io/file/csv/data                             |          4 | 24.48 us                        |
| wait/io/file/sql/dbopt                            |         12 | 24.38 us                        |
| wait/io/file/sql/ERRMSG                           |          5 | 23.76 us                        |
| wait/synch/mutex/myisam/MYISAM_SHARE::intern_lock |        229 | 11.35 us                        |
| wait/io/file/mysys/charset                        |          3 | 10.87 us                        |
| wait/io/file/archive/data                         |          3 | 4.36 us                         |
| wait/synch/mutex/innodb/trx_mutex                 |        148 | 3.94 us                         |
| wait/io/file/sql/global_ddl_log                   |          2 | 1.71 us                         |
| wait/io/file/sql/misc                             |          1 | 1.53 us                         |
| wait/lock/table/sql/handler                       |          2 | 991.52 ns                       |
| wait/synch/rwlock/innodb/dict_table_stats         |          6 | 793.73 ns                       |
| wait/synch/rwlock/sql/MDL_lock::rwlock            |          2 | 167.58 ns                       |
| wait/synch/mutex/mysys/THR_LOCK::mutex            |          2 | 150.20 ns                       |
+---------------------------------------------------+------------+---------------------------------+
29 rows in set (0.00 sec)
[20 Feb 2015 19:53] Mark Callaghan
Thank you for sharing. I have reported low-concurrency regressions in 5.7 as well -- http://smalldatum.blogspot.com/2014/10/low-concurrency-performance-for-updated.html
[10 Mar 2015 16:15] Jaime Crespo
Still applies to 5.7.6:

Test buffer=8G,log=2G,no_p_s,no_dw,no_chksm,no_ibuf,lru,io_cap

5.6.23: 132±3 s
5.7.6 : 196±2 s
[9 Apr 2015 4:35] Umesh Shastry
Hello Jaime Crespo,

Thank you for the report and test case.
Observed this with 5.6.24 and 5.7.6 on OL7.

Thanks,
Umesh
[4 Jun 2015 7:28] Marko Mäkelä
The first regression for this test case was introduced by me in May 2013, in MySQL 5.7.2.
For fixing that regression, I filed
Bug#77246 Reintroduce adaptive hash index field prefixes to speed up sequential inserts

Because other regression remains, with both innodb_adaptive_hash_index=ON and innodb_adaptive_hash_index=OFF, this bug will be kept open.
[11 Jun 2015 10:50] Marko Mäkelä
Posted by developer:
 
Independent of my bug fix mentioned above, some regression is still present.
We will keep this bug open until it has been addressed.
[5 Nov 2017 7:12] Umesh Shastry
Bug #88315 marked as duplicate of this one