| 2016-11-30 12:38:20 |
Francisco Bordenave |
description |
When loading big files using LOAD DATA INFILE Percona Server becomes unresponsive for some time during "Query end" stage. During this flushing new connections got stuck in Login status until LOAD DATA INFILE finsihes, this can take several minutes depending on the file size.
This is processlist output after we changed permissions to several users to avoid them getting access during the process so Killed status might be connection being rejected:
performance_schema> show processlist;
+--------+-----------------+---------------------+---------------------------+-------------+------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+--------+-----------------+---------------------+---------------------------+-------------+------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+
| 763513 | sysconfig | 10.96.123.30:42632 | system_configurations | Sleep | 83 | | NULL | 1 | 0 |
| 770141 | engin12 | 10.96.122.234:41073 | conf | Killed | 180 | cleaning up | NULL | 0 | 0 |
| 776030 | testing | localhost | dsp_manager | Query | 103 | starting | show binary logs | 0 | 0 |
| 779746 | engin12 | 10.96.122.234:59783 | conf | Sleep | 5 | | NULL | 1 | 0 |
| 780089 | ppp | 10.96.123.38:39834 | ppp | Query | 484 | starting | commit | 0 | 0 |
| 785960 | ppp | 10.96.123.38:37732 | ppp | Query | 482 | starting | commit | 0 | 0 |
| 786387 | creat_123_serv | 10.96.122.227:41110 | creative_approval_service | Query | 482 | starting | commit | 0 | 0 |
| 786423 | testing | localhost | performance_schema | Query | 0 | starting | show processlist | 0 | 0 |
| 786519 | testing | localhost | ai | Query | 840 | query end | load data local infile '/mnt/backups/db/utd/archive/20161124/ai/rrr_price_floor_10.txt' into table r | 0 | 0 |
| 788242 | slave | 10.96.122.201:51043 | NULL | Binlog Dump | 1435 | Master has sent all binlog to slave; waiting for more updates | NULL | 0 | 0 |
| 788358 | testing_user123 | 10.96.122.223:34029 | inventory_restriction | Query | 485 | starting | commit | 0 | 0 |
| 790646 | dspmgr | 10.96.120.78:44732 | dsp_manager | Killed | 449 | cleaning up | NULL | 0 | 0 |
| 790796 | fastl123 | 10.96.122.153:56137 | fastl123_installer | Killed | 446 | cleaning up | NULL | 0 | 0 |
| 790797 | fastl123 | 10.96.122.153:56138 | fastl123_installer | Killed | 446 | cleaning up | NULL | 0 | 0 |
| 790798 | fastl123 | 10.96.122.153:56139 | fastl123_installer | Killed | 446 | cleaning up | NULL | 0 | 0 |
| 790799 | fastl123 | 10.96.122.153:56141 | fastl123_installer | Killed | 446 | cleaning up | NULL | 0 | 0 |
| 790801 | fastl123 | 10.96.122.152:52671 | fastl123_installer | Query | 496 | starting | commit | 0 | 0 |
| 790803 | fastl123 | 10.96.122.152:52673 | fastl123_installer | Query | 495 | starting | commit | 0 | 0 |
| 790901 | testingMatcher | 10.83.125.21:53663 | testingMatcher | Query | 491 | starting | commit | 0 | 0 |
| 790910 | testingMatcher | 10.83.125.21:53664 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790911 | testingMatcher | 10.83.125.21:53665 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790912 | testingMatcher | 10.83.125.21:53666 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790913 | testingMatcher | 10.83.125.21:53667 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790914 | testingMatcher | 10.83.125.21:53668 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790915 | testingMatcher | 10.83.125.21:53669 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790916 | testingMatcher | 10.83.125.21:53670 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790917 | testingMatcher | 10.83.125.21:53671 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790918 | testingMatcher | 10.83.125.21:53672 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 791191 | engin12 | 10.96.122.141:58556 | arw | Killed | 316 | cleaning up | NULL | 0 | 0 |
| 791210 | dspmgr | 10.96.122.199:46862 | dsp_manager | Killed | 312 | cleaning up | NULL | 0 | 0 |
| 791234 | fastl123 | 10.96.122.14:37170 | fastl123_stats | Killed | 303 | cleaning up | NULL | 0 | 0 |
| 791422 | ppp | 10.96.123.38:34256 | ppp | Killed | 364 | cleaning up | NULL | 0 | 0 |
| 791423 | ppp | 10.96.123.38:34258 | ppp | Killed | 364 | cleaning up | NULL | 0 | 0 |
| 791424 | ppp | 10.96.123.38:34257 | ppp | Killed | 364 | cleaning up | NULL | 0 | 0 |
| 791433 | dspmgr | 10.96.120.78:47808 | dsp_manager | Killed | 257 | cleaning up | NULL | 0 | 0 |
| 792019 | fastl123 | 10.96.122.152:57568 | fastl123_installer | Killed | 415 | cleaning up | NULL | 0 | 0 |
| 792020 | fastl123 | 10.96.122.152:57569 | fastl123_installer | Killed | 414 | cleaning up | NULL | 0 | 0 |
| 792021 | fastl123 | 10.96.122.152:57570 | fastl123_installer | Killed | 454 | cleaning up | NULL | 0 | 0 |
| 792022 | fastl123 | 10.96.122.152:57571 | fastl123_installer | Killed | 424 | cleaning up | NULL | 0 | 0 |
| 792023 | fastl123 | 10.96.122.152:57572 | fastl123_installer | Killed | 440 | cleaning up | NULL | 0 | 0 |
| 792054 | ai | 10.96.122.229:46898 | ai | Query | 479 | starting | commit | 0 | 0 |
| 792066 | testing_user123 | 10.96.122.223:49000 | inventory_restriction | Killed | 429 | cleaning up | NULL | 0 | 0 |
| 792068 | fastl123 | 10.96.122.152:57741 | fastl123_installer | Killed | 444 | cleaning up | NULL | 0 | 0 |
| 792073 | readonly | 10.83.40.170:54683 | NULL | Query | 473 | Sending data | SHOW GLOBAL STATUS | 0 | 0 |
| 792074 | testingMatcher | 10.83.125.21:53866 | testingMatcher | Killed | 469 | cleaning up | NULL | 0 | 0 |
| 792075 | testingMatcher | 10.83.125.21:53867 | testingMatcher | Killed | 473 | cleaning up | NULL | 1 | 0 |
| 792076 | testingMatcher | 10.83.125.21:53868 | testingMatcher | Killed | 473 | cleaning up | NULL | 1 | 0 |
| 792077 | testingMatcher | 10.83.125.21:53869 | testingMatcher | Killed | 473 | cleaning up | NULL | 1 | 0 |
| 792078 | testingMatcher | 10.83.125.21:53870 | testingMatcher | Killed | 473 | cleaning up | NULL | 1 | 0 |
| 792079 | testing | localhost | dsp_manager | Killed | 473 | cleaning up | NULL | 0 | 0 |
| 792080 | testingMatcher | 10.83.125.21:53871 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792081 | testingMatcher | 10.83.125.21:53872 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792082 | testingMatcher | 10.83.125.21:53873 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792083 | testingMatcher | 10.83.125.21:53874 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792084 | testingMatcher | 10.83.125.21:53875 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792085 | testing | localhost | dsp_manager | Killed | 471 | cleaning up | NULL | 0 | 0 |
| 792086 | testing | localhost | dsp_manager | Killed | 470 | cleaning up | NULL | 0 | 0 |
| 792087 | creat_123_serv | 10.83.124.54:44097 | NULL | Killed | 470 | login | NULL | 0 | 0 |
| 792088 | creat_123_serv | 10.83.124.54:44096 | NULL | Killed | 470 | login | NULL | 0 | 0 |
| 792089 | creat_123_serv | 10.83.124.54:44098 | NULL | Killed | 470 | login | NULL | 0 | 0 |
| 792090 | testing | localhost | dsp_manager | Killed | 469 | cleaning up | NULL | 0 | 0 |
| 792091 | creat_123_serv | 10.83.124.54:44099 | NULL | Killed | 469 | login | NULL | 0 | 0 |
| 792092 | creat_123_serv | 10.83.124.54:44100 | NULL | Killed | 469 | login | NULL | 0 | 0 |
| 792093 | creat_123_serv | 10.83.124.54:44101 | NULL | Killed | 469 | login | NULL | 0 | 0 |
| 792094 | testing | localhost | dsp_manager | Killed | 468 | cleaning up | NULL | 0 | 0 |
| 792095 | creat_123_serv | 10.83.124.53:52018 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792096 | creat_123_serv | 10.83.124.53:52019 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792097 | creat_123_serv | 10.83.124.53:52020 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792098 | creat_123_serv | 10.83.124.54:44102 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792099 | creat_123_serv | 10.83.124.54:44103 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792100 | creat_123_serv | 10.83.124.54:44104 | NULL | Killed | 467 | login | NULL | 0 | 0 |
| 792101 | testing | localhost | dsp_manager | Killed | 467 | cleaning up | NULL | 0 | 0 |
| 792102 | creat_123_serv | 10.83.124.53:52021 | NULL | Killed | 467 | login | NULL | 0 | 0 |
| 792103 | creat_123_serv | 10.83.124.53:52022 | NULL | Killed | 467 | login | NULL | 0 | 0 |
| 792104 | creat_123_serv | 10.83.124.53:52024 | NULL | Killed | 467 | login | NULL | 0 | 0 |
| 792105 | creat_123_serv | 10.83.124.54:44106 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792106 | creat_123_serv | 10.83.124.54:44105 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792107 | creat_123_serv | 10.83.124.54:44108 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792108 | testing | localhost | dsp_manager | Killed | 466 | cleaning up | NULL | 0 | 0 |
| 792109 | creat_123_serv | 10.83.124.53:52025 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792110 | creat_123_serv | 10.83.124.53:52026 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792111 | creat_123_serv | 10.83.124.53:52028 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792112 | creat_123_serv | 10.83.124.54:44109 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792113 | creat_123_serv | 10.83.124.54:44110 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792114 | creat_123_serv | 10.83.124.54:44111 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792115 | creat_123_serv | 10.83.124.54:44112 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792116 | testing | localhost | dsp_manager | Killed | 465 | cleaning up | NULL | 0 | 0 |
| 792117 | creat_123_serv | 10.83.124.53:52029 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792118 | creat_123_serv | 10.83.124.53:52030 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792119 | creat_123_serv | 10.83.124.53:52031 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792120 | fastl123 | 10.96.122.152:57910 | fastl123_installer | Killed | 434 | cleaning up | NULL | 0 | 0 |
| 792121 | creat_123_serv | 10.83.124.54:44113 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792122 | testing | localhost | dsp_manager | Killed | 464 | cleaning up | NULL | 0 | 0 |
| 792123 | creat_123_serv | 10.83.124.53:52032 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792124 | creat_123_serv | 10.83.124.53:52033 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792125 | creat_123_serv | 10.83.124.53:52034 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792126 | creat_123_serv | 10.83.124.53:52035 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792127 | creat_123_serv | 10.83.124.54:44114 | NULL | Killed | 463 | login | NULL | 0 | 0 |
| 792128 | testing | localhost | dsp_manager | Killed | 463 | cleaning up | NULL | 0 | 0 |
| 792129 | creat_123_serv | 10.83.124.53:52036 | NULL | Killed | 463 | login | NULL | 0 | 0 |
| 792130 | creat_123_serv | 10.83.124.54:44117 | NULL | Killed | 462 | login | NULL | 0 | 0 |
+--------+-----------------+---------------------+---------------------------+-------------+------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+
101 rows in set (0.01 sec)
pt-pmp suggests some locking related release_resources mutex in thread handling used in Percona Server:
[root@frpq-utd9000.lab1 pmp]# perl pt-pmp -p 23791 -i 3 -s 1
Mon Nov 28 11:09:39 PST 2016
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff993fd000
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff993fd000
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff993fd000
192 __lll_lock_wait(libpthread.so.0),_L_lock_1233(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),THD::release_resources,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
84 poll(libc.so.6),vio_io_wait,vio_socket_io_wait,vio_read,net_read_raw_loop,net_read_packet,my_net_read,Protocol_classic::read_packet,Protocol_classic::get_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
30 libaio::??(libaio.so.1),LinuxAIOHandler::collect,LinuxAIOHandler::poll,os_aio_handler,fil_aio_wait,io_handler_thread,start_thread(libpthread.so.0),clone(libc.so.6)
24 nanosleep(libpthread.so.0),os_thread_sleep,buf_lru_manager,start_thread(libpthread.so.0),clone(libc.so.6)
15 pthread_cond_wait,Stage_manager::enroll_for,MYSQL_BIN_LOG::change_stage,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
9 pthread_cond_wait,os_event::wait_low,srv_worker_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_wait,os_event::wait_low,srv_purge_coordinator_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_wait,os_event::wait_low,buf_resize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_wait,os_event::wait_low,buf_dump_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_wait,compress_gtid_table,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_error_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,lock_wait_timeout_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,ib_wqueue_timedwait,fts_optimize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,dict_stats_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,MYSQL_BIN_LOG::wait_for_update_bin_log,Binlog_sender::send_binlog,Binlog_sender::run,mysql_binlog_send,com_binlog_dump,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 poll(libc.so.6),Mysqld_socket_listener::listen_for_connection_event,mysqld_main,__libc_start_main(libc.so.6),_start
3 nanosleep(libpthread.so.0),os_thread_sleep,srv_master_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 __lll_lock_wait(libpthread.so.0),_L_lock_1034(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),MYSQL_BIN_LOG::set_status_variables,show_binlog_vars,PFS_status_variable_cache::manifest,PFS_status_variable_cache::do_materialize_global,table_global_status::rnd_init,ha_perfschema::rnd_init,handler::ha_rnd_init,init_read_record,join_init_read_record,sub_select,JOIN::exec,TABLE_LIST::materialize_derived,join_materialize_derived,QEP_TAB::prepare_scan,sub_select,JOIN::exec,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 __lll_lock_wait(libpthread.so.0),_L_lock_1034(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),MYSQL_BIN_LOG::change_stage,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 do_sigwait(libpthread.so.0),sigwait(libpthread.so.0),signal_hand,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 do_sigwaitinfo(libc.so.6),sigwaitinfo(libc.so.6),timer_notify_thread_func,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
2 read(libpthread.so.0),my_read,my_b_fill,MYSQL_BIN_LOG::do_write_cache,MYSQL_BIN_LOG::write_cache,binlog_cache_data::flush,MYSQL_BIN_LOG::flush_thread_caches,MYSQL_BIN_LOG::process_flush_stage_queue,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit_stmt,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
1 write(libpthread.so.0),my_write,_my_b_write,MYSQL_BIN_LOG::do_write_cache,MYSQL_BIN_LOG::write_cache,binlog_cache_data::flush,MYSQL_BIN_LOG::flush_thread_caches,MYSQL_BIN_LOG::process_flush_stage_queue,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit_stmt,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
1 ut_time_ms,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
1 pthread_mutex_unlock(libpthread.so.0),os_event_reset,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
1 ::??,::??,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
Which is defined in sql/sql_class.cc as follows (PS 5.7.14-7):
void THD::release_resources()
{
DBUG_ASSERT(m_release_resources_done == false);
Global_THD_manager::get_instance()->release_thread_id(m_thread_id);
mysql_mutex_lock(&LOCK_status);
add_to_status(&global_status_var, &status_var, false);
/*
Status queries after this point should not aggregate THD::status_var
since the values has been added to global_status_var.
The status values are not reset so that they can still be read
by performance schema.
*/
status_var_aggregated= true;
mysql_mutex_unlock(&LOCK_status);
/* Ensure that no one is using THD */
mysql_mutex_lock(&LOCK_thd_data);
mysql_mutex_lock(&LOCK_query_plan);
/* Close connection */
#ifndef EMBEDDED_LIBRARY
if (is_classic_protocol() && get_protocol_classic()->get_vio())
{
vio_delete(get_protocol_classic()->get_vio());
get_protocol_classic()->end_net();
}
#endif
/* modification plan for UPDATE/DELETE should be freed. */
DBUG_ASSERT(query_plan.get_modification_plan() == NULL);
mysql_mutex_unlock(&LOCK_query_plan);
mysql_mutex_unlock(&LOCK_thd_data);
mysql_mutex_lock(&LOCK_thd_query);
mysql_mutex_unlock(&LOCK_thd_query);
stmt_map.reset(); /* close all prepared statements */
if (!cleanup_done)
cleanup();
mdl_context.destroy();
ha_close_connection(this);
/*
Debug sync system must be closed after ha_close_connection, because
DEBUG_SYNC is used in InnoDB connection handlerton close.
*/
#if defined(ENABLED_DEBUG_SYNC)
/* End the Debug Sync Facility. See debug_sync.cc. */
debug_sync_end_thread(this);
#endif /* defined(ENABLED_DEBUG_SYNC) */
plugin_thdvar_cleanup(this, m_enable_plugins);
DBUG_ASSERT(timer == NULL);
if (timer_cache)
thd_timer_destroy(timer_cache);
#ifndef EMBEDDED_LIBRARY
if (rli_fake)
{
rli_fake->end_info();
delete rli_fake;
rli_fake= NULL;
}
mysql_audit_free_thd(this);
#endif
if (current_thd == this)
restore_globals();
m_release_resources_done= true;
}
Seems these 3 might be related (Percona Server slow query log patch maybe?)
mysql_mutex_lock(&LOCK_thd_query);
mysql_mutex_lock(&LOCK_thd_data);
mysql_mutex_lock(&LOCK_query_plan);
Tested community version (5.7.16) with exactly the same dataset and load and problem is not present, also problem was not present in 5.6 series.
How to repeat:
Fire a VM with 2 cores and 2G of RAM, good IO capacity (maybe something around 10k IOPS), 1G of innodb_buffer_pool_size and load a file bigger than buffer pool capacity. We reproduced the error with files of 2G and 5G, sync_binlog=0 and innodb_flush_log_at_trx_commit=2 seems not related after few tests with different configurations.
On a side note the table loaded is using unique keys and text fields which can increment the flushing during commit stage. |
In Percona Server 5.7 when loading big files using LOAD DATA INFILE Percona Server becomes unresponsive for some time during "Query end" stage. During this flushing new connections got stuck in Login status until LOAD DATA INFILE finsihes, this can take several minutes depending on the file size.
This is processlist output after we changed permissions to several users to avoid them getting access during the process so Killed status might be connection being rejected:
performance_schema> show processlist;
+--------+-----------------+---------------------+---------------------------+-------------+------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+--------+-----------------+---------------------+---------------------------+-------------+------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+
| 763513 | sysconfig | 10.96.123.30:42632 | system_configurations | Sleep | 83 | | NULL | 1 | 0 |
| 770141 | engin12 | 10.96.122.234:41073 | conf | Killed | 180 | cleaning up | NULL | 0 | 0 |
| 776030 | testing | localhost | dsp_manager | Query | 103 | starting | show binary logs | 0 | 0 |
| 779746 | engin12 | 10.96.122.234:59783 | conf | Sleep | 5 | | NULL | 1 | 0 |
| 780089 | ppp | 10.96.123.38:39834 | ppp | Query | 484 | starting | commit | 0 | 0 |
| 785960 | ppp | 10.96.123.38:37732 | ppp | Query | 482 | starting | commit | 0 | 0 |
| 786387 | creat_123_serv | 10.96.122.227:41110 | creative_approval_service | Query | 482 | starting | commit | 0 | 0 |
| 786423 | testing | localhost | performance_schema | Query | 0 | starting | show processlist | 0 | 0 |
| 786519 | testing | localhost | ai | Query | 840 | query end | load data local infile '/mnt/backups/db/utd/archive/20161124/ai/rrr_price_floor_10.txt' into table r | 0 | 0 |
| 788242 | slave | 10.96.122.201:51043 | NULL | Binlog Dump | 1435 | Master has sent all binlog to slave; waiting for more updates | NULL | 0 | 0 |
| 788358 | testing_user123 | 10.96.122.223:34029 | inventory_restriction | Query | 485 | starting | commit | 0 | 0 |
| 790646 | dspmgr | 10.96.120.78:44732 | dsp_manager | Killed | 449 | cleaning up | NULL | 0 | 0 |
| 790796 | fastl123 | 10.96.122.153:56137 | fastl123_installer | Killed | 446 | cleaning up | NULL | 0 | 0 |
| 790797 | fastl123 | 10.96.122.153:56138 | fastl123_installer | Killed | 446 | cleaning up | NULL | 0 | 0 |
| 790798 | fastl123 | 10.96.122.153:56139 | fastl123_installer | Killed | 446 | cleaning up | NULL | 0 | 0 |
| 790799 | fastl123 | 10.96.122.153:56141 | fastl123_installer | Killed | 446 | cleaning up | NULL | 0 | 0 |
| 790801 | fastl123 | 10.96.122.152:52671 | fastl123_installer | Query | 496 | starting | commit | 0 | 0 |
| 790803 | fastl123 | 10.96.122.152:52673 | fastl123_installer | Query | 495 | starting | commit | 0 | 0 |
| 790901 | testingMatcher | 10.83.125.21:53663 | testingMatcher | Query | 491 | starting | commit | 0 | 0 |
| 790910 | testingMatcher | 10.83.125.21:53664 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790911 | testingMatcher | 10.83.125.21:53665 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790912 | testingMatcher | 10.83.125.21:53666 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790913 | testingMatcher | 10.83.125.21:53667 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790914 | testingMatcher | 10.83.125.21:53668 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790915 | testingMatcher | 10.83.125.21:53669 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790916 | testingMatcher | 10.83.125.21:53670 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790917 | testingMatcher | 10.83.125.21:53671 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 790918 | testingMatcher | 10.83.125.21:53672 | testingMatcher | Killed | 766 | cleaning up | NULL | 1 | 0 |
| 791191 | engin12 | 10.96.122.141:58556 | arw | Killed | 316 | cleaning up | NULL | 0 | 0 |
| 791210 | dspmgr | 10.96.122.199:46862 | dsp_manager | Killed | 312 | cleaning up | NULL | 0 | 0 |
| 791234 | fastl123 | 10.96.122.14:37170 | fastl123_stats | Killed | 303 | cleaning up | NULL | 0 | 0 |
| 791422 | ppp | 10.96.123.38:34256 | ppp | Killed | 364 | cleaning up | NULL | 0 | 0 |
| 791423 | ppp | 10.96.123.38:34258 | ppp | Killed | 364 | cleaning up | NULL | 0 | 0 |
| 791424 | ppp | 10.96.123.38:34257 | ppp | Killed | 364 | cleaning up | NULL | 0 | 0 |
| 791433 | dspmgr | 10.96.120.78:47808 | dsp_manager | Killed | 257 | cleaning up | NULL | 0 | 0 |
| 792019 | fastl123 | 10.96.122.152:57568 | fastl123_installer | Killed | 415 | cleaning up | NULL | 0 | 0 |
| 792020 | fastl123 | 10.96.122.152:57569 | fastl123_installer | Killed | 414 | cleaning up | NULL | 0 | 0 |
| 792021 | fastl123 | 10.96.122.152:57570 | fastl123_installer | Killed | 454 | cleaning up | NULL | 0 | 0 |
| 792022 | fastl123 | 10.96.122.152:57571 | fastl123_installer | Killed | 424 | cleaning up | NULL | 0 | 0 |
| 792023 | fastl123 | 10.96.122.152:57572 | fastl123_installer | Killed | 440 | cleaning up | NULL | 0 | 0 |
| 792054 | ai | 10.96.122.229:46898 | ai | Query | 479 | starting | commit | 0 | 0 |
| 792066 | testing_user123 | 10.96.122.223:49000 | inventory_restriction | Killed | 429 | cleaning up | NULL | 0 | 0 |
| 792068 | fastl123 | 10.96.122.152:57741 | fastl123_installer | Killed | 444 | cleaning up | NULL | 0 | 0 |
| 792073 | readonly | 10.83.40.170:54683 | NULL | Query | 473 | Sending data | SHOW GLOBAL STATUS | 0 | 0 |
| 792074 | testingMatcher | 10.83.125.21:53866 | testingMatcher | Killed | 469 | cleaning up | NULL | 0 | 0 |
| 792075 | testingMatcher | 10.83.125.21:53867 | testingMatcher | Killed | 473 | cleaning up | NULL | 1 | 0 |
| 792076 | testingMatcher | 10.83.125.21:53868 | testingMatcher | Killed | 473 | cleaning up | NULL | 1 | 0 |
| 792077 | testingMatcher | 10.83.125.21:53869 | testingMatcher | Killed | 473 | cleaning up | NULL | 1 | 0 |
| 792078 | testingMatcher | 10.83.125.21:53870 | testingMatcher | Killed | 473 | cleaning up | NULL | 1 | 0 |
| 792079 | testing | localhost | dsp_manager | Killed | 473 | cleaning up | NULL | 0 | 0 |
| 792080 | testingMatcher | 10.83.125.21:53871 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792081 | testingMatcher | 10.83.125.21:53872 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792082 | testingMatcher | 10.83.125.21:53873 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792083 | testingMatcher | 10.83.125.21:53874 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792084 | testingMatcher | 10.83.125.21:53875 | testingMatcher | Killed | 472 | cleaning up | NULL | 1 | 0 |
| 792085 | testing | localhost | dsp_manager | Killed | 471 | cleaning up | NULL | 0 | 0 |
| 792086 | testing | localhost | dsp_manager | Killed | 470 | cleaning up | NULL | 0 | 0 |
| 792087 | creat_123_serv | 10.83.124.54:44097 | NULL | Killed | 470 | login | NULL | 0 | 0 |
| 792088 | creat_123_serv | 10.83.124.54:44096 | NULL | Killed | 470 | login | NULL | 0 | 0 |
| 792089 | creat_123_serv | 10.83.124.54:44098 | NULL | Killed | 470 | login | NULL | 0 | 0 |
| 792090 | testing | localhost | dsp_manager | Killed | 469 | cleaning up | NULL | 0 | 0 |
| 792091 | creat_123_serv | 10.83.124.54:44099 | NULL | Killed | 469 | login | NULL | 0 | 0 |
| 792092 | creat_123_serv | 10.83.124.54:44100 | NULL | Killed | 469 | login | NULL | 0 | 0 |
| 792093 | creat_123_serv | 10.83.124.54:44101 | NULL | Killed | 469 | login | NULL | 0 | 0 |
| 792094 | testing | localhost | dsp_manager | Killed | 468 | cleaning up | NULL | 0 | 0 |
| 792095 | creat_123_serv | 10.83.124.53:52018 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792096 | creat_123_serv | 10.83.124.53:52019 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792097 | creat_123_serv | 10.83.124.53:52020 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792098 | creat_123_serv | 10.83.124.54:44102 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792099 | creat_123_serv | 10.83.124.54:44103 | NULL | Killed | 468 | login | NULL | 0 | 0 |
| 792100 | creat_123_serv | 10.83.124.54:44104 | NULL | Killed | 467 | login | NULL | 0 | 0 |
| 792101 | testing | localhost | dsp_manager | Killed | 467 | cleaning up | NULL | 0 | 0 |
| 792102 | creat_123_serv | 10.83.124.53:52021 | NULL | Killed | 467 | login | NULL | 0 | 0 |
| 792103 | creat_123_serv | 10.83.124.53:52022 | NULL | Killed | 467 | login | NULL | 0 | 0 |
| 792104 | creat_123_serv | 10.83.124.53:52024 | NULL | Killed | 467 | login | NULL | 0 | 0 |
| 792105 | creat_123_serv | 10.83.124.54:44106 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792106 | creat_123_serv | 10.83.124.54:44105 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792107 | creat_123_serv | 10.83.124.54:44108 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792108 | testing | localhost | dsp_manager | Killed | 466 | cleaning up | NULL | 0 | 0 |
| 792109 | creat_123_serv | 10.83.124.53:52025 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792110 | creat_123_serv | 10.83.124.53:52026 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792111 | creat_123_serv | 10.83.124.53:52028 | NULL | Killed | 466 | login | NULL | 0 | 0 |
| 792112 | creat_123_serv | 10.83.124.54:44109 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792113 | creat_123_serv | 10.83.124.54:44110 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792114 | creat_123_serv | 10.83.124.54:44111 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792115 | creat_123_serv | 10.83.124.54:44112 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792116 | testing | localhost | dsp_manager | Killed | 465 | cleaning up | NULL | 0 | 0 |
| 792117 | creat_123_serv | 10.83.124.53:52029 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792118 | creat_123_serv | 10.83.124.53:52030 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792119 | creat_123_serv | 10.83.124.53:52031 | NULL | Killed | 465 | login | NULL | 0 | 0 |
| 792120 | fastl123 | 10.96.122.152:57910 | fastl123_installer | Killed | 434 | cleaning up | NULL | 0 | 0 |
| 792121 | creat_123_serv | 10.83.124.54:44113 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792122 | testing | localhost | dsp_manager | Killed | 464 | cleaning up | NULL | 0 | 0 |
| 792123 | creat_123_serv | 10.83.124.53:52032 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792124 | creat_123_serv | 10.83.124.53:52033 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792125 | creat_123_serv | 10.83.124.53:52034 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792126 | creat_123_serv | 10.83.124.53:52035 | NULL | Killed | 464 | login | NULL | 0 | 0 |
| 792127 | creat_123_serv | 10.83.124.54:44114 | NULL | Killed | 463 | login | NULL | 0 | 0 |
| 792128 | testing | localhost | dsp_manager | Killed | 463 | cleaning up | NULL | 0 | 0 |
| 792129 | creat_123_serv | 10.83.124.53:52036 | NULL | Killed | 463 | login | NULL | 0 | 0 |
| 792130 | creat_123_serv | 10.83.124.54:44117 | NULL | Killed | 462 | login | NULL | 0 | 0 |
+--------+-----------------+---------------------+---------------------------+-------------+------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------+-----------+---------------+
101 rows in set (0.01 sec)
pt-pmp suggests some locking related release_resources mutex in thread handling used in Percona Server:
[root@frpq-utd9000.lab1 pmp]# perl pt-pmp -p 23791 -i 3 -s 1
Mon Nov 28 11:09:39 PST 2016
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff993fd000
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff993fd000
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff993fd000
192 __lll_lock_wait(libpthread.so.0),_L_lock_1233(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),THD::release_resources,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
84 poll(libc.so.6),vio_io_wait,vio_socket_io_wait,vio_read,net_read_raw_loop,net_read_packet,my_net_read,Protocol_classic::read_packet,Protocol_classic::get_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
30 libaio::??(libaio.so.1),LinuxAIOHandler::collect,LinuxAIOHandler::poll,os_aio_handler,fil_aio_wait,io_handler_thread,start_thread(libpthread.so.0),clone(libc.so.6)
24 nanosleep(libpthread.so.0),os_thread_sleep,buf_lru_manager,start_thread(libpthread.so.0),clone(libc.so.6)
15 pthread_cond_wait,Stage_manager::enroll_for,MYSQL_BIN_LOG::change_stage,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
9 pthread_cond_wait,os_event::wait_low,srv_worker_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_wait,os_event::wait_low,srv_purge_coordinator_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_wait,os_event::wait_low,buf_resize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_wait,os_event::wait_low,buf_dump_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_wait,compress_gtid_table,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_error_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,lock_wait_timeout_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,ib_wqueue_timedwait,fts_optimize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,dict_stats_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 pthread_cond_timedwait,MYSQL_BIN_LOG::wait_for_update_bin_log,Binlog_sender::send_binlog,Binlog_sender::run,mysql_binlog_send,com_binlog_dump,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 poll(libc.so.6),Mysqld_socket_listener::listen_for_connection_event,mysqld_main,__libc_start_main(libc.so.6),_start
3 nanosleep(libpthread.so.0),os_thread_sleep,srv_master_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 __lll_lock_wait(libpthread.so.0),_L_lock_1034(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),MYSQL_BIN_LOG::set_status_variables,show_binlog_vars,PFS_status_variable_cache::manifest,PFS_status_variable_cache::do_materialize_global,table_global_status::rnd_init,ha_perfschema::rnd_init,handler::ha_rnd_init,init_read_record,join_init_read_record,sub_select,JOIN::exec,TABLE_LIST::materialize_derived,join_materialize_derived,QEP_TAB::prepare_scan,sub_select,JOIN::exec,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 __lll_lock_wait(libpthread.so.0),_L_lock_1034(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),MYSQL_BIN_LOG::change_stage,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 do_sigwait(libpthread.so.0),sigwait(libpthread.so.0),signal_hand,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
3 do_sigwaitinfo(libc.so.6),sigwaitinfo(libc.so.6),timer_notify_thread_func,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
2 read(libpthread.so.0),my_read,my_b_fill,MYSQL_BIN_LOG::do_write_cache,MYSQL_BIN_LOG::write_cache,binlog_cache_data::flush,MYSQL_BIN_LOG::flush_thread_caches,MYSQL_BIN_LOG::process_flush_stage_queue,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit_stmt,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
1 write(libpthread.so.0),my_write,_my_b_write,MYSQL_BIN_LOG::do_write_cache,MYSQL_BIN_LOG::write_cache,binlog_cache_data::flush,MYSQL_BIN_LOG::flush_thread_caches,MYSQL_BIN_LOG::process_flush_stage_queue,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit_stmt,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
1 ut_time_ms,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
1 pthread_mutex_unlock(libpthread.so.0),os_event_reset,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
1 ::??,::??,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
Which is defined in sql/sql_class.cc as follows (PS 5.7.14-7):
void THD::release_resources()
{
DBUG_ASSERT(m_release_resources_done == false);
Global_THD_manager::get_instance()->release_thread_id(m_thread_id);
mysql_mutex_lock(&LOCK_status);
add_to_status(&global_status_var, &status_var, false);
/*
Status queries after this point should not aggregate THD::status_var
since the values has been added to global_status_var.
The status values are not reset so that they can still be read
by performance schema.
*/
status_var_aggregated= true;
mysql_mutex_unlock(&LOCK_status);
/* Ensure that no one is using THD */
mysql_mutex_lock(&LOCK_thd_data);
mysql_mutex_lock(&LOCK_query_plan);
/* Close connection */
#ifndef EMBEDDED_LIBRARY
if (is_classic_protocol() && get_protocol_classic()->get_vio())
{
vio_delete(get_protocol_classic()->get_vio());
get_protocol_classic()->end_net();
}
#endif
/* modification plan for UPDATE/DELETE should be freed. */
DBUG_ASSERT(query_plan.get_modification_plan() == NULL);
mysql_mutex_unlock(&LOCK_query_plan);
mysql_mutex_unlock(&LOCK_thd_data);
mysql_mutex_lock(&LOCK_thd_query);
mysql_mutex_unlock(&LOCK_thd_query);
stmt_map.reset(); /* close all prepared statements */
if (!cleanup_done)
cleanup();
mdl_context.destroy();
ha_close_connection(this);
/*
Debug sync system must be closed after ha_close_connection, because
DEBUG_SYNC is used in InnoDB connection handlerton close.
*/
#if defined(ENABLED_DEBUG_SYNC)
/* End the Debug Sync Facility. See debug_sync.cc. */
debug_sync_end_thread(this);
#endif /* defined(ENABLED_DEBUG_SYNC) */
plugin_thdvar_cleanup(this, m_enable_plugins);
DBUG_ASSERT(timer == NULL);
if (timer_cache)
thd_timer_destroy(timer_cache);
#ifndef EMBEDDED_LIBRARY
if (rli_fake)
{
rli_fake->end_info();
delete rli_fake;
rli_fake= NULL;
}
mysql_audit_free_thd(this);
#endif
if (current_thd == this)
restore_globals();
m_release_resources_done= true;
}
Seems these 3 might be related (Percona Server slow query log patch maybe?)
mysql_mutex_lock(&LOCK_thd_query);
mysql_mutex_lock(&LOCK_thd_data);
mysql_mutex_lock(&LOCK_query_plan);
Tested community version (5.7.16) with exactly the same dataset and load and problem is not present, also problem was not present in 5.6 series.
How to repeat:
Fire a VM with 2 cores and 2G of RAM, good IO capacity (maybe something around 10k IOPS), 1G of innodb_buffer_pool_size and load a file bigger than buffer pool capacity. We reproduced the error with files of 2G and 5G, sync_binlog=0 and innodb_flush_log_at_trx_commit=2 seems not related after few tests with different configurations.
On a side note the table loaded is using unique keys and text fields which can increment the flushing during commit stage. |
|
