enterprise-support team mailing list archive
-
enterprise-support team
-
Mailing list archive
-
Message #06965
[Bug 1710939] Re: Run multiple INSERT values (data), (data)...(data) allocates too much memory
I am running the following test under valgring massif tool to understand
the reason of the leak:
=============test begin==============
CREATE TABLE t (a BIGINT, b VARCHAR(256)) ENGINE=InnoDB;
--let INSERT_FILE_NAME = $MYSQLTEST_VARDIR/tmp/big-insert.sql
--let MAX_INSERT_SIZE=`SELECT @@max_allowed_packet`
--echo # GENERATE BIG "INSERT" STATEMENT
perl;
my $fname= $ENV{INSERT_FILE_NAME};
open(my $fh, '>', $fname) or die "Failed to open $fname: $!\n";
my $max_size = $ENV{MAX_INSERT_SIZE};
my $header = "INSERT INTO t VALUES\n";
my $values = "(1,'This is a dummy value'),\n";
my $footer = "(1,'This is a dummy value');";
my $cur_size = length($header) + length($footer);
my $max_size_without_footer = $max_size - length($footer);
print $fh $header;
while ($cur_size < $max_size_without_footer) {
print $fh $values;
$cur_size += length($values);
}
print $fh $footer;
close $fh;
EOF
SELECT * FROM sys.memory_global_total;
--echo # EXECUTE BIG "INSERT" STATEMENT
--disable_query_log
--source $INSERT_FILE_NAME
--enable_query_log
SELECT * FROM sys.memory_global_total;
--echo # SLEEP
SELECT SLEEP(600);
SELECT * FROM sys.memory_global_total;
--echo # EXECUTE BIG "INSERT" STATEMENT
--disable_query_log
--source $INSERT_FILE_NAME
--enable_query_log
SELECT * FROM sys.memory_global_total;
--echo # CLEANUP
--remove_file $INSERT_FILE_NAME
DROP TABLE t;
=============test end==============
To run this test the following fix is required:
=========mysqltest fix begin===========
--- a/client/mysqltest.cc
+++ b/client/mysqltest.cc
@@ -6964,7 +6964,7 @@ bool is_delimiter(const char* p)
terminated by new line '\n' regardless how many "delimiter" it contain.
*/
-#define MAX_QUERY (256*1024*2) /* 256K -- a test in sp-big is >128K */
+#define MAX_QUERY (500*1024*1024)
static char read_command_buf[MAX_QUERY];
int read_command(struct st_command** command_ptr)
=========mysqltest fix end===========
What I see is that the big amount of memory is allocated to parse and
process a big statement. For example, for the statement of 300M length
about 6G memory is allocated. After this the most of the memory is
deallocated, but about several hundreds of megabytes still stays
allocated. And this might be the leak we are looking for. But what is
bothering me is that 6G. If the customer's process is killed by OOM then
the reason is most likely in the amount of memory allocated for
statement parsing and processing, but not in the leak.
This is the result of the above test for 300M file:
======the result 300M=======
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
CREATE TABLE t (a BIGINT, b VARCHAR(256)) ENGINE=InnoDB;
# GENERATE BIG "INSERT" STATEMENT
SELECT * FROM sys.memory_global_total;
total_allocated
127.64 MiB
# EXECUTE BIG "INSERT" STATEMENT
SELECT * FROM sys.memory_global_total;
total_allocated
427.65 MiB
# SLEEP
SELECT SLEEP(60);
SLEEP(60)
0
SELECT * FROM sys.memory_global_total;
total_allocated
427.65 MiB
# EXECUTE BIG "INSERT" STATEMENT
worker[1] Trying to dump core for [mysqltest - pid: 32505, winpid: 32505]
worker[1] Trying to dump core for [mysqld.1 - pid: 32467, winpid: 32467]
======the result 300M end=======
As we can see the difference between the size of allocated memory before
the statement and after it is about 300M. And the test fails with crash
with the following backtrace:
=====the backtrace=====
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
62 ../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7ff8b4384740 (LWP 32468))]
#0 __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1 0x00000000019c4155 in my_write_core (sig=6) at ./mysys/stacktrace.c:249
#2 0x0000000000f42a90 in handle_fatal_signal (sig=6) at ./sql/signal_handler.cc:223
#3 <signal handler called>
#4 0x00007ff8b27a570d in poll () at ../sysdeps/unix/syscall-template.S:84
#5 0x00000000017a9e1f in Mysqld_socket_listener::listen_for_connection_event (this=0x53f1ce0) at ./sql/conn_handler/socket_connection.cc:876
#6 0x0000000000f3b4b3 in Connection_acceptor<Mysqld_socket_listener>::connection_event_loop (this=0x53c5930) at ./sql/conn_handler/connection_acceptor.h:66
#7 0x0000000000f32a2a in mysqld_main (argc=94, argv=0x4e13268) at ./sql/mysqld.cc:5373
#8 0x0000000000f28d86 in main (argc=9, argv=0x7ffd8abb4228) at ./sql/main.cc:25
=====the backtrace end=====
Let's now look at the result and massif output for 150M statement.
=====the result of 150M=====
CREATE TABLE t (a BIGINT, b VARCHAR(256)) ENGINE=InnoDB;
# GENERATE BIG "INSERT" STATEMENT
SELECT * FROM sys.memory_global_total;
total_allocated
117.14 MiB
# EXECUTE BIG "INSERT" STATEMENT
SELECT * FROM sys.memory_global_total;
total_allocated
276.00 MiB
# SLEEP
SELECT SLEEP(600);
SLEEP(600)
0
SELECT * FROM sys.memory_global_total;
total_allocated
275.99 MiB
# EXECUTE BIG "INSERT" STATEMENT
SELECT * FROM sys.memory_global_total;
total_allocated
276.01 MiB
# CLEANUP
DROP TABLE t;
=====the result of 150M end=====
This is the complete memory usage graphic. So for 150M statement parsing
and processing we can see that about 3G of memory is used.
GB
3.249^ @
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
| #@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|@#@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
0 +----------------------------------------------------------------------->h
0 2.192
Let's see the snapshot for the "sleep" period:
--------------------------------------------------------------------------------
n time(ms) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
255 3,674,655 263,376,328 263,293,265 83,063 0
99.97% (263,293,265B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->61.59% (162,217,441B) 0x19AC8E5: my_raw_malloc (my_malloc.c:191)
| ->61.59% (162,217,441B) 0x19AC4D1: my_malloc (my_malloc.c:54)
| ->59.75% (157,367,570B) 0x19AC617: my_realloc (my_malloc.c:88)
| | ->59.72% (157,286,439B) 0x1540BF9: net_realloc (net_serv.cc:168)
| | | ->59.72% (157,286,439B) 0x1541CF4: net_read_packet(st_net*, unsigned long*) (net_serv.cc:855)
| | | ->59.72% (157,286,439B) 0x1541DFC: my_net_read (net_serv.cc:909)
| | | | ->59.72% (157,286,439B) 0x1559D80: Protocol_classic::read_packet() (protocol_classic.cc:808)
| | | | ->59.72% (157,286,439B) 0x155A281: Protocol_classic::get_command(COM_DATA*, enum_server_command*) (protocol_classic.cc:965)
| | | | ->59.72% (157,286,439B) 0x16433C6: do_command(THD*) (sql_parse.cc:960)
| | | | ->59.72% (157,286,439B) 0x1795AF0: handle_connection (connection_handler_per_thread.cc:312)
| | | | ->59.72% (157,286,439B) 0x1E05ED7: pfs_spawn_thread (pfs.cc:2188)
| | | | ->59.72% (157,286,439B) 0x58996B8: start_thread (pthread_create.c:333)
| | | | ->59.72% (157,286,439B) 0x64573DB: clone (clone.S:109)
Here we can see that the memory was allocated for input buffer. It stays allocated while connection is active, and it is deallocated when connection is broken.
I would not consider this as memory leak.
Ok, let's look on what exactly such big amount of memory(~3G) is
allocated:
->97.10% (3,386,602,393B) 0x19AC8E5: my_raw_malloc (my_malloc.c:191)
| ->97.10% (3,386,602,393B) 0x19AC4D1: my_malloc (my_malloc.c:54)
| ->92.51% (3,226,443,504B) 0x19A5120: alloc_root (my_alloc.c:279)
| | ->45.05% (1,571,263,520B) 0xF28260: Item::operator new(unsigned long, st_mem_root*) (item.h:771)
| | | ->23.14% (806,974,656B) 0x17C7AC1: MYSQLparse(THD*) (sql_yacc.yy:12985)
| | | | ->23.14% (806,974,656B) 0x1654193: parse_sql(THD*, Parser_state*, Object_creation_ctx*) (sql_parse.cc:7486)
| | | | ->23.14% (806,974,656B) 0x1650603: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5787)
| | | | ->23.14% (806,974,656B) 0x16449AD: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1493)
| | | | ->23.14% (806,974,656B) 0x164374E: do_command(THD*) (sql_parse.cc:1021)
| | | | ->23.14% (806,974,656B) 0x1795AF0: handle_connection (connection_handler_per_thread.cc:312)
| | | | ->23.14% (806,974,656B) 0x1E05ED7: pfs_spawn_thread (pfs.cc:2188)
| | | | ->23.14% (806,974,656B) 0x58996B8: start_thread (pthread_create.c:333)
| | | | ->23.14% (806,974,656B) 0x64573DB: clone (clone.S:109)
| | | |
| | | ->21.91% (764,280,672B) 0x17C83C4: MYSQLparse(THD*) (sql_yacc.yy:13096)
| | | | ->21.91% (764,280,672B) 0x1654193: parse_sql(THD*, Parser_state*, Object_creation_ctx*) (sql_parse.cc:7486)
| | | | ->21.91% (764,280,672B) 0x1650603: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5787)
| | | | ->21.91% (764,280,672B) 0x16449AD: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1493)
| | | | ->21.91% (764,280,672B) 0x164374E: do_command(THD*) (sql_parse.cc:1021)
| | | | ->21.91% (764,280,672B) 0x1795AF0: handle_connection (connection_handler_per_thread.cc:312)
| | | | ->21.91% (764,280,672B) 0x1E05ED7: pfs_spawn_thread (pfs.cc:2188)
| | | | ->21.91% (764,280,672B) 0x58996B8: start_thread (pthread_create.c:333)
| | | | ->21.91% (764,280,672B) 0x64573DB: clone (clone.S:109)
| | | |
| | | ->00.00% (8,192B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->23.11% (805,984,096B) 0x175DAE6: sql_alloc(unsigned long) (thr_malloc.cc:39)
| | | ->13.14% (458,307,296B) 0xF52390: Sql_alloc::operator new(unsigned long) (sql_alloc.h:30)
| | | | ->13.14% (458,307,296B) 0xF653EF: base_list::push_back(void*) (sql_list.h:195)
| | | | | ->10.33% (360,426,144B) 0xF67547: List<Item>::push_back(Item*) (sql_list.h:545)
| | | | | | ->10.33% (360,426,144B) 0x17D6104: PT_item_list::push_back(Item*) (parse_tree_helpers.h:87)
| | | | | | | ->06.24% (217,721,216B) 0x17C36BE: MYSQLparse(THD*) (sql_yacc.yy:11731)
| | | | | | | | ->06.24% (217,721,216B) 0x1654193: parse_sql(THD*, Parser_state*, Object_creation_ctx*) (sql_parse.cc:7486)
| | | | | | | | ->06.24% (217,721,216B) 0x1650603: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5787)
| | | | | | | | ->06.24% (217,721,216B) 0x16449AD: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1493)
| | | | | | | | ->06.24% (217,721,216B) 0x164374E: do_command(THD*) (sql_parse.cc:1021)
| | | | | | | | ->06.24% (217,721,216B) 0x1795AF0: handle_connection (connection_handler_per_thread.cc:312)
| | | | | | | | ->06.24% (217,721,216B) 0x1E05ED7: pfs_spawn_thread (pfs.cc:2188)
| | | | | | | | ->06.24% (217,721,216B) 0x58996B8: start_thread (pthread_create.c:333)
| | | | | | | | ->06.24% (217,721,216B) 0x64573DB: clone (clone.S:109)
| | | | | | | |
| | | | | | | ->04.09% (142,704,928B) 0x17C374F: MYSQLparse(THD*) (sql_yacc.yy:11738)
| | | | | | | ->04.09% (142,704,928B) 0x1654193: parse_sql(THD*, Parser_state*, Object_creation_ctx*) (sql_parse.cc:7486)
| | | | | | | ->04.09% (142,704,928B) 0x1650603: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5787)
| | | | | | | ->04.09% (142,704,928B) 0x16449AD: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1493)
| | | | | | | ->04.09% (142,704,928B) 0x164374E: do_command(THD*) (sql_parse.cc:1021)
| | | | | | | ->04.09% (142,704,928B) 0x1795AF0: handle_connection (connection_handler_per_thread.cc:312)
| | | | | | | ->04.09% (142,704,928B) 0x1E05ED7: pfs_spawn_thread (pfs.cc:2188)
| | | | | | | ->04.09% (142,704,928B) 0x58996B8: start_thread (pthread_create.c:333)
| | | | | | | ->04.09% (142,704,928B) 0x64573DB: clone (clone.S:109)
| | | | | | |
| | | | | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | | | | |
| | | | | ->02.81% (97,881,152B) 0x17E2063: List<List<Item> >::push_back(List<Item>*) (sql_list.h:545)
| | | | | ->02.81% (97,881,152B) 0x17DDC29: PT_insert_values_list::push_back(List<Item>*) (parse_tree_nodes.h:2584)
| | | | | ->02.81% (97,881,152B) 0x17C357B: MYSQLparse(THD*) (sql_yacc.yy:11692)
| | | | | ->02.81% (97,881,152B) 0x1654193: parse_sql(THD*, Parser_state*, Object_creation_ctx*) (sql_parse.cc:7486)
| | | | | ->02.81% (97,881,152B) 0x1650603: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5787)
| | | | | ->02.81% (97,881,152B) 0x16449AD: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1493)
| | | | | ->02.81% (97,881,152B) 0x164374E: do_command(THD*) (sql_parse.cc:1021)
| | | | | ->02.81% (97,881,152B) 0x1795AF0: handle_connection (connection_handler_per_thread.cc:312)
| | | | | ->02.81% (97,881,152B) 0x1E05ED7: pfs_spawn_thread (pfs.cc:2188)
| | | | | ->02.81% (97,881,152B) 0x58996B8: start_thread (pthread_create.c:333)
| | | | | ->02.81% (97,881,152B) 0x64573DB: clone (clone.S:109)
| | | | |
| | | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | | |
| | | ->09.96% (347,309,248B) 0x175DC9D: sql_strmake_with_convert(char const*, unsigned long, charset_info_st const*, unsigned long, charset_info_st const*, unsigned long*) (thr_malloc.cc:93)
| | | | ->09.96% (347,309,248B) 0xFE42BE: Name_string::copy(char const*, unsigned long, charset_info_st const*) (item.cc:1153)
| | | | ->09.96% (347,309,248B) 0xF6694C: Item_string::init(char const*, unsigned long, charset_info_st const*, Derivation, unsigned int) (item.h:3642)
| | | | ->09.96% (347,309,248B) 0x17E025B: PTI_text_literal_text_string::itemize(Parse_context*, Item**) (parse_tree_items.h:490)
| | | | ->09.96% (347,309,248B) 0x185F38F: PT_insert_values_list::contextualize(Parse_context*) (parse_tree_nodes.cc:846)
| | | | ->09.96% (347,309,248B) 0x185F6C1: PT_insert::contextualize(Parse_context*) (parse_tree_nodes.cc:913)
| | | | ->09.96% (347,309,248B) 0x185F951: PT_insert::make_cmd(THD*) (parse_tree_nodes.cc:953)
| | | | ->09.96% (347,309,248B) 0x17A5C73: MYSQLparse(THD*) (sql_yacc.yy:1691)
| | | | ->09.96% (347,309,248B) 0x1654193: parse_sql(THD*, Parser_state*, Object_creation_ctx*) (sql_parse.cc:7486)
| | | | ->09.96% (347,309,248B) 0x1650603: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5787)
| | | | ->09.96% (347,309,248B) 0x16449AD: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1493)
| | | | ->09.96% (347,309,248B) 0x164374E: do_command(THD*) (sql_parse.cc:1021)
| | | | ->09.96% (347,309,248B) 0x1795AF0: handle_connection (connection_handler_per_thread.cc:312)
| | | | ->09.96% (347,309,248B) 0x1E05ED7: pfs_spawn_thread (pfs.cc:2188)
| | | | ->09.96% (347,309,248B) 0x58996B8: start_thread (pthread_create.c:333)
| | | | ->09.96% (347,309,248B) 0x64573DB: clone (clone.S:109)
| | | |
| | | ->00.01% (367,552B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->12.48% (435,359,600B) 0xF66B17: Query_arena::alloc(unsigned long) (sql_class.h:825)
| | | ->04.51% (157,286,440B) 0x160D91D: Lex_input_stream::init(THD*, char const*, unsigned long) (sql_lex.cc:187)
| | | | ->04.51% (157,286,440B) 0xF7918E: Parser_state::init(THD*, char const*, unsigned long) (sql_lex.h:3668)
| | | | ->04.51% (157,286,440B) 0x164498C: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1490)
| | | | | ->04.51% (157,286,440B) 0x164374E: do_command(THD*) (sql_parse.cc:1021)
| | | | | ->04.51% (157,286,440B) 0x1795AF0: handle_connection (connection_handler_per_thread.cc:312)
| | | | | ->04.51% (157,286,440B) 0x1E05ED7: pfs_spawn_thread (pfs.cc:2188)
| | | | | ->04.51% (157,286,440B) 0x58996B8: start_thread (pthread_create.c:333)
| | | | | ->04.51% (157,286,440B) 0x64573DB: clone (clone.S:109)
| | | | |
| | | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
So the most memory is allocated for parsing. This is how parser currently works, and we can do nothing with it.
Conclusion:
1) There is no memory leak, what we can see is just network buffer
expanding. The buffer itself is deallocated on connection finishing.
2) Current parser can consume up to 20x more memory the statement
length, and we can do nothing with it.
** Changed in: percona-server/5.7
Status: In Progress => Invalid
--
You received this bug notification because you are a member of Ubuntu
Server/Client Support Team, which is subscribed to MySQL.
Matching subscriptions: Ubuntu Server/Client Support Team
https://bugs.launchpad.net/bugs/1710939
Title:
Run multiple INSERT values (data),(data)...(data) allocates too much
memory
To manage notifications about this bug go to:
https://bugs.launchpad.net/mysql-server/+bug/1710939/+subscriptions
