Bug #19613 mysqlbinlog allocates huge amounts of RAM on unaligned start-position
Submitted: 8 May 2006 14:34 Modified: 4 Jul 2006 12:39
Reporter: Issac Goldstand Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Command-line Clients Severity:S2 (Serious)
Version:4.1.14 OS:Microsoft Windows (Win32 + Linux)
Assigned to: CPU Architecture:Any

[8 May 2006 14:34] Issac Goldstand
Description:
mysqlbinlog can be run with --start-position pointing to anything that's not really a binary log header block and will still to read the block with the data_len in the "header" read (via Log_event::read_log_event).  It will eventually realize that it's got bogus data in the event, but not before running packet->append(file, data_len), which can do really evil things to the system if data_len is really big (it often is hundreds of MB) and there's enough swap space (and not enough RAM) to hold it.  (Mericfully, if data_len > RAM + SWAP, it dies before allocating the memory [at least on LINUX])

Most mysql utilities allow max_allowed_packet to be set to avoid situations like this getting out of control, but mysqlbinlog doesn't support it.  

How to repeat:
run mysqlbinlog with a random --start-position.  it'll happen sooner or later :)

Suggested fix:
Support max_allowed_packet in mysqlbinlog and default to 16M
[11 May 2006 12:14] Valeriy Kravchuk
Thank you for the problem report. Can you try to create and upload exact (valid) binary log and specify the exact start position to demonstrate the problem. Or I have to use any one and just try start positions from 1 to something?
[11 May 2006 12:42] Issac Goldstand
Any random position that's not actually the beginning of a event header block should reproduce this to some degree or another.

Since any binary log file (at least from 4+) starts with a "start binary log" event, we can try to reproduce the effect using that specific event.  Thus, running mysqlbinlog --start-position 13 on any binary log sould do a nice job of trying to malloc 850MB or so.

However, recall that this is just one symptom - many random and non-random binary log positions will cause similar effects!
[11 May 2006 12:57] Valeriy Kravchuk
I had tried with debug binaries of 4.1.20-BK on Linux, and got nothing awful:

openxs@suse:~/dbs/4.1> bin/mysqlbinlog --start-position=13 var/suse-bin.000001
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
bin/mysqlbinlog: Out of memory at line 592, 'log_event.cc'
bin/mysqlbinlog: needed 872416001 byte (851969k), memory in use: 25468 bytes (25k)
ERROR: Error in Log_event::read_log_event(): 'Out of memory', data_len: 87241600
0, event_type: 4
Could not read entry at offset 13:Error in log format or read error

Will try with non-debug one...
[11 May 2006 13:01] Issac Goldstand
You consider "Out of memory " to not be awful?!?
[9 Jun 2006 13:36] Valeriy Kravchuk
Checked again with 4.1.21-BK on Linux:

openxs@suse:~/dbs/4.1> while true; do bin/mysqlbinlog --start-position=13 var/suse-bin.000001; done

And even in this case I saw no increase in memory consumption! Huge amounts of RAM are NOT allocated (I have 256MB on that box in total).
[10 Jun 2006 0:34] Tal Kelrich
Tried on latest daily snapshot, still has same issue
[root@SCU client]# pwd
/tmp/mysql-4.1.21-nightly-20060609/client
[root@SCU client]# ./mysqlbinlog --start-position=13 SCU-bin.053
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/tmp/mysql-4.1.21-nightly-20060609/client/.libs/lt-mysqlbinlog: Out of memory (Needed 872416001 bytes)
ERROR: Error in Log_event::read_log_event(): 'Out of memory', data_len: 872416000, event_type: 4
Could not read entry at offset 13:Error in log format or read error
[11 Jun 2006 5:53] Valeriy Kravchuk
Yes, the same error message still appears. But, according to my check, there are no attempts to _allocate_ any amount of memory. Only check is performed. So, this is a correct behaviour, that does not hurt overall system in any way.
[12 Jun 2006 7:56] Tal Kelrich
AFAICT (I traced the code with ltrace and gdb), it calls malloc(0x34000301), fails immediatly under linux if not enough RAM/swap exists.
under windows huge malloc will usually succeed as windows will grow the swap.
[19 Jun 2006 9:02] Tal Kelrich
I've created a patch that seems to make this problem go away, only tested on linux
patch here: http://hasturkun.com/temp/mysql-4.1.21-mysqlbinlog-max_allowed.patch

[tal@SCU client]$ ./mysqlbinlog --start-position=13 SCU-bin.053
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
ERROR: Error in Log_event::read_log_event(): 'Event too big', data_len: 872416000, event_type: 4
Could not read entry at offset 13:Error in log format or read error
[4 Jul 2006 12:39] Valeriy Kravchuk
On Windows with 4.1.20 I've got:

C:\...ram Files\MySQL\MySQL Server 4.1>position=13 data/toshiba-user-bin.000001
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 889193472,
event_type: 98
Could not read entry at offset 13:Error in log format or read error

but still no obvious increase in RAM/swap usage (according to Task Manager). So, I see no real need to apply any patches.
[4 Jul 2006 12:44] Valeriy Kravchuk
Sorry, used mysqlbinlog from 4.1.20 on 5.0.x binary log. With "native" one result is the same, though:

C:\...ram Files\MySQL\MySQL Server 4.1>position=13 data/toshiba-user-bin.000002
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 872416000,
event_type: 4
Could not read entry at offset 13:Error in log format or read error

Still no attempts to allocate so much memory.
[2 Aug 2006 14:22] Tal Kelrich
tried latest release, screenshots and output follow...

before: 
http://hasturkun.com/temp/mysqlsshots/before.png

while running mysqlbinlog (taking up 25MB of RAM and 854MB of virtual memory):
http://hasturkun.com/temp/mysqlsshots/during.png

C:\temp\mysql-4.1.21-win32\bin>mysqlbinlog --start-position=13 c:\temp\iocl-bos-
bin.000014
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 872416000,
event_type: 4
Could not read entry at offset 13:Error in log format or read error