LP #1710939: Run multiple INSERT values (data),(data)...(data) allocates too much memory

**Comment from Launchpad by: Marcelo Henrique Gonçalves on: 05-12-2017 18:55:52

Hi,

We do see a server in 5.6 crashing constantly because of lack of memory on the server. Memory explodes easily when loading files with LOAD or multiple INSERT. Are you sure this is an invalid bug for 5.6?
Version: 5.6.36-82.0-log Percona Server (GPL), Release 82.0, Revision 58e846a

Linux crashed again because of lack of memory:
Linux 4.9.62-21.56.amzn1.x86_64 #1 SMP Thu Nov 16 05:37:08 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

#######Output of sar -r:
01:40:01 PM kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit
01:50:01 PM 2718156 12683972 82.35 152180 2574512 5082832 29.05
02:00:01 PM 2715168 12686960 82.37 152568 2574724 5091108 29.09
02:10:01 PM 2715704 12686424 82.37 152952 2575016 5086576 29.07
02:20:01 PM 2714540 12687588 82.38 153420 2575236 5090164 29.09
02:30:01 PM 2643552 12758576 82.84 156644 2577432 5091668 29.10
02:40:01 PM 2642828 12759300 82.84 157048 2577640 5086068 29.06
02:50:01 PM 2641996 12760132 82.85 157416 2577860 5086768 29.07
03:00:01 PM 2640388 12761740 82.86 157808 2578076 5080992 29.04
03:10:01 PM 2640800 12761328 82.85 158192 2578364 5084248 29.05
03:20:01 PM 2639740 12762388 82.86 158472 2578584 5094484 29.11
03:30:01 PM 2639484 12762644 82.86 158876 2578804 5090928 29.09
03:40:01 PM 2638936 12763192 82.87 159176 2579024 5085192 29.06
03:50:01 PM 2637984 12764144 82.87 159488 2579244 5076964 29.01
04:00:01 PM 2636660 12765468 82.88 159844 2579468 5075912 29.01
04:10:01 PM 2636104 12766024 82.88 160184 2579752 5092508 29.10
04:20:01 PM 2636724 12765404 82.88 160548 2579972 5089448 29.08
04:30:01 PM 2630276 12771852 82.92 161900 2580592 5090984 29.09
04:40:01 PM 2629792 12772336 82.93 162308 2580800 5083364 29.05
04:50:01 PM 2627088 12775040 82.94 162712 2581048 5093204 29.11
05:00:01 PM 2623780 12778348 82.96 163468 2581388 5089148 29.08
05:10:01 PM 2617808 12784320 83.00 165128 2582144 5086660 29.07
05:20:01 PM 2610820 12791308 83.05 166616 2582760 5090880 29.09
05:30:01 PM 2610120 12792008 83.05 167084 2582980 5089528 29.08
05:40:01 PM 2602844 12799284 83.10 168732 2583560 5088280 29.08
05:50:01 PM 2602228 12799900 83.10 168980 2583776 5082756 29.05
06:00:01 PM 2600048 12802080 83.12 169316 2583996 5087040 29.07
06:10:01 PM 2600272 12801856 83.12 169632 2584288 5091264 29.09
06:20:01 PM 996248 14405880 93.53 8156 366260 5092992 29.10
Average: 2732253 12669875 82.26 136568 2531603 5088746 29.08

06:45:47 PM LINUX RESTART
user@hostname: ~ $ free -m
total used free shared buffers cached
Mem: 15041 2862 12179 0 16 720
-/+ buffers/cache: 2125 12915
Swap: 2047 0 2047

##########RELATED PARAMETERS
join_buffer_size=7340032
key_buffer_size=20971520
read_buffer_size=131072
read_rnd_buffer_size=262144
sort_buffer_size=524288
table_definition_cache=4096
table_open_cache=4096
table_open_cache_instances=8
thread_cache_size=32
innodb_buffer_pool_instances=4
innodb_buffer_pool_size=4G
innodb_sort_buffer_size=1048576
innodb_buffer_pool_dump_at_shutdown=1
innodb_buffer_pool_load_at_startup=1
innodb_log_buffer_size=8388608
query_cache_size=0
query_cache_type=0
max_connections=512

**Comment from Launchpad by: Vlad Lesin on: 05-12-2017 18:23:35

The full massif output is attached.

**Comment from Launchpad by: Vlad Lesin on: 05-12-2017 17:37:22

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;

1. GENERATE BIG "INSERT" STATEMENT
   SELECT * FROM sys.memory_global_total;
   total_allocated
   127.64 MiB

2. EXECUTE BIG "INSERT" STATEMENT
   SELECT * FROM sys.memory_global_total;
   total_allocated
   427.65 MiB

3. SLEEP
   SELECT SLEEP(60);
   SLEEP(60)
   0
   SELECT * FROM sys.memory_global_total;
   total_allocated
   427.65 MiB

4. 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;

1. GENERATE BIG "INSERT" STATEMENT
   SELECT * FROM sys.memory_global_total;
   total_allocated
   117.14 MiB

2. EXECUTE BIG "INSERT" STATEMENT
   SELECT * FROM sys.memory_global_total;
   total_allocated
   276.00 MiB

3. SLEEP
   SELECT SLEEP(600);
   SLEEP(600)
   0
   SELECT * FROM sys.memory_global_total;
   total_allocated
   275.99 MiB

4. EXECUTE BIG "INSERT" STATEMENT
   SELECT * FROM sys.memory_global_total;
   total_allocated
   276.01 MiB

5. 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^ @

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)

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)

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.

**Comment from Launchpad by: Marcelo Henrique Gonçalves on: 25-10-2017 21:36:36

Thank you very much Sveta,

I kindly ask your attention to one point.
I could not see the memory going free but the allocation of memory was much higher than expected in 5.6. The case is that it caused OOM and MySQL was killed.
So, one of the concern is that for a file of near 72MB of load, the memory went above 2GB even for very limited buffer_pool.
The main reason of this ticket is an issue in 5.6 loading file using a 256MB sql with multiple rows insert exploding memory in several Gigas and being killed by OOM.

Please, assess if this makes sense.

Thank you
Marcelo

**Comment from Launchpad by: Sveta Smirnova on: 25-10-2017 18:29:46

I can repeat memory leak only with version 5.7. Version 5.5 and 5.6 free memory after job done.