SHOW STATUS blocked by binlog commit | Server becomes unresponsive during flushing after loading big files through LOAD DATA INFILE
Affects | Status | Importance | Assigned to | Milestone | ||
---|---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS | Status tracked in 5.7 | |||||
5.5 |
Invalid
|
Undecided
|
Unassigned | |||
5.6 |
Fix Released
|
Medium
|
Laurynas Biveinis | |||
5.7 |
Fix Released
|
Medium
|
Laurynas Biveinis |
Bug Description
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_
| 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_
| 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/
| 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_
| 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_
| 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:
[<email address hidden> 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_
84 poll(libc.
30 libaio:
24 nanosleep(
15 pthread_
9 pthread_
3 pthread_
3 pthread_
3 pthread_
3 pthread_
3 pthread_
3 pthread_
3 pthread_
3 pthread_
3 pthread_
3 pthread_
3 poll(libc.
3 nanosleep(
3 __lll_lock_
3 __lll_lock_
3 do_sigwait(
3 do_sigwaitinfo(
2 read(libpthread
1 write(libpthrea
1 ut_time_
1 pthread_
1 ::??,::
Which is defined in sql/sql_class.cc as follows (PS 5.7.14-7):
void THD::release_
{
DBUG_
Global_
mysql_
add_to_
/*
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_
mysql_
/* Ensure that no one is using THD */
mysql_
mysql_
/* Close connection */
#ifndef EMBEDDED_LIBRARY
if (is_classic_
{
vio_
get_
}
#endif
/* modification plan for UPDATE/DELETE should be freed. */
DBUG_
mysql_
mysql_
mysql_
mysql_
stmt_map.reset(); /* close all prepared statements */
if (!cleanup_done)
cleanup();
mdl_context.
ha_close_
/*
Debug sync system must be closed after ha_close_
DEBUG_SYNC is used in InnoDB connection handlerton close.
*/
#if defined(
/* End the Debug Sync Facility. See debug_sync.cc. */
debug_
#endif /* defined(
plugin_
DBUG_ASSERT(timer == NULL);
if (timer_cache)
thd_
#ifndef EMBEDDED_LIBRARY
if (rli_fake)
{
rli_
delete rli_fake;
rli_fake= NULL;
}
mysql_
#endif
if (current_thd == this)
restore_
m_release_
}
Seems these 3 might be related (Percona Server slow query log patch maybe?)
mysql_mutex_
mysql_mutex_
mysql_mutex_
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_
On a side note the table loaded is using unique keys and text fields which can increment the flushing during commit stage.
Can you provide the raw unaggregated PMP samples?