Bug #47808 innodb_information_schema.test fails when run under valgrind
Submitted: 4 Oct 2009 10:04 Modified: 19 Jun 2010 0:20
Reporter: Georgi Kodinov Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S3 (Non-critical)
Version:5.1+ OS:Linux (Fedora Core 11/x86_64)
Assigned to: Satya B CPU Architecture:Any
Triage: Triaged: D3 (Medium)

[4 Oct 2009 10:04] Georgi Kodinov
Description:
Innodb_information_schema.test fails for innodb plugin when run under valgrind as follows :
innodb.innodb_information_schema 'InnoDB plugin' w8 [ fail ]
        Test ended at 2009-10-02 23:50:30

CURRENT_TEST: innodb.innodb_information_schema
==30753== Memcheck, a memory error detector.
==30753== Copyright (C) 2002-2006, and GNU GPL'd, by Julian Seward et al.
==30753== Using LibVEX rev 1658, a library for dynamic binary translation.
==30753== Copyright (C) 2004-2006, and GNU GPL'd, by OpenWorks LLP.
==30753== Using valgrind-3.2.1, a dynamic binary instrumentation framework.
==30753== Copyright (C) 2000-2006, and GNU GPL'd, by Julian Seward et al.
==30753== For more details, rerun with: -v
==30753== 
--- /export/home/pb2/test/sb_1-787728-1254519012.52/mysql-5.1.40-linux-x86_64-test/mysql-test/suite/innodb/r/innodb_information_schema.result	2009-10-02 16:42:34.000000000 +0300
+++ /export/home/pb2/test/sb_1-787728-1254519012.52/mysql-5.1.40-linux-x86_64-test/mysql-test/suite/innodb/r/innodb_information_schema.reject	2009-10-03 00:50:29.000000000 +0300
@@ -1,18 +1,8 @@
 lock_mode	lock_type	lock_table	lock_index	lock_rec	lock_data
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	2	'1', 'abc', '''abc', 'abc''', 'a''bc', 'a''bc''', '''abc'''''
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	2	'1', 'abc', '''abc', 'abc''', 'a''bc', 'a''bc''', '''abc'''''
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	3	'2', 'abc', '"abc', 'abc"', 'a"bc', 'a"bc"', '"abc""'
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	3	'2', 'abc', '"abc', 'abc"', 'a"bc', 'a"bc"', '"abc""'
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	4	'3', 'abc', '\\abc', 'abc\\', 'a\\bc', 'a\\bc\\', '\\abc\\\\'
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	4	'3', 'abc', '\\abc', 'abc\\', 'a\\bc', 'a\\bc\\', '\\abc\\\\'
 X	RECORD	`test`.```t'\"_str`	`PRIMARY`	5	'4', 'abc', '\0abc', 'abc\0', 'a\0bc', 'a\0bc\0', 'a\0bc\0\0'
 X	RECORD	`test`.```t'\"_str`	`PRIMARY`	5	'4', 'abc', '\0abc', 'abc\0', 'a\0bc', 'a\0bc\0', 'a\0bc\0\0'
 X	RECORD	`test`.`t_min`	`PRIMARY`	2	-128, 0, -32768, 0, -8388608, 0, -2147483648, 0, -9223372036854775808, 0
 X	RECORD	`test`.`t_min`	`PRIMARY`	2	-128, 0, -32768, 0, -8388608, 0, -2147483648, 0, -9223372036854775808, 0
-X	RECORD	`test`.`t_max`	`PRIMARY`	2	127, 255, 32767, 65535, 8388607, 16777215, 2147483647, 4294967295, 9223372036854775807, 18446744073709551615
-X	RECORD	`test`.`t_max`	`PRIMARY`	2	127, 255, 32767, 65535, 8388607, 16777215, 2147483647, 4294967295, 9223372036854775807, 18446744073709551615
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	1	supremum pseudo-record
-X	RECORD	`test`.```t'\"_str`	`PRIMARY`	1	supremum pseudo-record
 lock_table	COUNT(*)
 `test`.`t_max`	2
 `test`.`t_min`	2

mysqltest: Result content mismatch

==30753== 
==30753== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 4 from 1)
==30753== malloc/free: in use at exit: 344 bytes in 10 blocks.
==30753== malloc/free: 1,055 allocs, 1,045 frees, 518,825 bytes allocated.
==30753== For counts of detected errors, rerun with: -v
==30753== searching for pointers to 10 not-freed blocks.
==30753== checked 2,294,848 bytes.
==30753== 
==30753== 32 bytes in 1 blocks are still reachable in loss record 1 of 3
==30753==    at 0x4A0590B: realloc (vg_replace_malloc.c:306)
==30753==    by 0x4661B4: my_realloc (my_realloc.c:62)
==30753==    by 0x46D0B5: dynstr_append_mem (string.c:106)
==30753==    by 0x452F58: do_eval(st_dynamic_string*, char const*, char const*, char) (mysqltest.cc:798)
==30753==    by 0x453851: check_command_args(st_command*, char const*, command_arg const*, int, char) (mysqltest.cc:996)
==30753==    by 0x45659C: do_close_connection(st_command*) (mysqltest.cc:4645)
==30753==    by 0x458B2F: main (mysqltest.cc:7740)
{
   <insert a suppression name here>
   Memcheck:Leak
   fun:_vgrZU_libcZdsoZa_realloc
   fun:my_realloc
   fun:dynstr_append_mem
   fun:_Z7do_evalP17st_dynamic_stringPKcS2_c
   fun:_Z18check_command_argsP10st_commandPKcPK11command_argic
   fun:_Z19do_close_connectionP10st_command
   fun:main
}
==30753== 
==30753== 
==30753== 256 bytes in 8 blocks are definitely lost in loss record 3 of 3
==30753==    at 0x4A0590B: realloc (vg_replace_malloc.c:306)
==30753==    by 0x4661B4: my_realloc (my_realloc.c:62)
==30753==    by 0x46D0B5: dynstr_append_mem (string.c:106)
==30753==    by 0x452F58: do_eval(st_dynamic_string*, char const*, char const*, char) (mysqltest.cc:798)
==30753==    by 0x453851: check_command_args(st_command*, char const*, command_arg const*, int, char) (mysqltest.cc:996)
==30753==    by 0x45659C: do_close_connection(st_command*) (mysqltest.cc:4645)
==30753==    by 0x458B2F: main (mysqltest.cc:7740)
{
   <insert a suppression name here>
   Memcheck:Leak
   fun:_vgrZU_libcZdsoZa_realloc
   fun:my_realloc
   fun:dynstr_append_mem
   fun:_Z7do_evalP17st_dynamic_stringPKcS2_c
   fun:_Z18check_command_argsP10st_commandPKcPK11command_argic
   fun:_Z19do_close_connectionP10st_command
   fun:main
}
==30753== 
==30753== LEAK SUMMARY:
==30753==    definitely lost: 256 bytes in 8 blocks.
==30753==      possibly lost: 0 bytes in 0 blocks.
==30753==    still reachable: 32 bytes in 1 blocks.
==30753==         suppressed: 56 bytes in 1 blocks.

How to repeat:
Compile with valgrind and run
./mysql-test-run --valgrind innodb_information_schema.test

Suggested fix:
"cure" the valgrind warnings
[4 Oct 2009 10:16] 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/85664

3150 Georgi Kodinov	2009-10-04
      Disable innodb_information_schema.test until bug #47808 is fixed.
[5 Oct 2009 15:43] Vasil Dimov
This could be the reason for the failure:

innodb_information_schema.test:

112 # Give time to the above 2 queries to execute before continuing.
113 # Without this sleep it sometimes happens that the SELECT from innodb_locks
114 # executes before some of them, resulting in less than expected number
115 # of rows being selected from innodb_locks.
116 -- sleep 0.1

Georgi, can you change the above to e.g. sleep 5 and see if the test passes?

Thanks!
[6 Oct 2009 6:43] Vasil Dimov
I confirm that the sleep 0.1 is the reason for the failure, changing it to sleep 20 results in no missing rows, which of course is not a solution to the problem with the timing.
[6 Oct 2009 7:03] Sergey Vojtovich
Sleep is extremely fragile for the purpose of waiting for a condition. Some of the "wait" scripts should work here, see mysql-test/include/wait_*.inc
[6 Oct 2009 9:00] Bugs System
Pushed into 5.1.40 (revid:joro@sun.com-20091006073316-lea2cpijh9r6on7c) (version source revid:joro@sun.com-20091004101553-vwri4yqps0nisb8y) (merge vers: 5.1.40) (pib:11)
[19 Oct 2009 12:56] Vasil Dimov
Patch to fix this bug

Attachment: innodb_information_schema.test.diff (application/octet-stream, text), 1.21 KiB.

[19 Oct 2009 13:01] Vasil Dimov
Here is a patch to fix this bug:

http://bugs.mysql.com/file.php?id=13144

The patch uses the wait macros (thanks, Sergey!)

I confirm that without this patch I get the error reported here and after applying the patch the error is gone.

Btw there are some unrelated to this bug warnings produced:

./mysql-test-run --valgrind innodb_information_schema
Logging: ./mysql-test-run  --valgrind innodb_information_schema
MySQL Version 5.1.41
Turning on valgrind for all executables
Running valgrind with options " --show-reachable=yes "
Checking supported features...
 - skipping ndbcluster, mysqld not compiled with ndbcluster
 - skipping SSL, mysqld not compiled with SSL
Using "../libtool" when running valgrind or debugger
Collecting tests...
vardir: /tmp/mysql-5.1-checkout-lightweight/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/tmp/mysql-5.1-checkout-lightweight/mysql-test/var'...
Installing system database...
Using server port 42897

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
innodb.innodb_information_schema         [ skipped ]  Test requires: 'true'
innodb.innodb_information_schema 'InnoDB plugin' [ fail ]  Found warnings/errors in server log file!
        Test ended at 2009-10-19 05:54:25
mysqltest: Logging to ''.
mysqltest: Results saved in ''.
mysqltest: Connecting to server localhost:13000 (socket /tmp/mysql-5.1-checkout-lightweight/mysql-test/var/tmp/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-warnings.test' ...
file_name	line
/tmp/mysql-5.1-checkout-lightweight/mysql-test/var/log/mysqld.1.err	==7298==    at 0x5A04E2D: rw_lock_x_lock_func (in /tmp/mysql-5.1-checkout-lightweight/storage/innodb_plugin/.libs/ha_innodb_plugin.so.0.0.0)
/tmp/mysql-5.1-checkout-lightweight/mysql-test/var/log/mysqld.1.err	==7298==    at 0x5A04E2D: rw_lock_x_lock_func (in /tmp/mysql-5.1-checkout-lightweight/storage/innodb_plugin/.libs/ha_innodb_plugin.so.0.0.0)
/tmp/mysql-5.1-checkout-lightweight/mysql-test/var/log/mysqld.1.err	==7298==    at 0x5A04FA8: rw_lock_x_lock_func (in /tmp/mysql-5.1-checkout-lightweight/storage/innodb_plugin/.libs/ha_innodb_plugin.so.0.0.0)
/tmp/mysql-5.1-checkout-lightweight/mysql-test/var/log/mysqld.1.err	==7298==    at 0x5A04FA8: rw_lock_x_lock_func (in /tmp/mysql-5.1-checkout-lightweight/storage/innodb_plugin/.libs/ha_innodb_plugin.so.0.0.0)
...
/tmp/mysql-5.1-checkout-lightweight/mysql-test/var/log/mysqld.1.err	==7298==    at 0x5A04E2D: rw_lock_x_lock_func (in /tmp/mysql-5.1-checkout-lightweight/storage/innodb_plugin/.libs/ha_innodb_plugin.so.0.0.0)
^ Found warnings!!
mysqltest: ... Done processing test commands.
mysqltest: Test has succeeded!
ok

 - saving '/tmp/mysql-5.1-checkout-lightweight/mysql-test/var/log/innodb.innodb_information_schema-InnoDB plugin/' to '/tmp/mysql-5.1-checkout-lightweight/mysql-test/var/log/innodb.innodb_information_schema-InnoDB plugin/'
------------------------------------------------------------
The servers were restarted 1 times
Spent 0.000 of 25 seconds executing testcases
mysql-test-run: WARNING: Got errors/warnings while running tests, please examine '/tmp/mysql-5.1-checkout-lightweight/mysql-test/var/log/warnings' for details.

Failed 1/1 tests, 0.00% were successful.

Failing test(s): innodb.innodb_information_schema

The log files in var/log may give you some hint of what went wrong.
[22 Oct 2009 6:35] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091022063126-l0qzirh9xyhp0bpc) (version source revid:alik@sun.com-20091019135554-s1pvptt6i750lfhv) (merge vers: 6.0.14-alpha) (pib:13)
[22 Oct 2009 7:07] Bugs System
Pushed into 5.5.0-beta (revid:alik@sun.com-20091022060553-znkmxm0g0gm6ckvw) (version source revid:alik@sun.com-20091013094238-g67x6tgdm9a7uik0) (merge vers: 5.5.0-beta) (pib:13)
[4 Nov 2009 9:25] Bugs System
Pushed into 5.1.41 (revid:joro@sun.com-20091104092152-qz96bzlf2o1japwc) (version source revid:kristofer.pettersson@sun.com-20091103162305-08l4gkeuif2ozsoj) (merge vers: 5.1.41) (pib:13)
[11 Nov 2009 6:50] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091110093407-rw5g8dys2baqkt67) (version source revid:alik@sun.com-20091109080109-7dxapd5y5pxlu08w) (merge vers: 6.0.14-alpha) (pib:13)
[11 Nov 2009 6:58] Bugs System
Pushed into 5.5.0-beta (revid:alik@sun.com-20091109115615-nuohp02h8mdrz8m2) (version source revid:svoj@sun.com-20091105122958-jyqjx9xus8v4e0yd) (merge vers: 5.5.0-beta) (pib:13)
[22 Nov 2009 0:27] Paul Dubois
Changes to test case. No changelog entry needed.
[18 Dec 2009 10:33] Bugs System
Pushed into 5.1.41-ndb-7.1.0 (revid:jonas@mysql.com-20091218102229-64tk47xonu3dv6r6) (version source revid:jonas@mysql.com-20091218095730-26gwjidfsdw45dto) (merge vers: 5.1.41-ndb-7.1.0) (pib:15)
[18 Dec 2009 10:49] Bugs System
Pushed into 5.1.41-ndb-6.2.19 (revid:jonas@mysql.com-20091218100224-vtzr0fahhsuhjsmt) (version source revid:jonas@mysql.com-20091217101452-qwzyaig50w74xmye) (merge vers: 5.1.41-ndb-6.2.19) (pib:15)
[18 Dec 2009 11:04] Bugs System
Pushed into 5.1.41-ndb-6.3.31 (revid:jonas@mysql.com-20091218100616-75d9tek96o6ob6k0) (version source revid:jonas@mysql.com-20091217154335-290no45qdins5bwo) (merge vers: 5.1.41-ndb-6.3.31) (pib:15)
[18 Dec 2009 11:18] Bugs System
Pushed into 5.1.41-ndb-7.0.11 (revid:jonas@mysql.com-20091218101303-ga32mrnr15jsa606) (version source revid:jonas@mysql.com-20091218064304-ezreonykd9f4kelk) (merge vers: 5.1.41-ndb-7.0.11) (pib:15)
[5 May 2010 15:16] Bugs System
Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[6 May 2010 17:17] Paul Dubois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.
[28 May 2010 6:02] 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:31] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[28 May 2010 6:59] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[30 May 2010 0:17] Paul Dubois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.
[15 Jun 2010 8:15] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)
[15 Jun 2010 8:32] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)
[17 Jun 2010 12:06] 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:51] 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:33] 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)