Bug #50225 rpl_backup_shutdown reveals memory issue in backup code
Submitted: 11 Jan 2010 10:57 Modified: 14 Jan 2010 7:26
Reporter: Andrei Elkin Email Updates:
Status: Patch queued Impact on me:
None 
Category:MySQL Server: Backup Severity:S3 (Non-critical)
Version: OS:Any
Assigned to: Rafal Somla CPU Architecture:Any
Triage: Triaged: D2 (Serious)

[11 Jan 2010 10:57] Andrei Elkin
Description:
Evidence can be found on PB2 as well:

https://central.sun.net/http//pb2.norway.sun.com?template=mysql_show_test_failure&test_fai...

rpl.rpl_backup_shutdown                  [ fail ]  Found warnings/errors in server log file!
        Test ended at 2010-01-10 16:40:38
mysqltest: Logging to ''.
mysqltest: Results saved in ''.
mysqltest: Connecting to server localhost:13020 (socket /export/home2/pb2/test/sb_1-1165605-1263092695.4/tmp/A5m2hkYmzR/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-warnings.test' ...
line
==8351== 
==8351== 16 bytes in 2 blocks are indirectly lost in loss record 1 of 3
==8351==    at 0x4A05809: malloc (vg_replace_malloc.c:149)
==8351==    by 0xB3190E: my_malloc (my_malloc.c:37)
==8351==    by 0x693243: String::real_alloc(unsigned) (sql_string.cc:52)
==8351==    by 0x601249: String::alloc(unsigned) (sql_string.h:209)
==8351==    by 0x693522: String::copy(char const*, unsigned, charset_info_st*) (sql_string.cc:212)
==8351==    by 0x8C04F8: obs::Abstract_obj::Abstract_obj(st_mysql_lex_string, bool) (si_objects.cc:679)
==8351==    by 0x8C0594: obs::Database_item_obj::Database_item_obj(st_mysql_lex_string, st_mysql_lex_string, bool) (si_objects.cc:929)
==8351==    by 0x8C0736: obs::Table_obj::Table_obj(st_mysql_lex_string, st_mysql_lex_string) (si_objects.cc:983)
==8351==    by 0x8BCEFA: obs::find_table_for_trigger(THD*, String const*, String const*) (si_objects.cc:3203)
==8351==    by 0xC0A33C: Backup_info::add_db_object(backup::Image_info::Db&, enum_bstream_item_type, obs::Obj*) (backup_info.cc:1384)
==8351==    by 0xC0A9EC: Backup_info::add_objects(backup::Image_info::Db&, enum_bstream_item_type, obs::Obj_iterator&) (backup_info.cc:965)
==8351==    by 0xC0C5F4: Backup_info::add_db_items(backup::Image_info::Db&) (backup_info.cc:1114)
==8351==    by 0xC0CCE1: Backup_info::add_dbs(THD*, List<st_mysql_lex_string>&) (backup_info.cc:842)
==8351==    by 0xBF59D7: execute_backup_command(THD*, LEX*, String*, bool, bool) (kernel.cc:242)
==8351==    by 0x6AC211: mysql_execute_command(THD*) (sql_parse.cc:2455)
==8351==    by 0x6B3436: mysql_parse(THD*, char const*, unsigned, char const**) (sql_parse.cc:5879)

How to repeat:
to see PB2 or run the test.
[12 Jan 2010 16:46] Rafal Somla
I was able to reproduce symptoms with the following test case:

---------------------------------------------------------------
CREATE DATABASE db1;
CREATE TABLE db1.t1 (a int);
CREATE TRIGGER db1.r1 AFTER INSERT ON db1.t1 FOR EACH ROW SET @foo=1;

BACKUP DATABASE db1 TO 'db1.bak';

--echo --> Stop the server ...
--write_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
wait
EOF
--shutdown_server 10
--source include/wait_until_disconnected.inc

--echo --> Restart the server ...
--append_file $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
restart
EOF
--enable_reconnect
--source include/wait_until_connected_again.inc

--echo --> Cleanup ...
DROP DATABASE db1;

--exit
---------------------------------------------------------------

It means that issue is not related to replication. I observe memory leak only if server is stopped and restarted - if these lines are commented-out then no leak is reported. Also, one needs to backup a trigger to get memory leak.
[12 Jan 2010 16:48] Rafal Somla
When I run the above test script in valgrind mode I see the following stacks:

==8209== 
==8209== 16 bytes in 2 blocks are indirectly lost in loss record 1 of 7
==8209==    at 0x4023D6E: malloc (vg_replace_malloc.c:207)
==8209==    by 0x85DB900: my_malloc (my_malloc.c:37)
==8209==    by 0x82755FC: String::real_alloc(unsigned) (sql_string.cc:52)
==8209==    by 0x81EF790: String::alloc(unsigned) (sql_string.h:209)
==8209==    by 0x8275885: String::copy(char const*, unsigned, charset_info_st*) (sql_string.cc:212)
==8209==    by 0x847FAC6: obs::Abstract_obj::Abstract_obj(st_mysql_lex_string, bool) (si_objects.cc:679)
==8209==    by 0x847FC23: obs::Database_item_obj::Database_item_obj(st_mysql_lex_string, st_mysql_lex_string, bool) (si_objects.cc:929)
==8209==    by 0x847FD80: obs::Table_obj::Table_obj(st_mysql_lex_string, st_mysql_lex_string) (si_objects.cc:983)
==8209==    by 0x847CE06: obs::find_table_for_trigger(THD*, String const*, String const*) (si_objects.cc:3203)
==8209==    by 0x86B3589: Backup_info::add_db_object(backup::Image_info::Db&, enum_bstream_item_type, obs::Obj*) (backup_info.cc:1384)
==8209==    by 0x86B3BA9: Backup_info::add_objects(backup::Image_info::Db&, enum_bstream_item_type, obs::Obj_iterator&) (backup_info.cc:965)
==8209==    by 0x86B58C6: Backup_info::add_db_items(backup::Image_info::Db&) (backup_info.cc:1114)
==8209==    by 0x86B5FB4: Backup_info::add_dbs(THD*, List<st_mysql_lex_string>&) (backup_info.cc:842)
==8209==    by 0x869E62B: execute_backup_command(THD*, LEX*, String*, bool, bool) (kernel.cc:242)
==8209==    by 0x828E030: mysql_execute_command(THD*) (sql_parse.cc:2455)
==8209==    by 0x82959B1: mysql_parse(THD*, char const*, unsigned, char const**) (sql_parse.cc:5879)
==8209== 
==8209== 
==8209== 112 (96 direct, 16 indirect) bytes in 1 blocks are definitely lost in loss record 5 of 7
==8209==    at 0x4023D6E: malloc (vg_replace_malloc.c:207)
==8209==    by 0x85DC789: operator new(unsigned) (my_new.cc:27)
==8209==    by 0x847CDDE: obs::find_table_for_trigger(THD*, String const*, String const*) (si_objects.cc:3203)
==8209==    by 0x86B3589: Backup_info::add_db_object(backup::Image_info::Db&, enum_bstream_item_type, obs::Obj*) (backup_info.cc:1384)
==8209==    by 0x86B3BA9: Backup_info::add_objects(backup::Image_info::Db&, enum_bstream_item_type, obs::Obj_iterator&) (backup_info.cc:965)
==8209==    by 0x86B58C6: Backup_info::add_db_items(backup::Image_info::Db&) (backup_info.cc:1114)
==8209==    by 0x86B5FB4: Backup_info::add_dbs(THD*, List<st_mysql_lex_string>&) (backup_info.cc:842)
==8209==    by 0x869E62B: execute_backup_command(THD*, LEX*, String*, bool, bool) (kernel.cc:242)
==8209==    by 0x828E030: mysql_execute_command(THD*) (sql_parse.cc:2455)
==8209==    by 0x82959B1: mysql_parse(THD*, char const*, unsigned, char const**) (sql_parse.cc:5879)
==8209==    by 0x8296420: dispatch_command(enum_server_command, THD*, char*, unsigned) (sql_parse.cc:1071)
==8209==    by 0x82976A7: do_command(THD*) (sql_parse.cc:755)
==8209==    by 0x82859B3: handle_one_connection (sql_connect.cc:1163)
==8209==    by 0x402CF3A: start_thread (pthread_create.c:297)
==8209==    by 0x417DBED: clone (in /usr/lib/debug/libc-2.7.so)
[12 Jan 2010 16:58] Rafal Somla
REFINED PROBLEM DESCRIPTION
---------------------------

Si_objects function obs::find_table_for_trigger() returns a pointer to an obs::Obj instance which should be freed by the caller of this function. However, in function Backup_info::add_db_object() the instance returned by obs::find_table_for_trigger() is not freed (backup_info.cc:1383) leading to memory leak.

I don't know why valgrind detects this only when server is shut down and restarted.
[12 Jan 2010 17:54] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/96655

3056 Rafal Somla	2010-01-12
      Bug #50225 - rpl_backup_shutdown reveals memory issue in backup code
      
      Ensure that object returned by obs::find_table_for_trigger() is always deleted.
     @ sql/backup/backup_info.cc
        Delete tbl_obj instance returned by obs::find_table_for_trigger().
     @ sql/si_objects.cc
        Add note that object returned by find_table_for_trigger() must be deleted by caller.
[12 Jan 2010 19:25] Chuck Bell
Approved
[13 Jan 2010 13:39] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/96766

3061 Rafal Somla	2010-01-13
      Bug #50225 - rpl_backup_shutdown reveals memory issue in backup code
      
      Ensure that object returned by obs::find_table_for_trigger() is always deleted.
     @ sql/backup/backup_info.cc
        Delete tbl_obj instance returned by obs::find_table_for_trigger().
     @ sql/si_objects.cc
        Add note that object returned by find_table_for_trigger() must be deleted by caller.
[14 Jan 2010 7:26] Rafal Somla
Queued into mysql-backup-backport tree.
revision-id:rafal.somla@sun.com-20100113133815-ab8mwj09uzwovef4