| Bug #85251 | Memory leak in master-master GTID replication with sync_relay_log_info | ||
|---|---|---|---|
| Submitted: | 1 Mar 2017 13:16 | Modified: | 29 Sep 2017 12:06 |
| Reporter: | Przemyslaw Malkowski | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
| Version: | 5.7.17, 8.0.0 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | GTID, memory leak | ||
[1 Mar 2017 13:44]
Przemyslaw Malkowski
Same test results on 8.0:
rcsandbox_mysql-8_0_0$ ps aux|grep rcsandbox_mysql-8_0_0|grep .sock|awk '{print "vsz: "$5/1024" MB","rss: "$6/1024" MB",$19}'
vsz: 3871.91 MB rss: 1575.86 MB --port=14001
vsz: 1692.12 MB rss: 330.715 MB --port=14002
rcsandbox_mysql-8_0_0$ ./use_all 'select * from sys.memory_global_total'
# server: 1:
total_allocated
1.55 GiB
# server: 2:
total_allocated
360.32 MiB
node1 [localhost] {msandbox} ((none)) > select @@version;
+---------------+
| @@version |
+---------------+
| 8.0.0-dmr-log |
+---------------+
1 row in set (0.00 sec)
node1 [localhost] {msandbox} ((none)) > select event_name, high_number_of_bytes_used/1024/1024 high_number_of_bytes_used_MB from performance_schema.memory_summary_global_by_event_name order by high_number_of_bytes_used desc limit 10;
+----------------------------------------------------------------------+------------------------------+
| event_name | high_number_of_bytes_used_MB |
+----------------------------------------------------------------------+------------------------------+
| memory/sql/thd::main_mem_root | 1206.48774719 |
| memory/innodb/buf_buf_pool | 131.06250000 |
| memory/innodb/log0log | 32.00839233 |
| memory/innodb/std | 27.05821228 |
| memory/sql/XID | 19.00152588 |
| memory/innodb/lock0lock | 14.35904694 |
| memory/performance_schema/events_statements_history_long | 13.65661621 |
| memory/innodb/fil0fil | 12.41208172 |
| memory/performance_schema/events_statements_summary_by_digest.tokens | 9.76562500 |
| memory/performance_schema/events_statements_history_long.tokens | 9.76562500 |
+----------------------------------------------------------------------+------------------------------+
10 rows in set (0.00 sec)
node1 [localhost] {msandbox} ((none)) > select thread_id tid, user, current_count_used ccu, current_allocated ca, current_avg_alloc caa, current_max_alloc cma, total_allocated from sys.memory_by_thread_by_current_bytes limit 10;
+-----+----------------------------+--------+------------+-----------+------------+-----------------+
| tid | user | ccu | ca | caa | cma | total_allocated |
+-----+----------------------------+--------+------------+-----------+------------+-----------------+
| 41 | sql/slave_sql | 539822 | 1.19 GiB | 2.32 KiB | 1.18 GiB | 13.05 GiB |
| 1 | sql/main | 1094 | 7.50 MiB | 7.02 KiB | 8.00 MiB | 58.74 MiB |
| 66 | msandbox@localhost | 72 | 531.08 KiB | 7.38 KiB | 196.70 KiB | 905.86 KiB |
| 22 | innodb/srv_worker_thread | 363 | 397.95 KiB | 1.10 KiB | 364.65 KiB | 1.59 GiB |
| 40 | sql/slave_io | 373 | 107.66 KiB | 296 bytes | 32.01 KiB | 7.04 MiB |
| 23 | innodb/srv_worker_thread | 51 | 56.44 KiB | 1.11 KiB | 33.77 KiB | 149.79 MiB |
| 20 | innodb/srv_worker_thread | 34 | 34.92 KiB | 1.03 KiB | 12.49 KiB | 479.17 MiB |
| 42 | rsandbox@localhost | 15 | 12.90 KiB | 880 bytes | 8.00 KiB | 62.29 KiB |
| 29 | innodb/dict_stats_thread | 23 | 736 bytes | 32 bytes | 736 bytes | 5.73 MiB |
| 30 | innodb/fts_optimize_thread | 1 | 648 bytes | 648 bytes | 648 bytes | 648 bytes |
+-----+----------------------------+--------+------------+-----------+------------+-----------------+
10 rows in set (0.10 sec)
[2 Mar 2017 6:46]
MySQL Verification Team
Hello Przemyslaw, Thank you for the report. Verified as described. Thanks, Umesh
[2 Mar 2017 6:49]
MySQL Verification Team
5.7.17 - test results
Attachment: 85251_5.7.17.results (application/octet-stream, text), 8.60 KiB.
[2 Mar 2017 7:11]
MySQL Verification Team
-- One more sysbench attempt
[umshastr@hod03]~/bugs/sysbench: sysbench/sysbench --num-threads=16 --max-requests=300000 --db-driver=mysql --test=/home/umshastr/bugs/sysbench/sysbench/tests/db/oltp.lua --mysql-table-engine=InnoDB --mysql-db=sbtest1 --mysql-user=msandbox --mysql-password=msandbox --oltp-table-size=1000000 --mysql-socket=/tmp/mysql_sandbox15701.sock run
sysbench 0.5: multi-threaded system evaluation benchmark
Running the test with following options:
Number of threads: 16
Random number generator seed is 0 and will be ignored
Threads started!
OLTP test statistics:
queries performed:
read: 4206230
write: 1201101
other: 600637
total: 6007968
transactions: 300192 (2014.51 per sec.)
deadlocks: 253 (1.70 per sec.)
read/write requests: 5407331 (36287.18 per sec.)
other operations: 600637 (4030.72 per sec.)
General statistics:
total time: 149.0149s
total number of events: 300192
total time taken by event execution: 2383.5730s
response time:
min: 3.15ms
avg: 7.94ms
max: 267.93ms
approx. 95 percentile: 26.65ms
Threads fairness:
events (avg/stddev): 18762.0000/68.29
execution time (avg/stddev): 148.9733/0.00
[umshastr@hod03]~/sandboxes/rcsandbox_mysql-5_7_17: ./use_all 'select * from sys.memory_global_total'
# server: 1:
total_allocated
2.39 GiB
# server: 2:
total_allocated
335.46 MiB
[umshastr@hod03]~/sandboxes/rcsandbox_mysql-5_7_17: ps aux|grep rcsandbox_mysql-5_7_17|grep .sock|awk '{print "vsz: "$5/1024" MB","rss: "$6/1024" MB",$19}'
vsz: 5123.34 MB rss: 2428.93 MB --port=15701
vsz: 1790.28 MB rss: 300.293 MB --port=15702
[umshastr@hod03]~/sandboxes/rcsandbox_mysql-5_7_17: ./n1 -e 'select event_name, high_number_of_bytes_used/1024/1024 high_number_of_bytes_used_MB from performance_schema.memory_summary_global_by_event_name order by high_number_of_bytes_used desc limit 10;'
+----------------------------------------------------------------------+------------------------------+
| event_name | high_number_of_bytes_used_MB |
+----------------------------------------------------------------------+------------------------------+
| memory/sql/thd::main_mem_root | 2085.32130432 |
| memory/innodb/buf_buf_pool | 131.06250000 |
| memory/innodb/log0log | 32.00839996 |
| memory/sql/XID | 19.00152588 |
| memory/innodb/lock0lock | 14.35904694 |
| memory/performance_schema/events_statements_history_long | 13.65661621 |
| memory/innodb/fil0fil | 10.22176933 |
| memory/performance_schema/events_statements_summary_by_digest.tokens | 9.76562500 |
| memory/performance_schema/events_statements_history_long.tokens | 9.76562500 |
| memory/performance_schema/events_statements_history_long.sqltext | 9.76562500 |
+----------------------------------------------------------------------+------------------------------+
[umshastr@hod03]~/sandboxes/rcsandbox_mysql-5_7_17: ./n1 -e 'select thread_id tid, user, current_count_used ccu, current_allocated ca, current_avg_alloc caa, current_max_alloc cma, total_allocated from sys.memory_by_thread_by_current_bytes limit 10;'
+-----+---------------------------+--------+------------+-----------+------------+-----------------+
| tid | user | ccu | ca | caa | cma | total_allocated |
+-----+---------------------------+--------+------------+-----------+------------+-----------------+
| 36 | sql/slave_sql | 930903 | 2.06 GiB | 2.33 KiB | 2.04 GiB | 22.45 GiB |
| 1 | sql/main | 28185 | 189.36 MiB | 6.88 KiB | 131.06 MiB | 220.49 MiB |
| 88 | msandbox@localhost | 53 | 721.76 KiB | 13.62 KiB | 256.00 KiB | 755.47 KiB |
| 35 | sql/slave_io | 694 | 118.00 KiB | 174 bytes | 32.01 KiB | 14.23 MiB |
| 37 | rsandbox@localhost | 18 | 13.04 KiB | 742 bytes | 8.00 KiB | 70.42 KiB |
| 29 | sql/compress_gtid_table | 5 | 4.84 KiB | 992 bytes | 4.30 KiB | 4.99 KiB |
| 24 | innodb/dict_stats_thread | 41 | 672 bytes | 16 bytes | 1.34 KiB | 10.21 MiB |
| 23 | innodb/buf_dump_thread | 4 | 128 bytes | 32 bytes | 128 bytes | 609.20 KiB |
| 27 | sql/signal_handler | 0 | 0 bytes | 0 bytes | 0 bytes | 0 bytes |
| 2 | sql/thread_timer_notifier | 0 | 0 bytes | 0 bytes | 0 bytes | 0 bytes |
+-----+---------------------------+--------+------------+-----------+------------+-----------------+
[umshastr@hod03]~/sandboxes/rcsandbox_mysql-5_7_17:
[2 Mar 2017 13:13]
MySQL Verification Team
Bug#85034 marked as duplicate of this one
[2 Aug 2017 14:21]
Vlad Lesin
The following is the analysis for 5.7:
1) In Rpl_info_table::do_init_info() and some other Rpl_info_table::* functions
the thd is gotten with the following code:
THD *thd= access->create_thd();
2) If we look into Rpl_info_table_access::create_thd() we will see that thd is
created only in the case if the current_thd is NULL, otherwise the
current_thd is returned. For our case that means the replication thread is
used to store data in rpl info table.
THD *Rpl_info_table_access::create_thd()
{
THD *thd= current_thd;
if (!thd)
{
thd= System_table_access::create_thd();
thd->system_thread= SYSTEM_THREAD_INFO_REPOSITORY;
thd_created= true;
}
return(thd);
}
3) If wee look at the massif.out file we will see that new memory is allocated
with "new" operator with parameters, and thd->mem_root is used as the
parameter, so the memory is allocated in thd->mem_root arena.
->09.32% (578,806,592B) 0x188E91C: my_raw_malloc (in /usr/sbin/mysqld-debug)
| ->09.32% (578,806,592B) 0x188E519: my_malloc (in /usr/sbin/mysqld-debug)
| ->09.03% (561,046,608B) 0x1887A44: alloc_root (in /usr/sbin/mysqld-debug)
| | ->08.75% (543,172,776B) 0xEFC948: Sql_alloc::operator new(unsigned long, st_mem_root*) (in /usr/sbin/mysqld-debug)
| | | ->06.25% (388,424,352B) 0x153B929: LEX::new_query(st_select_lex*) (in /usr/sbin/mysqld-debug)
| | | | ->06.25% (388,424,352B) 0x153BEEE: LEX::new_top_level_query() (in /usr/sbin/mysqld-debug)
| | | | ->06.25% (388,424,352B) 0x153B5E2: lex_start(THD*) (in /usr/sbin/mysqld-debug)
| | | | ->06.25% (388,424,352B) 0x1858CB9: Rpl_info_table_access::before_open(THD*) (in /usr/sbin/mysqld-debug)
| | | | | ->06.25% (388,424,352B) 0x181FA59: System_table_access::open_table(THD*, st_mysql_lex_string, st_mysql_lex_string, unsigned int, thr_lock_type, TABLE**, Open_tables_backup*) (in /usr/sbin/mysqld-debug)
| | | | | ->06.25% (388,424,352B) 0x186E3D3: Rpl_info_table::do_flush_info(bool) (in /usr/sbin/mysqld-debug)
4) If we look at the end of Rpl_info_table::do_init_info() and some other
Rpl_info_tables::* functions we will see the call of access->drop_thd(thd)
which code is the following:
void Rpl_info_table_access::drop_thd(THD *thd)
{
DBUG_ENTER("Rpl_info::drop_thd");
if (thd_created)
{
System_table_access::drop_thd(thd);
thd_created= false;
}
DBUG_VOID_RETURN;
}
For our case thd_created is false, and that is why thd is not deleted and
the memory managed with thd->mem_root is not deallocated.
The solution is to use local MEMROOT instance which would be freed after the
corresponding function finish their work with thd.
For 8.0 there is no need to fix it because because new THD and THD::memroot are created unconditionally (while in 5.7 new THD is created only if current_thd is NULL). But the function which creates THD can return NULL, and this case is not processed at all (I would add assert there).
[2 Aug 2017 14:25]
Vlad Lesin
the patch which creates local memroot object (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.
Contribution: 1.diff (text/x-patch), 5.13 KiB.
[29 Sep 2017 12:06]
Margaret Fisher
Posted by developer: Changelog entry added for MySQL 8.0.4 and 5.7.21: A memory leak was fixed in GTID-based replication. Memory was not being freed after the repository tables were updated for skipped or ignored events.
Description: When sync_relay_log_info=1 the leak is manifesting very fast, with higher sync values, accordingly slower. With default of 10k, the leak may too slow to notice. Primary master ends up with huge memory usage, growing forever. Memory instrumentation says it ends up in memory/sql/thd::main_mem_root and caused by SQL slave thread. stop slave; start slave; sequence releases the RSS memory, but not the VSZ. How to repeat: Simple mysqlsandbox + sysbench test: $ make_replication_sandbox --master_master tarballs/mysql-5.7.17-linux-glibc2.5-x86_64.tar.gz $ cd rcsandbox_mysql-5_7_17 $ for i in {1..2}; do echo "sync_relay_log_info=1" >> node$i/my.sandbox.cnf ; done $ for i in {1..2}; do echo "performance-schema-instrument='memory%=ON' " >> node$i/my.sandbox.cnf ; done $ ./enable_gtid $ ./n1 -e 'create database sbtest1' $ ps aux|grep rcsandbox_mysql-5_7_17|grep .sock|awk '{print "vsz: "$5/1024" MB","rss: "$6/1024" MB",$19}' vsz: 1470.8 MB rss: 172.523 MB --port=15701 vsz: 1470.8 MB rss: 172.789 MB --port=15702 $ ./use_all 'select * from sys.memory_global_total' # server: 1: total_allocated 324.68 MiB # server: 2: total_allocated 324.75 MiB $ sysbench --num-threads=16 --max-requests=300000 --db-driver=mysql --test=oltp --mysql-table-engine=InnoDB --mysql-db=sbtest1 --mysql-user=msandbox --mysql-password=msandbox --oltp-table-size=1000000 --mysql-socket=/tmp/mysql_sandbox15701.sock --test=/usr/share/doc/sysbench/tests/db/oltp.lua prepare $ sysbench --num-threads=16 --max-requests=300000 --db-driver=mysql --test=oltp --mysql-table-engine=InnoDB --mysql-db=sbtest1 --mysql-user=msandbox --mysql-password=msandbox --oltp-table-size=1000000 --mysql-socket=/tmp/mysql_sandbox15701.sock --test=/usr/share/doc/sysbench/tests/db/oltp.lua run -- wait till replication catches up $ ps aux|grep rcsandbox_mysql-5_7_17|grep .sock|awk '{print "vsz: "$5/1024" MB","rss: "$6/1024" MB",$19}' vsz: 3778.61 MB rss: 1514.19 MB --port=15701 vsz: 1662.8 MB rss: 301.727 MB --port=15702 $ ./use_all 'select * from sys.memory_global_total' # server: 1: total_allocated 1.50 GiB # server: 2: total_allocated 335.29 MiB node1 [localhost] {msandbox} ((none)) > select event_name, high_number_of_bytes_used/1024/1024 high_number_of_bytes_used_MB from performance_schema.memory_summary_global_by_event_name order by high_number_of_bytes_used desc limit 10; +----------------------------------------------------------------------+------------------------------+ | event_name | high_number_of_bytes_used_MB | +----------------------------------------------------------------------+------------------------------+ | memory/sql/thd::main_mem_root | 1171.11776733 | | memory/innodb/buf_buf_pool | 131.06250000 | | memory/innodb/log0log | 32.00839996 | | memory/sql/XID | 19.00152588 | | memory/innodb/lock0lock | 14.35904694 | | memory/performance_schema/events_statements_history_long | 13.65661621 | | memory/innodb/fil0fil | 10.22165203 | | memory/performance_schema/events_statements_summary_by_digest.tokens | 9.76562500 | | memory/performance_schema/events_statements_history_long.tokens | 9.76562500 | | memory/performance_schema/events_statements_history_long.sqltext | 9.76562500 | +----------------------------------------------------------------------+------------------------------+ 10 rows in set (0.00 sec) node1 [localhost] {msandbox} ((none)) > select thread_id tid, user, current_count_used ccu, current_allocated ca, current_avg_alloc caa, current_max_alloc cma, total_allocated from sys.memory_by_thread_by_current_bytes limit 10; +-----+--------------------------+--------+------------+-----------+------------+-----------------+ | tid | user | ccu | ca | caa | cma | total_allocated | +-----+--------------------------+--------+------------+-----------+------------+-----------------+ | 36 | sql/slave_sql | 517331 | 1.16 GiB | 2.35 KiB | 1.14 GiB | 12.59 GiB | | 1 | sql/main | 28175 | 189.36 MiB | 6.88 KiB | 131.06 MiB | 220.49 MiB | | 60 | msandbox@localhost | 56 | 721.86 KiB | 12.89 KiB | 256.00 KiB | 832.50 KiB | | 35 | sql/slave_io | 361 | 105.10 KiB | 298 bytes | 32.01 KiB | 7.06 MiB | | 37 | rsandbox@localhost | 18 | 13.04 KiB | 742 bytes | 8.00 KiB | 62.40 KiB | | 24 | innodb/dict_stats_thread | 27 | 1.16 KiB | 44 bytes | 832 bytes | 5.73 MiB | | 23 | innodb/buf_dump_thread | 4 | 128 bytes | 32 bytes | 128 bytes | 609.20 KiB | | 20 | innodb/srv_worker_thread | 0 | 0 bytes | 0 bytes | 0 bytes | 0 bytes | | 21 | innodb/srv_worker_thread | 0 | 0 bytes | 0 bytes | 0 bytes | 0 bytes | | 22 | innodb/srv_purge_thread | 0 | 0 bytes | 0 bytes | 0 bytes | 0 bytes | +-----+--------------------------+--------+------------+-----------+------------+-----------------+ 10 rows in set (0.06 sec) Suggested fix: Avoid memory leak.