| Bug #46656 | InnoDB plugin: memory leaks (Valgrind) | ||
|---|---|---|---|
| Submitted: | 11 Aug 18:13 | Modified: | 2 Nov 10:44 |
| Reporter: | Guilhem Bichot | ||
| Status: | Patch approved | ||
| Category: | Server: InnoDB Plugin | Severity: | S3 (Non-critical) |
| Version: | 5.1 | OS: | Linux (64bit) |
| Assigned to: | Marko Mäkelä | Target Version: | 5.1+ |
| Tags: | experimental, test failure, pb2 | ||
| Triage: | Triaged: D2 (Serious) | ||
[11 Aug 19:35]
Guilhem Bichot
here are more detailed stack traces when plugin is made a builtin: for (1): ==32736== 16 bytes in 1 blocks are still reachable in loss record 1 of 9 ==32736== at 0x4C266E1: realloc (vg_replace_malloc.c:429) ==32736== by 0x9847CB: ut_realloc (ut0mem.c:365) ==32736== by 0x9D12DD: string_append (pars0lex.l:75) ==32736== by 0x9D163D: yylex (pars0lex.l:134) ==32736== by 0x9CE01E: yyparse (pars0grm.c:1563) ==32736== by 0x9CAD59: pars_sql (pars0pars.c:1873) ==32736== by 0x94792A: que_eval_sql (que0que.c:1408) ==32736== by 0x9594E9: row_drop_table_for_mysql (row0mysql.c:3219) ==32736== by 0x91480C: ha_innobase::delete_table(char const*) (ha_innodb.cc:6505) ==32736== by 0x7E0F12: handler::ha_delete_table(char const*) (handler.cc:3316) ==32736== by 0x7E6C67: ha_delete_table(THD*, handlerton*, char const*, char const*, char const*, bool) (handler.cc:1959) ==32736== by 0x80A8B5: mysql_rm_table_part2(THD*, TABLE_LIST*, bool, bool, bool, bool) (sql_table.cc:1956) ==32736== by 0x80AE1D: mysql_rm_table(THD*, TABLE_LIST*, char, char) (sql_table.cc:1749) ==32736== by 0x6AFB8E: mysql_execute_command(THD*) (sql_parse.cc:3416) ==32736== by 0x6B524E: mysql_parse(THD*, char const*, unsigned, char const**) (sql_parse.cc:6003) ==32736== by 0x6B6008: dispatch_command(enum_server_command, THD*, char*, unsigned) (sql_parse.cc:1222) for (2): ==32736== 4,272,931 bytes in 28 blocks are still reachable in loss record 8 of 9 ==32736== at 0x4C265AE: malloc (vg_replace_malloc.c:207) ==32736== by 0x984311: ut_malloc_low (ut0mem.c:106) ==32736== by 0x9845A9: ut_malloc (ut0mem.c:244) ==32736== by 0x92F339: mem_pool_create (mem0pool.c:213) ==32736== by 0x92E614: mem_init (mem0dbg.c:171) ==32736== by 0x968F73: srv_general_init (srv0srv.c:1037) ==32736== by 0x9696A7: srv_boot (srv0srv.c:1366) ==32736== by 0x96DAB5: innobase_start_or_create_for_mysql (srv0start.c:1254) ==32736== by 0x910445: _ZL13innobase_initPv (ha_innodb.cc:2217) ==32736== by 0x7E4CDE: ha_initialize_handlerton(st_plugin_int*) (handler.cc:433) ==32736== by 0x89FB5F: _ZL17plugin_initializeP13st_plugin_int (sql_plugin.cc:1014) ==32736== by 0x8A37B6: plugin_init(int*, char**, int) (sql_plugin.cc:1238) ==32736== by 0x69D92C: _ZL22init_server_componentsv (mysqld.cc:3961) ==32736== by 0x69E3CB: main (mysqld.cc:4433) ==32736== ==32736== ==32736== 5,630,312 bytes in 130 blocks are still reachable in loss record 9 of 9 ==32736== at 0x4C265AE: malloc (vg_replace_malloc.c:207) ==32736== by 0x92FB9D: mem_area_alloc (mem0pool.c:357) ==32736== by 0x92EEB8: mem_heap_create_block (mem0mem.c:333) ==32736== by 0x92E289: mem_heap_create_func (mem0mem.ic:443) ==32736== by 0x92E3E8: mem_alloc_func (mem0mem.ic:529) ==32736== by 0x9C80AA: hash0_create (hash0hash.c:107) ==32736== by 0x97134A: thr_local_init (thr0loc.c:245) ==32736== by 0x968F78: srv_general_init (srv0srv.c:1038) ==32736== by 0x9696A7: srv_boot (srv0srv.c:1366) ==32736== by 0x96DAB5: innobase_start_or_create_for_mysql (srv0start.c:1254) ==32736== by 0x910445: _ZL13innobase_initPv (ha_innodb.cc:2217) ==32736== by 0x7E4CDE: ha_initialize_handlerton(st_plugin_int*) (handler.cc:433) ==32736== by 0x89FB5F: _ZL17plugin_initializeP13st_plugin_int (sql_plugin.cc:1014) ==32736== by 0x8A37B6: plugin_init(int*, char**, int) (sql_plugin.cc:1238) ==32736== by 0x69D92C: _ZL22init_server_componentsv (mysqld.cc:3961) ==32736== by 0x69E3CB: main (mysqld.cc:4433)
[12 Aug 14:24]
Guilhem Bichot
now that 5.1-innodb_plugin has been merged into 5.1-main, bug can very likely be reproduced with the latest 5.1-main tree, available at https://code.launchpad.net/~mysql/mysql-server/mysql-5.1
[13 Aug 15:23]
Guilhem Bichot
Hello Marko, thanks for your comments. What about the first leak, which happens when dropping a table: if we drop many tables, can be have a leak for each of them (would be serious) ? It sounds different from other leaks where we allocate a big chunk at startup and forget to free it at shutdown (which, though it annoys our Valgrind test suite runs, isn't technically a risk).
[13 Aug 15:31]
Marko Mäkelä
Is there any other leak when dropping a table than the stringbuf in pars0lex.l? The stringbuf is just a one-time thing that should be released on shutdown. (The InnoDB internal SQL parser is not reentrant.)
[13 Aug 15:59]
Guilhem Bichot
No, the 16-byte leak in pars_sql is all that seems to happen at DROP TABLE. And I changed the test so that it repeats all its operations, and I didn't observe a bigger leak. So it looks one-time indeed (good). Still it makes our Valgrind runs red... wonder how to tackle this... Hopefully it's possible to add explicit free-ing at shutdown in InnoDB?
[25 Sep 11:22]
Alexander Nozdrin
rpl.rpl_trigger has been marked experimental (in mysql-trunk) due to this bug.
[5 Oct 1:29]
Luís Soares
See also: BUG#47810.
[5 Oct 10:38]
Georgi Kodinov
Bug #47810 duplicate of this one
Description: We can see this kind of memory leak reports in pushbuild2 for 5.1-innodb_plugin: rpl.rpl_trigger 'InnoDB plugin' w1 [ retry-fail ] Found warnings/errors in server log file! Test ended at 2009-08-04 12:25:42 mysqltest: Logging to ''. mysqltest: Results saved in ''. mysqltest: Connecting to server localhost:13120 (socket /export/home/pb2/test/sb_1-671695-1249375950.81/tmp/8PvXC7QAbf/1/mysqld.1.sock) as 'root', connection 'default', attempt 0 ... mysqltest: ... Connected. mysqltest: Start processing test commands from './include/check-warnings.test' ... file_name line /export/home/pb2/test/sb_1-671695-1249375950.81/mysql-5.1.37-linux-x86_64-test/mysql-test/var/1/log/mysqld.1.err ==28039== at 0x4A04B32: calloc (vg_replace_malloc.c:279) /export/home/pb2/test/sb_1-671695-1249375950.81/mysql-5.1.37-linux-x86_64-test/mysql-test/var/1/log/mysqld.1.err ==28039== at 0x4A05809: malloc (vg_replace_malloc.c:149) /export/home/pb2/test/sb_1-671695-1249375950.81/mysql-5.1.37-linux-x86_64-test/mysql-test/var/1/log/mysqld.1.err ==28039== at 0x4A05809: malloc (vg_replace_malloc.c:149) /export/home/pb2/test/sb_1-671695-1249375950.81/mysql-5.1.37-linux-x86_64-test/mysql-test/var/1/log/mysqld.1.err ==28039== at 0x4A05809: malloc (vg_replace_malloc.c:149) /export/home/pb2/test/sb_1-671695-1249375950.81/mysql-5.1.37-linux-x86_64-test/mysql-test/var/1/log/mysqld.1.err ==28039== at 0x4A05809: malloc (vg_replace_malloc.c:149) /export/home/pb2/test/sb_1-671695-1249375950.81/mysql-5.1.37-linux-x86_64-test/mysql-test/var/1/log/mysqld.1.err ==28039== at 0x4A05809: malloc (vg_replace_malloc.c:149) /export/home/pb2/test/sb_1-671695-1249375950.81/mysql-5.1.37-linux-x86_64-test/mysql-test/var/1/log/mysqld.1.err ==28039== at 0x4A05809: malloc (vg_replace_malloc.c:149) /export/home/pb2/test/sb_1-671695-1249375950.81/mysql-5.1.37-linux-x86_64-test/mysql-test/var/1/log/mysqld.1.err ==28039== at 0x4A05809: malloc (vg_replace_malloc.c:149) ^ Found warnings!! Similar ones are also seen in mysql-trunk. More stack traces in "How to repeat". How to repeat: Add this line to the end of mysql-test/t/innodb-semi-consistent.test: --source include/restart_mysqld.inc This is needed because leaks are reported only at mysqld shutdown, and mtr does not do a proper shutdown when it ends a test (it seems to kill-9), so to get a non-abrupt shutdown, we need to put the shutdown before the test returns control to mtr (see BUG#43418). Then run it with: ./mtr --valgrind --valgrind-option=--show-reachable=yes --valgrind-option=--error-limit=no --mem --force --retry-failure=0 innodb-semi-consistent Only when the test is run in "innodb plugin" mode, var/log/*err contains: 1) a leak due to DROP TABLE: ==27005== 16 bytes in 1 blocks are definitely lost in loss record 1 of 16 ==27005== at 0x4C266E1: realloc (vg_replace_malloc.c:429) ==27005== by 0x6D9DF61: ??? ==27005== by 0x6D523C1: ??? ==27005== by 0x6D527A3: ??? ==27005== by 0x6D543F0: ??? ==27005== by 0x6D5A21C: ??? ==27005== by 0x6D5D047: ??? ==27005== by 0x6D6F5FA: ??? ==27005== by 0x6D1EDE7: ??? ==27005== by 0x7FEC22: handler::ha_delete_table(char const*) (handler.cc:3315) ==27005== by 0x804977: ha_delete_table(THD*, handlerton*, char const*, char const*, char const*, bool) (handler.cc:1958) ==27005== by 0x8285C5: mysql_rm_table_part2(THD*, TABLE_LIST*, bool, bool, bool, bool) (sql_table.cc:1956) ==27005== by 0x828B2D: mysql_rm_table(THD*, TABLE_LIST*, char, char) (sql_table.cc:1749) ==27005== by 0x6CD887: mysql_execute_command(THD*) (sql_parse.cc:3353) ==27005== by 0x6D2F47: mysql_parse(THD*, char const*, unsigned, char const**) (sql_parse.cc:5932) ==27005== by 0x6D3CFE: dispatch_command(enum_server_command, THD*, char*, unsigned) (sql_parse.cc:1213) 2) several leaks of memory initialized by InnoDB when it starts, like (but not only): ==27005== 201,675 (1,992 direct, 199,683 indirect) bytes in 8 blocks are definitely lost in loss record 10 of 16 ==27005== at 0x4C265AE: malloc (vg_replace_malloc.c:207) ==27005== by 0x6D9DA5F: ??? ==27005== by 0x6D9DD1E: ??? ==27005== by 0x6D3B1EB: ??? ==27005== by 0x6D3A477: ??? ==27005== by 0x6D813DE: ??? ==27005== by 0x6D81B4A: ??? ==27005== by 0x6D863D9: ??? ==27005== by 0x6D1A802: ??? ==27005== by 0x8029EE: ha_initialize_handlerton(st_plugin_int*) (handler.cc:432) ==27005== by 0x8BD86F: _ZL17plugin_initializeP13st_plugin_int (sql_plugin.cc:1014) ==27005== by 0x8C14C6: plugin_init(int*, char**, int) (sql_plugin.cc:1238) ==27005== by 0x6BB6B0: _ZL22init_server_componentsv (mysqld.cc:3883) ==27005== by 0x6BC14F: main (mysqld.cc:4355) Don't be afraid of the ??? in stack traces, this is likely due to using a .so file. The stack traces in (2) don't mention innodb, but as this is happening only in "innodb plugin" mode, it can only be the innodb plugin's fault.