Linux

This is the comment history imported from bugzilla:

Comment 1 Yves Trudeau 2015-02-20 14:25:16 UTC
After looking at the code, I think I understand what MaxScale is doing. It saves all the session variables in case a backend disconnect, in order to be able to replay them.

So, this is not a bug although it should be documented in some way that it shouldn't be used with long running database sessions. The solutions will be to set a max connection age with the application.

--Yves

Comment 2 Markus Mäkelä 2015-02-20 14:42:26 UTC
I've added a description of how the readwritesplit stores session commands into the configuration guide document. I also added a note about long-running applications, growing memory consumption and connection timeouts on the application side as a solution.

Comment 3 Timofey Turenko 2015-02-25 13:08:17 UTC
it is not a blocker;

documentation changed, closing

Comment 4 Yves Trudeau 2015-02-28 20:51:18 UTC
The saving of the history of session variables is something that needs to be disable if needed, a route_option should exists to disable the behavior. We are facing a case where a few sessions are held by hibernate issue multiple sessions for each writes ops. The java connection pool aging cannot be used here because the offending sessions are never released by the application so they can't be aged out.

Comment 5 Markus Mäkelä 2015-03-01 00:31:41 UTC
Added a configurable upper limit to the number of session commands the readwritesplit router stores before closing the session.

The parameter can be enabled by adding the 'max_sescmd_history' to the service's router options:

router_options=max_sescmd_history=2500

Comment 6 Yves Trudeau 2015-03-03 15:59:09 UTC
I tried the patch with the develop branch and with max_sescmd_history=200. The session closes but, there still a leak though, here the valgrind output tail after about 1000 queries done by executing a few times:

yves@yves-desktop:~/src/sysbench/sysbench$ ( while true; do echo "rollback;select 'rollback';set autocommit=1;select 'ac1';set autocommit=0;select 'ac0';insert into simpleinsert (val) values (0);select 'insert';commit;select now();select 1;"; done ) | mysql -h 10.3.1.110 -P 4006 -u tpcc -ptpcc test

==25245== 4,140,600 bytes in 1,005 blocks are still reachable in loss record 122 of 124

==25245==    at 0x4C2B6CD: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)

==25245==    by 0x7922A1: my_malloc (my_malloc.c:41)

==25245==    by 0x78C648: reset_root_defaults (my_alloc.c:129)

==25245==    by 0x666E71: THD::init_for_queries() (sql_class.cc:1345)

==25245==    by 0x5702F8: create_embedded_thd (lib_sql.cc:685)

==25245==    by 0x18A98F3F: ???

==25245==    by 0x18A98E6F: ???

==25245==    by 0x18A98CC1: ???

==25245==    by 0x1888897B: ???

==25245==    by 0x188884A5: ???

==25245==    by 0x196B27DC: ???

==25245==    by 0x196B1496: ???

==25245== 

==25245== 8,257,080 bytes in 1,005 blocks are still reachable in loss record 123 of 124

==25245==    at 0x4C2B6CD: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)

==25245==    by 0x7922A1: my_malloc (my_malloc.c:41)

==25245==    by 0x78C648: reset_root_defaults (my_alloc.c:129)

==25245==    by 0x666E57: THD::init_for_queries() (sql_class.cc:1342)

==25245==    by 0x5702F8: create_embedded_thd (lib_sql.cc:685)

==25245==    by 0x18A98F3F: ???

==25245==    by 0x18A98E6F: ???

==25245==    by 0x18A98CC1: ???

==25245==    by 0x1888897B: ???

==25245==    by 0x188884A5: ???

==25245==    by 0x196B27DC: ???

==25245==    by 0x196B1496: ???

==25245== 

==25245== 18,459,840 bytes in 1,005 blocks are still reachable in loss record 124 of 124

==25245==    at 0x4C2B6CD: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)

==25245==    by 0x7922A1: my_malloc (my_malloc.c:41)

==25245==    by 0x5701BD: create_embedded_thd (sql_list.h:629)

==25245==    by 0x18A98F3F: ???

==25245==    by 0x18A98E6F: ???

==25245==    by 0x18A98CC1: ???

==25245==    by 0x1888897B: ???

==25245==    by 0x188884A5: ???

==25245==    by 0x196B27DC: ???

==25245==    by 0x196B1496: ???

==25245==    by 0x55A78F: process_pollq (in /usr/local/skysql/maxscale/bin/maxscale)

==25245==    by 0x55A058: poll_waitevents (in /usr/local/skysql/maxscale/bin/maxscale)

It all seems to come from the embedded thread in the query_classifier, maybe some unfreed gwbuf_clone missing that the sbuf->refcount would prevent from being actually freed.

I added a Valgrind log of MaxScale with a Readwritesplit router limited to 100 session commands. I tested it by executing the following command:

while true ; do echo "set @var1=1;set @var2=@var1;" ; sleep 0.2  ; done|mysql -u maxuser -pmaxpwd -h 127.0.0.1 -P 4006

The connection was closed after 100 session commands were issued and MaxScale was shut down through maxadmin. From this log I can't see a memory leak so I will mark bug as fixed.

From your vg.log, what is this if not a leak... Loop over 200 and check, it will be twice as large. Closing the session has no impacts. You can also verify without valgrind, let it run for a few minutes, you'll see the RSS rising.

--Yves

==30167== 32,736 bytes in 4 blocks are possibly lost in loss record 113 of 115
==30167== at 0x4C29BCF: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
==30167== by 0x7289E6: my_malloc (in /home/markus/build/bin/maxscale)
==30167== by 0x6FB841: alloc_dynamic (in /home/markus/build/bin/maxscale)
==30167== by 0x708828: my_hash_insert (in /home/markus/build/bin/maxscale)
==30167== by 0x55DEE5: mysql_options4 (in /home/markus/build/bin/maxscale)
==30167== by 0x55E0E9: cli_mysql_real_connect (in /home/markus/build/bin/maxscale)
==30167== by 0x54C61D: mysql_real_connect (in /home/markus/build/bin/maxscale)
==30167== by 0x1B095F39: ???
==30167== by 0x1B096772: ???
==30167== by 0x5719529: start_thread (in /usr/lib64/libpthread-2.20.so)
==30167== by 0x6EA122C: clone (in /usr/lib64/libc-2.20.so)
==30167==
==30167== 65,568 bytes in 4 blocks are possibly lost in loss record 114 of 115
==30167== at 0x4C29BCF: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
==30167== by 0x7289E6: my_malloc (in /home/markus/build/bin/maxscale)
==30167== by 0x72C6BE: mysql_socket_vio_new (in /home/markus/build/bin/maxscale)
==30167== by 0x72C820: vio_new (in /home/markus/build/bin/maxscale)
==30167== by 0x55ED99: cli_mysql_real_connect (in /home/markus/build/bin/maxscale)
==30167== by 0x54C61D: mysql_real_connect (in /home/markus/build/bin/maxscale)
==30167== by 0x1B095F39: ???
==30167== by 0x1B096772: ???
==30167== by 0x5719529: start_thread (in /usr/lib64/libpthread-2.20.so)
==30167== by 0x6EA122C: clone (in /usr/lib64/libc-2.20.so)
==30167==
==30167== 65,600 bytes in 4 blocks are possibly lost in loss record 115 of 115
==30167== at 0x4C29BCF: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
==30167== by 0x7289E6: my_malloc (in /home/markus/build/bin/maxscale)
==30167== by 0x64CCB0: my_net_init (in /home/markus/build/bin/maxscale)
==30167== by 0x55E2CA: cli_mysql_real_connect (in /home/markus/build/bin/maxscale)
==30167== by 0x54C61D: mysql_real_connect (in /home/markus/build/bin/maxscale)
==30167== by 0x1B095F39: ???
==30167== by 0x1B096772: ???
==30167== by 0x5719529: start_thread (in /usr/lib64/libpthread-2.20.so)
==30167== by 0x6EA122C: clone (in /usr/lib64/libc-2.20.so)

There was a memory leak in the client protocol when an error message was improperly free'd. This has been fixed in the develop branch.

Attached is a log from valgrind with 200 queries of set @var1 = if(@var1 = NULL,0,@var1 + 1); in the same session.

The call to mysql_real_connect and mysql_init is done by the monitors and since the monitors currently do not disconnect when they are stopped, they do not explicitly free their memory. I've been running valgrind and I've yet to pinpoint a reason for the increased memory consumption of MaxScale.

I did a test with 20000 commands and 100 iterations and MaxScale ended up with a memory usage of about 1200MB. The memory does not seem to grow linearly with the amount of queries executed. Increasing the amount of session commands for a session increases MaxScale's memory consumption. The amount does not drop down to normal levels after the sessions close so I think it might somehow relate to the embedded library.

I'll continue the investigation and reopen the bug.

I've noticed some interesting behavior, MaxScale seems to use large amounts of memory after large amounts of session commands are issued but the memory usage drops down when further sessions connect and issue smaller sets of session commands. For example, I ran the previous comment's query 20000 times and ended up with the following results:

UID PID PPID C SZ RSS PSR STIME TTY TIME CMD
markus 9013 8381 26 385047 664456 3 09:00 pts/3 00:18:10 ./maxscale -d -c ..

Next I ran 15 sessions of 200 queries and got the following results:

UID PID PPID C SZ RSS PSR STIME TTY TIME CMD
markus 9013 8381 25 301241 133464 7 09:00 pts/3 00:18:11 ./maxscale -d -c ..

This is indeed curious behavior but it would suggest that memory might not actually leak but the embedded library somehow cached data that is not immediately purged.

It seems I misunderstood the output and memory usage includes paged memory. So far I have not been able to find a memory leak while continuously issuing session commands. The overall memory usage stays around 800 Mb if I keep executing a loop of sessions issuing 20 queries of set @var1 = if(@var1 = NULL,0,@var1 + 1); forever. I will keep investigating for possible leaks.

The latest code release the memory correctly when the session close but, there is still an issue with long running connection that cannot be ignored. Here's an example using the latest code from the develop branch:

root@maxscale-1:/usr/local/skysql/maxscale# LD_PRELOAD=/usr/lib/libjemalloc.so.1 ./bin/maxscale -c `pwd` -f ./etc/MaxScale.cnf -lfile
root@maxscale-1:/usr/local/skysql/maxscale# top -b | grep `pidof maxscale`

8430 root 20 0 478m 43m 4000 S 1 5.9 0:00.17 maxscale
8430 root 20 0 478m 43m 4000 S 0 5.9 0:00.17 maxscale
8430 root 20 0 480m 46m 4396 R 4 6.2 0:00.28 maxscale
8430 root 20 0 536m 84m 4396 R 63 11.3 0:02.19 maxscale
8430 root 20 0 584m 119m 4396 R 65 16.1 0:04.17 maxscale
8430 root 20 0 632m 154m 4396 R 68 20.8 0:06.24 maxscale
8430 root 20 0 680m 186m 4396 R 68 25.1 0:08.29 maxscale
8430 root 20 0 720m 217m 4396 R 69 29.3 0:10.37 maxscale
8430 root 20 0 764m 247m 4396 R 69 33.2 0:12.46 maxscale
8430 root 20 0 804m 276m 4396 S 69 37.2 0:14.55 maxscale
8430 root 20 0 840m 302m 4396 R 67 40.7 0:16.58 maxscale
8430 root 20 0 876m 328m 4396 R 70 44.1 0:18.69 maxscale
8430 root 20 0 908m 44m 4400 S 65 6.0 0:20.65 maxscale
8430 root 20 0 908m 44m 4400 S 0 6.0 0:20.66 maxscale
8430 root 20 0 908m 44m 4400 S 0 6.0 0:20.67 maxscale
8430 root 20 0 908m 44m 4400 S 0 6.0 0:20.68 maxscale

The RSS is going 43M just after start to 328M just before the session exit and then goes back to 44M (if using jemalloc). The database session was:

yves@yves-desktop:/opt/src/MaxScale$ ( for i in `seq 1 10000`; do echo "set @test=$i;"; done ) | mysql -h 10.3.1.110 -utpcc -ptpcc tpcc

All the set variables are in the same connection. That represents (328M-44M)/10000 ~ 30KB per set variable, not small. If I loop more, eventually memory can no longer be allocated and MaxScale crashes.

8446 root 20 0 1240m 588m 4344 R 79 79.3 1:10.35 maxscale
mysql_embedded: Out of memory (Needed 18368 bytes)
8446 root 20 0 1252m 569m 4072 S 37 76.6 1:11.46 maxscale
8446 root 20 0 1252m 569m 4072 S 0 76.6 1:11.47 maxscale
Error in my_thread_global_end(): 1 threads didn't exit

Based on the message, that smells like the memory usage is coming from libmysqld.

my router configuration is:

[RW Split Router]
type=service
router=readwritesplit
servers=server1,server2,server3
router_options=slave_selection_criteria=LEAST_CURRENT_OPERATIONS
max_slave_connections=100%
max_slave_replication_lag=30
use_sql_variables_in=all
disable_sescmd_history=true
max_sescmd_history=0
user=maxuser
passwd=maxpasswd

Standby on this... found something wrong on my side.

The disable_sescmd_history and max_sescmd_history are router_option values and should be formatted like so:
router_options=slave_selection_criteria=LEAST_CURRENT_OPERATIONS,disable_sescmd_history=true,max_sescmd_history=0

Sadly, this does not provide a smooth way to configure it. I'll look into adding them as regular parameters.

All is good, the behavior is correct, this can be closed. I suggest you add an example of chaining router_options in the doc like:

router_options=slave_selection_criteria=LEAST_CURRENT_OPERATIONS,disable_sescmd_history=true

I happened to have 2 route_options lines and the disable_sescmd_history wasn't set.

closing is confirmed by bug reporter.

tturenko, markus makela
Which is the document that shows the example requested by Yves ?

this bug is about memory leak and high memory consumption. disable_sescmd_history option was introduced as well as several code improvements were done. Now things are better. What kind of document do you need?

tturenko

When we add new router option, we need to have example of how to use it in Router User Guide or Tutorial document.

We also need to have our test case that uses this option and validates that it takes care of memory leak during regression.

Dipti

Options are described in Configuration guide https://github.com/mariadb-corporation/MaxScale/blob/develop/Documentation/Getting-Started/Configuration-Guide.md#optional-parameters

tturenko Where is the test cases that tests these options ?

test for 'max_sescmd_history' and 'connection_timeout' options: https://github.com/mariadb-corporation/maxscale-system-test/blob/master/session_limits.cpp