| 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: | |
| Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
| Version: | 5.6.19 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | replication | ||
[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.
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