Bug #72610 Out of memory replicating using RBR and slave having different data types.
Submitted: 11 May 2014 8:03 Modified: 18 Jul 2014 14:08
Reporter: Jean-François Gagné Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.6.19 OS:Linux
Assigned to: CPU Architecture:Any
Tags: replication

[11 May 2014 8:03] Jean-François Gagné
Description:
When replicating from a 5.5 master in ROW based logging and when a table includes a DATETIME column, if a transaction contains thousands of statements, a 5.6 slave will consume lots of RAM.  This can result in the OOM Killer being waken up, or the following lines being written to the error logs:

[ERROR] /usr/sbin/mysqld: Out of memory (Needed 4398240 bytes)
[ERROR] Out of memory; check if mysqld or some other process uses all available memory; if not, you may have to use 'ulimit' to allow mysqld to use more memory or you can add more swap space
[ERROR] Slave SQL: Can't create conversion table for table 'xxx.yyy', Error_code: 1678
[ERROR] Slave (additional info): Out of memory (Needed 4398240 bytes) Error_code: 5

How to repeat:
Configure a 5.5 master and a 5.6 slave (5.5.37 and 5.6.17).

Run the following bash script on the master:

{ cat << EOF
SET GLOBAL binlog_format='ROW';
DROP DATABASE IF EXISTS test;
CREATE DATABASE test;
CREATE TABLE test.t1 (
  userid   BIGINT PRIMARY KEY,
  password BIGINT DEFAULT NULL,
  created  DATETIME DEFAULT NULL);
BEGIN;
EOF
seq 1 1000000 | while read i; do
  echo "INSERT into test.t1 VALUES ($i, NULL, NOW());"
done
echo "COMMIT;"; } | sudo mysql

Observe mysqld RAM usage growing as the transaction is executed on the slave.

The 1000000 seq argument above will wake up the OOM killer on a vm with 4 GB of RAM and 1 GB of swap.  On such vm, I have this ps before running the transaction:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql    20420 23.3 33.3 4077064 1306888 ?     Sl   09:16   2:06 /usr/sbin/mysqld

It becomes the following while running the transaction (beginning):

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql    20420 29.4 46.6 4535816 1829356 ?     Sl   09:16   3:07 /usr/sbin/mysqld

It becomes the following while running the transaction (latter):

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql    20420 32.5 92.3 6632968 3623404 ?     Sl   09:16   3:36 /usr/sbin/mysqld

It was the following just before mysqld being killed by the OOM Killer:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql    20420 33.4 89.7 7091720 3520020 ?     Sl   09:16   3:45 /usr/sbin/mysqld
[14 May 2014 11:13] Andrii Nikitin
Do you have slave-rows-search-algorithms configured in my.cnf ?
Does increased memory usage happen when table has PK or index on userid ?
[15 May 2014 11:06] Jean-François Gagné
Hi Andrii,
thanks for looking into this bug.

Unless I am mistaken, the table has a PK:

> describe test.t1;
+----------+------------+------+-----+---------+-------+
| Field    | Type       | Null | Key | Default | Extra |
+----------+------------+------+-----+---------+-------+
| userid   | bigint(20) | NO   | PRI | NULL    |       |
| password | bigint(20) | YES  |     | NULL    |       |
| created  | datetime   | YES  |     | NULL    |       |
+----------+------------+------+-----+---------+-------+

Here are the requested parameters from the slave:

> show global variables where Variable_name='slave_allow_batching' or Variable_name='slave_rows_search_algorithms';
+------------------------------+-----------------------+
| Variable_name                | Value                 |
+------------------------------+-----------------------+
| slave_allow_batching         | OFF                   |
| slave_rows_search_algorithms | TABLE_SCAN,INDEX_SCAN |
+------------------------------+-----------------------+
[15 May 2014 13:52] Jean-François Gagné
Running out of memory can also happen when the master is updated to 5.6.  This is how to reproduce:

Configure a 5.5 master and a 5.6 slave (5.5.37 and 5.6.17).

Run the following bash script on the master:

{ cat << EOF
SET GLOBAL binlog_format='ROW';
DROP DATABASE IF EXISTS test_72610;
CREATE DATABASE test_72610;
CREATE TABLE test_72610.t1 (
  userid   BIGINT PRIMARY KEY,
  password BIGINT DEFAULT NULL,
  created  DATETIME DEFAULT NULL);
EOF
} | sudo mysql

Upgrade the master to 5.6 by replacing the binaries and running mysql_upgrade.

Run the following bash script on the master:

{ echo "SET GLOBAL binlog_format='ROW'; BEGIN;";
  seq -f "INSERT into test_72610.t1 VALUES (%.0f, NULL, NOW());" 1 1000000;
  echo "COMMIT;";
} | sudo mysql

Observe mysqld RAM usage growing as the transaction is executed on the slave.

The 1000000 seq argument above will trigger the below error message on a vm with 4 GB of RAM, 1 GB of swap and the following kernel parameters:

$ cat /proc/sys/vm/overcommit_{memory,ratio}
2
100

2014-05-15 15:45:36 24212 [ERROR] /usr/sbin/mysqld: Out of memory (Needed 1999200 bytes)
2014-05-15 15:45:36 24212 [ERROR] Out of memory; check if mysqld or some other process uses all available memory; if not, you may have to use 'ulimit' to allow mysqld to use more memory or you can add more swap space
2014-05-15 15:45:36 24212 [ERROR] Slave SQL: Can't create conversion table for table 'test_72610.t1', Error_code: 1678
2014-05-15 15:45:36 24212 [ERROR] Slave (additional info): Out of memory (Needed 1999200 bytes) Error_code: 5
2014-05-15 15:45:36 24212 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'binlog.000002' position 137889406

Some ps of the above:

Before running the transaction:

Thu May 15 15:44:02 CEST 2014
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql    24212  2.4 33.4 4075472 1313880 ?     Sl   12:38   4:29 /usr/sbin/mysqld

While running the transaction:

Thu May 15 15:45:03 CEST 2014
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql    24212  2.7 40.8 4337616 1600944 ?     Sl   12:38   5:12 /usr/sbin/mysqld

Before running out of memory:

Thu May 15 15:45:32 CEST 2014
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql    24212  3.2 51.4 4730832 2019172 ?     Sl   12:38   6:02 /usr/sbin/mysqld

Just after running out of memory:

Thu May 15 15:45:38 CEST 2014
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql    24212  3.2 33.5 4076516 1314928 ?     Sl   12:38   6:08 /usr/sbin/mysqld
[15 May 2014 15:42] MySQL Verification Team
Hello Jean-François,

Thank you for the bug report and test case.
Verified as described.

Environment used for testing:

Master - 5.5.38
Slave - 5.6.19

Before Starting slave:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 4852 root      20   0 1268m 445m 7764 S 40.6  7.5   0:03.18 mysqld

After Starting slave and when OOM invoked, memory usage(missed last few screens)

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 4852 root      20   0 9560m 5.6g 2124 S 56.0 96.0   6:29.96 mysqld

Out of memory: kill process 4620 (mysqld_safe) score 2816165 or a child
Killed process 4852 (mysqld)

Thanks,
Umesh
[27 May 2014 23:50] Domas Mituzas
You can add more memory to your machine to avoid the OOM killer.
I guess this bug is more of an "Excessive/unexpected memory usage" (not even a leak!) :)
[10 Jul 2014 14:15] Jean-François Gagné
Changing title from
Out of memory on 5.6 slave using RBR with DATETIME when table created in 5.5.
to
Out of memory replicating using RBR and slave having different data types.

This bug can happen when replicating from 5.6.19 to 5.6.19 when using RBR and slave having different data types than master.  (The new temporal formats in 5.6 is only a special case of the slave having different data types than master.)  This is how to reproduce:

Configure a 5.6 master and a 5.6 slave (5.6.19 and 5.6.19).

Start the slave with "slave_type_conversions = ALL_NON_LOSSY".

Run the following bash script on the master:

cat << EOF | sudo mysql
DROP DATABASE IF EXISTS test_72610;
CREATE DATABASE test_72610;
CREATE TABLE test_72610.t1 (
  userid   BIGINT PRIMARY KEY,
  password INT DEFAULT NULL);
EOF

Run the following bash script on the slave:

cat << EOF | sudo mysql
ALTER TABLE test_72610.t1 MODIFY COLUMN password BIGINT DEFAULT NULL;
EOF

Run the following bash script on the master:

{ echo "SET GLOBAL binlog_format='ROW'; BEGIN;";
  seq -f "INSERT into test_72610.t1 VALUES (%.0f, NULL);" 1 1000000;
  echo "COMMIT;";
} | sudo mysql

Observe mysqld RAM usage growing as the transaction is executed on the slave.
[18 Jul 2014 14:08] David Moss
Thanks for your input everyone. I have added the following to the 5.6.21 and 5.7.5 release notes with commit 3720:
Replication: When using row-based replication, running a long transaction involving a large number of events could trigger an Out of Memory(OOM) error if the slave's table structure was not compatible with the master's table structure. Such an incompatible situation could occur if the table on the slave had been manually changed, or when replicating between different MySQL versions that have different data types. This OOM error was caused because the virtual temporary tables created for the row conversion were not being freed until the end of the transaction, which was a problem when replicating large numbers of events.

Starting with this version, such virtual tables are correctly freed during the conversion process.
[25 Sep 2014 11:41] Laurynas Biveinis
revno: 6065
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.6
timestamp: Mon 2014-07-07 23:25:21 +0530
message:
  Bug #18770469 OUT OF MEMORY ON 5.6 SLAVE USING RBR WITH DATETIME WHEN TABLE
  CREATED IN 5.5.
  
  Problem: In RBR, running a long transaction, which has big number or rows
  log events, causes Out of Memory(OOM) error on slave when Slave's table
  structure is not compatible with Master's table structure.
  
  Even though the reported issue is between 5.5->5.6 replication
  and with DATATIME column, the problem can be seen in 5.6->5.6 replication
  and with any data type column when Slave's table structure is not
  compatible with Master's table structure i.e., when Slave server finds
  both Master and Slave table's are not compatible with each other and
  decides to create a virtual temporary table to do the row conversion
  at replication layer. This situation happens when some one alters the
  table on Slave by connecting directly to Slave server.
  
  Analysis:
  
  In the above explained scenario, when slave is creating a virtual
  temporary table, the logic is using thd's mem_root to create field
  and table structure. This temporary table is required only till
  the end of Rows_log_event scope but Slave's SQL thread mem_root is
  getting freed only at the end of the transaction. There are some
  exceptions that mem_root is getting freed in some other places in
  the code. Eg: After every Query_log_event::do_apply_event(),
  free_root is called on thread's mem_root. 
  
  Sample events:
    master-bin.000001 536  Query 1 608 BEGIN
    master-bin.000001 608 Table_map 1 696 table_id: 81 (test.t1)
    master-bin.000001 696 Write_rows  1 900 table_id: 81 flags: STMT_END_F
    master-bin.000001 900 Table_map 1 988 table_id: 81 (test.t1)
    master-bin.000001 988 Write_rows  1 1192  table_id: 81 flags: STMT_END_F
    ....
    master-bin.000001 29808 Xid 1 29839 COMMIT /* xid=167 */
  
  Lets say table is 't1' and it's structure is different from Master
  to Slave. And for every Rows_log_event, it creates temporary table
  and uses some 'X' amount of memory from thd's mem_root.
  If a transaction involves 'Y' number of Rows_log_events, then by
  the time of the end of the transaction, server would have used
  'XY' amount of memory from thd's mem_root. This can cause OOM
  when 'Y' is increasing. The root cause of the problem is server
  is holding the memory of temporary table even though it's scope
  is ended after applying the Rows_log_event, hence mem_root usage
  is growing up.
  
  Unlike Query_log_event::do_apply_event(), Rows_log_event::do_apply_event
  can be called from a regular thread (not only SQL thread), hence
  free_root(thd->mem_root,...) cannot be called at the end of
  Rows_log_event::do_apply_event.
  
  Fix: m_event_mem_root ( a special mem root) is added to Log_event
  class and it will be initialized in constructor and freed in
  destructor. If there is a memory requirement while applying
  any type of events whose scope should be till applying the
  event, it can be allocated from this special mem root.
  In the above situation, while creating the temporary table
  the memory needed is allocated from this special mem root
  which will be freed in ~Log_event().
[25 Sep 2014 11:46] Laurynas Biveinis
revno: 6078
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.6
timestamp: Tue 2014-07-15 16:26:07 +0530
message:
  Bug#18770469 OUT OF MEMORY ON 5.6 SLAVE USING RBR WITH DATETIME WHEN TABLE CREATED IN 5.5.
  
  Post push fix
  (Removing newly added THD::alloc() member. It is not required)
[30 Sep 2014 12:09] David Moss
Posted by developer:
 
Reopened by merge, no new changelog entries needed. Set back to Closed.
[4 Nov 2014 14:35] David Moss
Posted by developer:
 
Reopened by merge, no new changelog entries needed. Set back to Closed.