| Bug #48993 | valgrind errors in mysqlbinlog | ||
|---|---|---|---|
| Submitted: | 23 Nov 2009 13:27 | Modified: | 21 Jun 2010 0:49 |
| Reporter: | Shane Bester (Platinum Quality Contributor) | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 5.1.41, 5.1.44-bzr,mysql-5.5.99-m3 | OS: | Linux (32-bit, Mac OS X) |
| Assigned to: | Luis Soares | CPU Architecture: | Any |
| Tags: | valgrind | ||
[23 Nov 2009 13:27]
Shane Bester
[23 Nov 2009 13:27]
MySQL Verification Team
binlog
Attachment: box1-bin.000001 (application/octet-stream, text), 743 bytes.
[23 Nov 2009 13:34]
Valeriy Kravchuk
I was not able to get definite memory leaks with 5.1.42-debug from bzr on Mac OS X, but errors are repeatable: ==92922== ERROR ==92922== ==92922== Conditional jump or move depends on uninitialised value(s) ==92922== at 0x10621: Query_log_event::print_query_header(st_io_cache*, st_print_event_info*)+1099 (in ./bin/mysqlbinlog) ==92922== by 0x10E06: Query_log_event::print(__sFILE*, st_print_event_info*)+88 (in ./bin/mysqlbinlog) ==92922== by 0x17C85: process_event(st_print_event_info*, Log_event*, unsigned long long, char const*)+1131 (in ./bin/mysqlbinlog) ==92922== by 0x1B904: dump_local_log_entries(st_print_event_info*, char const*)+1238 (in ./bin/mysqlbinlog) ==92922== by 0x1C163: dump_log_entries(char const*)+247 (in ./bin/mysqlbinlog) ==92922== by 0x1C49A: main+698 (in ./bin/mysqlbinlog) ==92922== Uninitialised value was created by a stack allocation ==92922== at 0x1C070: dump_log_entries(char const*)+4 (in ./bin/mysqlbinlog) ==92922== IN SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
[21 Jan 2010 10:04]
Daogang Qu
Hi Shane Bester, Which system did you reproduce the bug? I have checked all the Mac OS hosts on PB2, the valgrind was not been install. And danny from engineering team said that they will not install valgrind on these hosts. And the bug can't be reproduced with the build created from the current mysql-5.1-bugteam tree on Ubuntu.
[22 Jan 2010 12:03]
MySQL Verification Team
both problems still repeatable for me using latest 5.1 source.
Attachment: bug48993_full_infos_5.1_bugfix.txt (text/plain), 10.43 KiB.
[25 Jan 2010 8:23]
MySQL Verification Team
mysql-5.5.99-m3 didn't have a memory leak. But it did have the uninitialized value:
1 errors in context 1 of 1:
Conditional jump or move depends on uninitialised value(s)
at: Query_log_event::print_query_header (log_event.cc:2945)
by: Query_log_event::print (log_event.cc:3022)
by: process_event (mysqlbinlog.cc:752)
by: dump_local_log_entries (mysqlbinlog.cc:2005)
by: dump_log_entries) (mysqlbinlog.cc:1452)
by: main (mysqlbinlog.cc:2094)
Uninitialised value was created by a stack allocation
at 0x806836F: dump_log_entries(char const*) (mysqlbinlog.cc:1435)
log_event:2945 is this:
if (likely(sql_mode_inited) &&
(unlikely(print_event_info->sql_mode != sql_mode ||
!print_event_info->sql_mode_inited)))
{
[25 Jan 2010 10:06]
Valeriy Kravchuk
I still can repeat the uninitialized value problem with recent 5.1.44 from bzr: openxs@suse:/home2/openxs/dbs/5.1> valgrind --tool=memcheck --track-origins=yes --leak-check=full --db-attach=no -v --show-reachable=yes bin/mysqlbinlog ~/box1-bin.000001 ==6967== Memcheck, a memory error detector ==6967== Copyright (C) 2002-2009, and GNU GPL'd, by Julian Seward et al. ==6967== Using Valgrind-3.5.0 and LibVEX; rerun with -h for copyright info ==6967== Command: bin/mysqlbinlog /home/openxs/box1-bin.000001 ==6967== --6967-- Valgrind options: --6967-- --tool=memcheck --6967-- --track-origins=yes --6967-- --leak-check=full --6967-- --db-attach=no --6967-- -v --6967-- --show-reachable=yes --6967-- Contents of /proc/version: --6967-- Linux version 2.6.11.4-20a-default (geeko@buildhost) (gcc version 3.3.5 20050117 (prerelease) (SUSE Linux)) #1 Wed Mar 23 21:52:37 UTC 2005 --6967-- Arch and hwcaps: X86, x86-sse1-sse2 --6967-- Page sizes: currently 4096, max supported 4096 --6967-- Valgrind library directory: /usr/local/lib/valgrind --6967-- Reading syms from /lib/ld-2.3.4.so (0x4000000) --6967-- object doesn't have a symbol table --6967-- Reading syms from /home2/openxs/dbs/5.1/bin/mysqlbinlog (0x8048000) --6967-- Reading syms from /usr/local/lib/valgrind/memcheck-x86-linux (0x38000000) --6967-- object doesn't have a dynamic symbol table --6967-- Reading suppressions file: /usr/local/lib/valgrind/default.supp --6967-- Reading syms from /usr/local/lib/valgrind/vgpreload_core-x86-linux.so (0x4018000) --6967-- Reading syms from /usr/local/lib/valgrind/vgpreload_memcheck-x86-linux.so (0x401b000) --6967-- Reading syms from /lib/tls/libpthread.so.0 (0x4035000) --6967-- object doesn't have a symbol table --6967-- Reading syms from /home2/openxs/dbs/5.1/lib/mysql/libmysqlclient.so.16.0.0 (0x4047000) --6967-- Reading syms from /lib/libcrypt.so.1 (0x4260000) --6967-- object doesn't have a symbol table --6967-- Reading syms from /lib/libnsl.so.1 (0x4292000) --6967-- object doesn't have a symbol table --6967-- Reading syms from /lib/tls/libm.so.6 (0x42a7000) --6967-- object doesn't have a symbol table --6967-- Reading syms from /lib/libz.so.1.2.2 (0x42cb000) --6967-- object doesn't have a symbol table --6967-- Reading syms from /lib/tls/libc.so.6 (0x42dc000) --6967-- object doesn't have a symbol table ... ==6967== LEAK SUMMARY: ==6967== definitely lost: 0 bytes in 0 blocks ==6967== indirectly lost: 0 bytes in 0 blocks ==6967== possibly lost: 0 bytes in 0 blocks ==6967== still reachable: 615 bytes in 2 blocks ==6967== suppressed: 0 bytes in 0 blocks ==6967== ==6967== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 23 from 6) ==6967== ==6967== 1 errors in context 1 of 1: ==6967== Conditional jump or move depends on uninitialised value(s) ==6967== at 0x8060436: Query_log_event::print_query_header(st_io_cache*, st_print_event_info*) (log_event.cc:2838) ==6967== by 0x8060791: Query_log_event::print(_IO_FILE*, st_print_event_info*) (log_event.cc:2915) ==6967== by 0x80521C2: process_event(st_print_event_info*, Log_event*, unsigned long long, char const*) (mysqlbinlog.cc:745) ==6967== by 0x80543D5: dump_local_log_entries(st_print_event_info*, char const*) (mysqlbinlog.cc:1989) ==6967== by 0x8052F5D: dump_log_entries(char const*) (mysqlbinlog.cc:1435) ==6967== by 0x805468D: main (mysqlbinlog.cc:2076) ==6967== Uninitialised value was created by a stack allocation ==6967== at 0x8052E84: dump_log_entries(char const*) (mysqlbinlog.cc:1420) ==6967== --6967-- --6967-- used_suppression: 23 Ubuntu-stripped-ld.so ==6967== ==6967== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 23 from 6) openxs@suse:/home2/openxs/dbs/5.1> bin/mysqldump --version mysqldump Ver 10.13 Distrib 5.1.44, for suse-linux (i686)
[17 Feb 2010 11:09]
Luis Soares
I was able to reproduce it, in 5.1, following Shane's instructions. Steps to reproduce it: $ ./BUILD/compile-pentium-debug-max $ valgrind --tool=memcheck --track-origins=yes --leak-check=full --db-attach=no -v --show-reachable=yes ./client/.libs/lt-mysqlbinlog ~/box1-bin.000001
[17 Feb 2010 18:07]
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/100658 3341 Luis Soares 2010-02-17 BUG#48993: valgrind errors in mysqlbinlog I found three issues during the analysis: 1. Memory leak caused by temp_buf not being freed; 2. Memory leak caused when handling argv; 3. Conditional jump that depended on unitialized values. Issue #1 -------- DESCRIPTION: when mysqlbinlog is reading from a remote location the event temp_buf references the incoming stream (in NET object), which is not freed by mysqlbinlog explicitly. On the other hand, when it is reading local binary log, it points to a temporary buffer that needs to be explicitly freed. For both cases, the temp_buf was not freed by mysqlbinlog, instead was set to 0. This clearly disregards the free required in the second case, thence creating a memory leak. FIX: we make temp_buf to be conditionally freed depending on the value of remote_opt. Found out that similar fix is already in most recent codebases. Issue #2 -------- DESCRIPTION: load_defaults is called by parse_args, and it reads default options from configuration files and put them BEFORE the arguments that are already in argc and argv. This is done resorting to MEM_ROOT. However, parse_args calls handle_options immediately after which changes argv. Later when freeing the defaults, pointers to MEM_ROOT won't match, causing the memory not to be freed: void free_defaults(char **argv) { MEM_ROOT ptr memcpy_fixed((char*) &ptr,(char *) argv - sizeof(ptr), sizeof(ptr)); free_root(&ptr,MYF(0)); } FIX: we remove load_defaults from parse_args and call it before. Then we save argv with defaults in defaults_argv BEFORE calling parse_args (which inside can then call handle_options at will). Actually, found out that this is in fact kind of a backport for BUG#38468 into 5.1, so I merged in the test case as well and added error check for load_defaults call. Fix based on: revid:zhenxing.he@sun.com-20091002081840-uv26f0flw4uvo33y Issue #3 -------- DESCRIPTION: the structure st_print_event_info constructor would not initialize the sql_mode member, although it did for sql_mode_inited (set to false). This would later raise the warning in valgrind when printing the sql_mode in the event header, as this print out is protected by a check against sql_mode_inited and sql_mode variables. Given that sql_mode was not initialized valgrind would output the warning. FIX: we add initialization of sql_mode to the st_print_event_info constructor. @ client/mysqlbinlog.cc - Conditionally free ev->temp_buf. - save defaults_argv before handle_options is called. @ mysql-test/t/mysqlbinlog.test Added test case from BUG#38468. @ sql/log_event.cc Added initialization of sql_mode for st_print_event_info.
[23 Feb 2010 15:02]
Andrei Elkin
The patch is approved.
[26 Mar 2010 8:20]
Bugs System
Pushed into 5.5.4-m3 (revid:alik@sun.com-20100326080914-2pz8ns984e0spu03) (version source revid:alexey.kopytov@sun.com-20100312095153-t4rtoqc7p96lmxvh) (merge vers: 5.5.3-m2) (pib:16)
[26 Mar 2010 8:24]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100326081116-m3v4l34yhr43mtsv) (version source revid:alik@sun.com-20100325072612-4sds00ix8ajo1e84) (pib:16)
[26 Mar 2010 8:29]
Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100326081944-qja07qklw1p2w7jb) (version source revid:alik@sun.com-20100325073410-4t4i9gu2u1pge7xb) (merge vers: 6.0.14-alpha) (pib:16)
[29 Mar 2010 12:52]
Jon Stephens
No user-facing changes to document. Closed without further action.
[6 Apr 2010 7:59]
Bugs System
Pushed into 5.1.46 (revid:sergey.glukhov@sun.com-20100405111026-7kz1p8qlzglqgfmu) (version source revid:luis.soares@sun.com-20100308235519-dyijxl1xhf3ln7mv) (merge vers: 5.1.45) (pib:16)
[6 Apr 2010 10:36]
Jon Stephens
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.
If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at
http://dev.mysql.com/doc/en/installing-source.html
[17 Jun 2010 11:50]
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:27]
Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609211156-tsac5qhw951miwtt) (merge vers: 5.1.46-ndb-6.2.19) (pib:16)
[17 Jun 2010 13:15]
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)
