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:
None 
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:16] Przemyslaw Malkowski
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.
[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.