MySQL Bugs: #19613: mysqlbinlog allocates huge amounts of RAM on unaligned start-position

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:	Windows (Win32 + Linux)
Assigned to:		CPU Architecture:	Any

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

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?

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!

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...

You consider "Out of memory " to not be awful?!?

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).

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

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.

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.

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

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.

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.

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