Bug #52629 memory leak from sys_var_thd_dbug in binlog.binlog_write_error
Submitted: 6 Apr 2010 18:54 Modified: 18 Jun 2010 1:50
Reporter: Mark Callaghan Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: General Severity:S3 (Non-critical)
Version:5.1.45, 5.1 bzr OS:Any
Assigned to: Georgi Kodinov CPU Architecture:Any
Tags: binlog_write_error, Leak, mtr, valgrind
Triage: Triaged: D2 (Serious)

[6 Apr 2010 18:54] Mark Callaghan
Description:
./mysql-test-run --valgrind binlog.binlog_write_error reports a memory leak in mysql 5.1.45. This is similar to http://bugs.mysql.com/bug.php?id=34424 but that was fixed.

==31468== 663 bytes in 17 blocks are definitely lost in loss record 2 of 2
==31468==    at 0x4A05809: malloc (vg_replace_malloc.c:149)
==31468==    by 0x7A9378: DbugMalloc (dbug.c:2016)
==31468==    by 0x7AAAB5: ListAdd (dbug.c:1271)
==31468==    by 0x7AB306: DbugParse (dbug.c:522)
==31468==    by 0x7AB498: _db_set_init_ (dbug.c:745)
==31468==    by 0x5B6F78: sys_var_thd_dbug::update(THD*, set_var*) (set_var.cc:4232)
==31468==    by 0x5AA30F: set_var::update(THD*) (set_var.cc:3595)
==31468==    by 0x5B53B8: sql_set_variables(THD*, List<set_var_base>*) (set_var.cc:3470)
==31468==    by 0x5A71E4: mysql_execute_command(THD*) (sql_parse.cc:3478)
==31468==    by 0x5A789F: mysql_parse(THD*, char const*, unsigned, char const**) (sql_parse.cc:5971)
==31468==    by 0x5A8A3E: dispatch_command(enum_server_command, THD*, char*, unsigned) (sql_parse.cc:1233)
==31468==    by 0x5A997B: do_command(THD*) (sql_parse.cc:874)
==31468==    by 0x59945C: handle_one_connection (sql_connect.cc:1127)
==31468==    by 0x328F8062F6: start_thread (in /lib64/libpthread-2.5.so)
==31468==    by 0x328ECD1E3C: clone (in /lib64/libc-2.5.so)

How to repeat:
Use unmodified 5.1.45 source

 ./configure --enable-thread-safe-client --with-plugins=csv,blackhole,myisam,heap,innodb_plugin --without-plugin-innobase --with-fast-mutexes --with-extra-charsets=all --with-debug C_EXTRA_FLAGS="-fno-omit-frame-pointer -DHAVE_purify"

gcc 4.1.2
valgrind-3.2.1
[6 Apr 2010 18:58] Mark Callaghan
the error is also in rpl.rpl_bug26395
[7 Apr 2010 8:04] Sveta Smirnova
Thank you for the report.

I can not repeat described behavior with current development sources. Is it repeatable without Facebook patch in your environment?
[7 Apr 2010 9:09] Daniel Fischer
I can repeat it and it is visible in our test environment with current debug builds from 5.1 sources (the ones specifically built for valgrind, for example). Note that leak reports show up after the test run is complete, they are not associated directly with a test case. The test case itself will be reported as a pass.

Displaying the leak report after test runs is a recent addition in 5.1.45. These leaks are probably older and not a regression in 5.1.45.

It is impossible to associate leaks with individual test cases because (unlike errors) leaks are only reported when the executable exits, and the server is not restarted for every test case. They also don't trigger an error in our test environment yet.
[7 Apr 2010 13:59] Mark Callaghan
This leak is caused by this test. It does 'SET global debug=...' when it runs 'source include/binlog_inject_error.inc' and that uses sys_var_thd_dbug
[7 Apr 2010 14:00] Mark Callaghan
My reproduction uses unmodified 5.1.45
[7 Apr 2010 19:36] Sveta Smirnova
Thank you for the feedback.

Verified as described. Only repeatable with valgrind 3.2.1
[7 Apr 2010 19:37] Sveta Smirnova
Not repeatable with valgrind 3.5
[14 Apr 2010 12:29] Georgi Kodinov
I was able to reproduce in valgrind 3.5.0 using Mark's compilation options on a fresh 5.1-bugteam as follows : 
==5553== 663 bytes in 17 blocks are definitely lost in loss record 2 of 2
==5553==    at 0x4A0515D: malloc (vg_replace_malloc.c:195)
==5553==    by 0x78C4B8: DbugMalloc (dbug.c:2016)
==5553==    by 0x78DBA8: ListAdd (dbug.c:1271)
==5553==    by 0x78E2FE: DbugParse (dbug.c:522)
==5553==    by 0x78E72B: _db_set_init_ (dbug.c:745)
==5553==    by 0x5AF18D: sys_var_thd_dbug::update(THD*, set_var*) (set_var.cc:4243)
==5553==    by 0x5A3865: set_var::update(THD*) (set_var.cc:3606)
==5553==    by 0x5AE4F6: sql_set_variables(THD*, List<set_var_base>*) (set_var.cc:3481)==5553==    by 0x5A08F5: mysql_execute_command(THD*) (sql_parse.cc:3478)
==5553==    by 0x5A0D68: mysql_parse(THD*, char const*, unsigned int, char const**) (sql_parse.cc:5971)  ==5553==    by 0x5A1A0D: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1233)==5553==    by 0x5A28C6: do_command(THD*) (sql_parse.cc:874)
==5553==    by 0x5938B1: handle_one_connection (sql_connect.cc:1127)
==5553==    by 0x3665E06A39: start_thread (in /lib64/libpthread-2.11.1.so)
==5553==    by 0x36656DE65C: clone (in /lib64/libc-2.11.1.so)
[14 Apr 2010 13:19] 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/105644

3452 Georgi Kodinov	2010-04-14
      Bug #52629: memory leak from sys_var_thd_dbug in binlog.binlog_write_error
      
      When setting the GLOBAL debug settings the server was not freeing the 
      data elements from the top (initial) frame before setting them to 0.
      As these are global settings there's a chance that something is there 
      already.
      Fixed by :
      1. making sure the allocated data are cleaned up before re-setting them
      while parsing a debug string
      2. making sure the stuff allocated in the global settings is freed on 
      shutdown.
[16 Apr 2010 7:31] 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/105805

3452 Georgi Kodinov	2010-04-16
      Bug #52629: memory leak from sys_var_thd_dbug in binlog.binlog_write_error
      
      When re-setting (SET GLOBAL debug='') the GLOBAL debug settings the 
      server was not freeing the data elements from the top (initial) frame 
      before setting them to 0 without freeing the underlying memory. As these 
      are global settings there's a chance that something is there already.
      Fixed by :
      1. making sure the allocated data are cleaned up before re-setting them
      while parsing a debug string
      2. making sure the stuff allocated in the global settings is freed on 
      shutdown.
[16 Apr 2010 7:32] 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/105806

3455 Georgi Kodinov	2010-04-16
      Bug #52629: memory leak from sys_var_thd_dbug in binlog.binlog_write_error
      
      When re-setting (SET GLOBAL debug='') the GLOBAL debug settings the 
      server was not freeing the data elements from the top (initial) frame 
      before setting them to 0 without freeing the underlying memory. As these 
      are global settings there's a chance that something is there already.
      Fixed by :
      1. making sure the allocated data are cleaned up before re-setting them
      while parsing a debug string
      2. making sure the stuff allocated in the global settings is freed on 
      shutdown.
[5 May 2010 15:21] Bugs System
Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:kristofer.pettersson@sun.com-20100416145616-vdcdyz9eu7j86lp7) (merge vers: 5.1.47) (pib:16)
[6 May 2010 17:04] Paul Dubois
Noted in 5.1.47 changelog.

Setting @@GLOBAL.debug to an empty string failed to clear the current
debug settings.
[19 May 2010 7:19] Tor Didriksen
This seems to have broken 'mtr --debug' for all test cases, see
Bug #53779  	mtr --debug was broken by bugfix 52629
[28 May 2010 6:00] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)
[28 May 2010 6:29] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:alik@sun.com-20100422150658-fkhgnwwkyugtxrmu) (merge vers: 6.0.14-alpha) (pib:16)
[28 May 2010 6:56] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:alexey.kopytov@sun.com-20100429203306-tg0wz4y2xyx8edrl) (merge vers: 5.5.5-m3) (pib:16)
[29 May 2010 2:37] Paul Dubois
Noted in 5.5.5, 6.0.14 changelogs.
[17 Jun 2010 11:56] Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:35] Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 13:22] Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)