Run multiple INSERT values (data),(data)...(data) allocates too much memory

[Marcelo Henrique Gonçalves]

Hi,

I would like you to test one problem I was able to reproduce and it is completely compatible with the scenario described here.
I reproduced the memory growth with and without libjemalloc lib in use.

How I reproduced a memory issue that can be related to this one.

1) Startup a new Percona Server Instance (5.6 or 5.7, I think both are affected) I used 5.6.36.
2) Setup only 1 variable in my.cnf: max_allowed_packet=96M

3) Create a dummy table like this one:

create database db;
  use db;
  create table db.dummy (acol bigint, anything varchar(256)) engine=innodb;

4) Create a SQL file (load_test.sql) like this one:
INSERT INTO db.dummy VALUES
(1,'This is a dummy value'),
(1,'This is a dummy value'),
...
(1,'This is a dummy value');

5) Repeat the values until you reach a file size bigger than 64MB. It needs to be bigger than 64MB and smaller then max_allowed_packet.

6) Take note of memory allocation and how it is.

7) Run the following:
mysql db < load_test.sql ; vmstat -S m 2 100

This might cause mysqld memory to explode! Run with bigger file size, bigger max_allowed_packet if needed.

[Daniel Macedo (daniel.macedo)]

This problem also affected my company too.

[Marcelo Henrique Gonçalves (marcelo.goncalves)]

An observation in steps 4 and 5. The file needs to be bigger than 64MB IN A SINGLE statement.

[Sveta Smirnova (svetasmirnova)]

Thank you for the report.

Please provide numbers you are seeing in your environment. I am seeing 300MB memory usage increase with version 5.6.36 which gets cleared after job is done.

[Marcelo Henrique Gonçalves (marcelo.goncalves)]

Thank you very much Mrs Sveta.

I had a small centos vm with 768MB of RAM and 2GB of swap. It used all memory until kernel kill it with OOM. I was using version 5.6.36.
In client side, memory is not released I do not know why. We had several times (with 5.6.36 and 5.6.34) server allocating everything in memory (and memory is tuned to be below 66%) only when loading these big files. In client files were near 256MB size.

Do you want me to recreate the scenario with more details?

[Sveta Smirnova (svetasmirnova)]

Thank you for the update. Comment in upstream helped. I started seeing issue (memory allocated and not freed) after I create file of 129M

[Sveta Smirnova (svetasmirnova)]

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

[Marcelo Henrique Gonçalves (marcelo.goncalves)]

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

[Vlad Lesin (vlad-lesin)]

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======...

[Vlad Lesin (vlad-lesin)]

The full massif output is attached.

[Marcelo Henrique Gonçalves (marcelo.goncalves)]

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

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1815