MySQL Bugs: #47873: innodb.innodb-timeout fails under valgrind

Bug #47873	innodb.innodb-timeout fails under valgrind
Submitted:	6 Oct 2009 19:25	Modified:	6 Sep 2010 9:14
Reporter:	Sveta Smirnova	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	mysql-trunk, mysql-next-mr	OS:	Any
Assigned to:	Satya B	CPU Architecture:	Any

Description:
innodb.innodb-timeout fails under valgrind with:

/users/ssmirnova/blade12/src/mysql-trunk/mysql-test/var/log/mysqld.1.err        ==2224==    at 0x96D88D: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)
/users/ssmirnova/blade12/src/mysql-trunk/mysql-test/var/log/mysqld.1.err        ==2224==    at 0x96D88D: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)
/users/ssmirnova/blade12/src/mysql-trunk/mysql-test/var/log/mysqld.1.err        ==2224==    at 0x9328A5: os_thread_eq (os0thread.c:56)
/users/ssmirnova/blade12/src/mysql-trunk/mysql-test/var/log/mysqld.1.err        ==2224==    at 0x96D88D: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)
/users/ssmirnova/blade12/src/mysql-trunk/mysql-test/var/log/mysqld.1.err        ==2224==    at 0x96D88D: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)

==2224== Conditional jump or move depends on uninitialised value(s)
==2224==    at 0x96D88D: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)
==2224==    by 0x96E321: rw_lock_x_lock_low (sync0rw.c:558)
==2224==    by 0x96E407: rw_lock_x_lock_func (sync0rw.c:617)
==2224==    by 0x92D774: mtr_x_lock_func (mtr0mtr.ic:268)
==2224==    by 0x9C0430: fsp_header_init (fsp0fsp.c:971)
==2224==    by 0x96BF4F: innobase_start_or_create_for_mysql (srv0start.c:1528)
==2224==    by 0x90511F: innobase_init(void*) (ha_innodb.cc:2217)
==2224==    by 0x7C74D5: ha_initialize_handlerton(st_plugin_int*) (handler.cc:436)
==2224==    by 0x8902CD: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1014)
==2224==    by 0x890B84: plugin_init(int*, char**, int) (sql_plugin.cc:1238)
==2224==    by 0x679C7B: init_server_components() (mysqld.cc:3978)
==2224==    by 0x67A74A: main (mysqld.cc:4449)
==2224==
==2224==
==2224== Conditional jump or move depends on uninitialised value(s)
==2224==    at 0x96D88D: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)
==2224==    by 0x96E321: rw_lock_x_lock_low (sync0rw.c:558)
==2224==    by 0x96E407: rw_lock_x_lock_func (sync0rw.c:617)
==2224==    by 0x9239B3: log_group_checkpoint (log0log.c:1830)
==2224==    by 0x923AFE: log_groups_write_checkpoint_info (log0log.c:1940)
==2224==    by 0x923C79: log_checkpoint (log0log.c:2027)
==2224==    by 0x9217A1: log_fsp_current_free_limit_set_and_checkpoint (log0log.c:194)
==2224==    by 0x9C10E3: fsp_fill_free_list (fsp0fsp.c:1390)
==2224==    by 0x9C06D9: fsp_header_init (fsp0fsp.c:1005)
==2224==    by 0x96BF4F: innobase_start_or_create_for_mysql (srv0start.c:1528)
==2224==    by 0x90511F: innobase_init(void*) (ha_innodb.cc:2217)
==2224==    by 0x7C74D5: ha_initialize_handlerton(st_plugin_int*) (handler.cc:436)
==2224==    by 0x8902CD: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1014)
==2224==    by 0x890B84: plugin_init(int*, char**, int) (sql_plugin.cc:1238)
==2224==    by 0x679C7B: init_server_components() (mysqld.cc:3978)
==2224==    by 0x67A74A: main (mysqld.cc:4449)
==2224==
==2224== Conditional jump or move depends on uninitialised value(s)
==2224==    at 0x9328A5: os_thread_eq (os0thread.c:56)
==2224==    by 0x96E365: rw_lock_x_lock_low (sync0rw.c:570)
==2224==    by 0x96E407: rw_lock_x_lock_func (sync0rw.c:617)
==2224==    by 0x92D774: mtr_x_lock_func (mtr0mtr.ic:268)
==2224==    by 0x9C27BD: fseg_create_general (fsp0fsp.c:2228)
==2224==    by 0x9C2C05: fseg_create (fsp0fsp.c:2329)
==2224==    by 0x985959: btr_create (btr0btr.c:748)
==2224==    by 0x9C078A: fsp_header_init (fsp0fsp.c:1006)
==2224==    by 0x96BF4F: innobase_start_or_create_for_mysql (srv0start.c:1528)
==2224==    by 0x90511F: innobase_init(void*) (ha_innodb.cc:2217)
==2224==    by 0x7C74D5: ha_initialize_handlerton(st_plugin_int*) (handler.cc:436)
==2224==    by 0x8902CD: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1014)
==2224==    by 0x890B84: plugin_init(int*, char**, int) (sql_plugin.cc:1238)
==2224==    by 0x679C7B: init_server_components() (mysqld.cc:3978)
==2224==    by 0x67A74A: main (mysqld.cc:4449)
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables

How to repeat:
See description

which OS is it?

Linux 64-bit

I think Sunny fixed something similar

I have three things to say about Valgrind errors in InnoDB Plugin.

(1) innodb_use_sys_malloc=0 (the default before InnoDB Plugin) will hide memory leaks, because InnoDB will keep track of the allocated memory in a linked list and free each object on shutdown. Fixing these leaks (Bug #46656, Bug #46657, Bug #45992) requires the introduction of cleanup procedures in various InnoDB subsystems. I would like to fix that in the near future.

(2) When InnoDB uses atomic memory access to implement mutexes and rw-locks, there may be false positives. Please compile the code with -DUNIV_DEBUG_VALGRIND to get rid of those.

(3) I do not think that we have fixed any Valgrind-related stuff in the InnoDB Plugin recently. Thus, unless this bug is a case of (2), it should remain open.

Does UNIV_DEBUG_VALGRIND cure this?

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Marko,

sorry for the delay: was on vacation.

No, UNIV_DEBUG_VALGRIND doesn't cure this.

I defined it in storage/innodb_plugin/include/univ.i:

$bzr diff
=== modified file 'storage/innodb_plugin/include/univ.i'
--- storage/innodb_plugin/include/univ.i        2009-11-03 10:26:39 +0000
+++ storage/innodb_plugin/include/univ.i        2009-11-23 07:02:55 +0000
@@ -165,9 +165,9 @@
 #define UNIV_COMPILE_TEST_FUNCS
 */
 
-#if 0
 #define UNIV_DEBUG_VALGRIND                    /* Enable extra
                                                Valgrind instrumentation */
+#if 0
 #define UNIV_DEBUG_PRINT                       /* Enable the compilation of
                                                some debug print functions */
 #define UNIV_AHI_DEBUG                         /* Enable adaptive hash index

Please let me know if I did it wrong.

Can you repeat this with InnoDB Plugin 1.0.6? It fixes several memory leaks that were reported by Valgrind.

Marko,

I can not repeat the problem with InnoDB Plugin 1.0.6.

I leave status of bug as "Verified", because patch not is in version of plugin bundled with MySQL.

I am assigning this bug away from me, because the fix has been supplied in InnoDB Plugin 1.0.6 and it should eventually be merged to the MySQL 5.1 storage/innodb_plugin tree.

To my understanding, InnoDB Plugin 1.0.6 should have been merged to the MySQL code base a few weeks ago. Can this bug be closed, or is it still repeatable?

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Seems this bug has resurfaced.   Getting it in 
mysql-trunk when running ./mtr --mem --valgrind-mysqld innodb.innodb :

==2684== Conditional jump or move depends on uninitialised value(s)
==2684==    at 0x79F109: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)
==2684==    by 0x79F340: rw_lock_x_lock_low (sync0rw.c:569)
==2684==    by 0x79F590: rw_lock_x_lock_func (sync0rw.c:628)
==2684==    by 0x79F72A: pfs_rw_lock_x_lock_func (sync0rw.ic:692)
==2684==    by 0x7F7C22: log_groups_write_checkpoint_info (log0log.c:1865)
==2684==    by 0x7FB500: recv_recovery_from_checkpoint_start_func (log0recv.c:614)
==2684==    by 0x79DC0C: innobase_start_or_create_for_mysql (srv0start.c:1609)
==2684==    by 0x777508: innobase_init(void*) (ha_innodb.cc:2437)
==2684==    by 0x63BED0: ha_initialize_handlerton(st_plugin_int*) (handler.cc:464)
==2684==    by 0x56A04E: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1037)
==2684==    by 0x56D527: plugin_init(int*, char**, int) (sql_plugin.cc:1323)
==2684==    by 0x50944A: init_server_components() (mysqld.cc:4023)
==2684==    by 0x50C90B: mysqld_main(int, char**) (mysqld.cc:4589)
==2684==    by 0x5928C4C: (below main) (libc-start.c:228)

Also showing up in mysql-5.5 now.  I'm not able to reproduce in mysql-5.1, though.   The build is created by the BUILD/compile-pentium-debug-max-no-ndb script.

==15918== Conditional jump or move depends on uninitialised value(s)
==15918==    at 0x8EF3B1: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)
==15918==    by 0x8F02C4: rw_lock_x_lock_low (sync0rw.c:569)
==15918==    by 0x8F03AA: rw_lock_x_lock_func (sync0rw.c:628)
==15918==    by 0x8EF882: pfs_rw_lock_x_lock_func (sync0rw.ic:692)
==15918==    by 0x963088: log_group_checkpoint (log0log.c:1845)
==15918==    by 0x9631D3: log_groups_write_checkpoint_info (log0log.c:1955)
==15918==    by 0x964B52: recv_synchronize_groups (log0recv.c:613)
==15918==    by 0x967E32: recv_recovery_from_checkpoint_start_func (log0recv.c:3203)
==15918==    by 0x8EDA6A: innobase_start_or_create_for_mysql (srv0start.c:1609)
==15918==    by 0x8B881F: innobase_init(void*) (ha_innodb.cc:2432)
==15918==    by 0x736630: ha_initialize_handlerton(st_plugin_int*) (handler.cc:463)
==15918==    by 0x5E92D1: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1037)
==15918==    by 0x5E9BF4: plugin_init(int*, char**, int) (sql_plugin.cc:1323)
==15918==    by 0x547918: init_server_components() (mysqld.cc:3875)
==15918==    by 0x548596: mysqld_main(int, char**) (mysqld.cc:4441)
==15918==    by 0x541E43: main (main.cc:24)
==15918== Conditional jump or move depends on uninitialised value(s)
==15918==    at 0x8EF3B1: rw_lock_set_writer_id_and_recursion_flag (sync0rw.ic:283)
==15918==    by 0x8F02C4: rw_lock_x_lock_low (sync0rw.c:569)
==15918==    by 0x8F03AA: rw_lock_x_lock_func (sync0rw.c:628)
==15918==    by 0x96D0F4: mtr_x_lock_func (mtr0mtr.ic:271)
==15918==    by 0x94DC42: ibuf_init_at_db_start (ibuf0ibuf.c:538)
==15918==    by 0x92B3F8: dict_boot (dict0boot.c:446)
==15918==    by 0x8EDA84: innobase_start_or_create_for_mysql (srv0start.c:1624)
==15918==    by 0x8B881F: innobase_init(void*) (ha_innodb.cc:2432)
==15918==    by 0x736630: ha_initialize_handlerton(st_plugin_int*) (handler.cc:463)
==15918==    by 0x5E92D1: plugin_initialize(st_plugin_int*) (sql_plugin.cc:1037)
==15918==    by 0x5E9BF4: plugin_init(int*, char**, int) (sql_plugin.cc:1323)
==15918==    by 0x547918: init_server_components() (mysqld.cc:3875)
==15918==    by 0x548596: mysqld_main(int, char**) (mysqld.cc:4441)
==15918==    by 0x541E43: main (main.cc:24)

According to Marco, this is a bogus warning:

"we are doing compare-and-swap using an uninitialized value, or something. we really only need a write there, but are using a compare-and-swap so that the memory bus semantics are clear"

If the server is built with either UNIV_DEBUG_VALGRIND defined, _or_ configured with --with-valgrind (or using one of the -valgrind scripts in BUILD), this warning is silenced.

This is a duplicate of Bug #59307. We are comparing x==x with uninitialized x. As this keeps popping up, I submitted a fix that takes care of this even when InnoDB Valgrind instrumentation is not enabled.