Valgrind: malloc in init_io_cache (my_write/my_b_flush_io_cache)

[Roel Van de Paar]

The surrounding queries are printed. It is highly likely that the query directly after the Valgrind stack (highlighted) is the problem query (the run was single threaded).

2012-11-25T17:29:07 [26618] Query: UPDATE `view_table500_innodb_compressed` t1, `table500_innodb_default` t2 SET t1.`c48` = 0 WHERE t1.`c16` > NULL
2012-11-25T17:29:07 [26618] Query: SELECT `c22` > `c54`, `c53`, `c10` FROM `table100_innodb_default_int_autoinc` ORDER BY `c35` LIMIT 1
==15346== Thread 20:
==15346== Syscall param write(buf) points to uninitialised byte(s)
==15346== at 0x38E260D96B: ??? (in /lib64/libpthread-2.5.so)
==15346== by 0x7D7CB4: my_write (my_write.c:41)
==15346== by 0x7C5E97: my_b_flush_io_cache (mysql_file.h:1134)
==15346== by 0x7C5F4B: end_io_cache (mf_iocache.c:1851)
==15346== by 0x96C08E: mi_extra (mi_extra.c:156)
==15346== by 0x5ED1B4: select_union::flush() (sql_union.cc:87)
==15346== by 0x5611EF: mysql_derived_filling(THD*, LEX*, TABLE_LIST*) (sql_derived.cc:308)
==15346== by 0x560C28: mysql_handle_derived(LEX*, bool (*)(THD*, LEX*, TABLE_LIST*)) (sql_derived.cc:60)
==15346== by 0x547B31: open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) (sql_base.cc:5552)
==15346== by 0x57C75A: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_base.h:475)
==15346== by 0x57F93D: mysql_execute_command(THD*) (sql_parse.cc:2284)
==15346== by 0x583112: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5811)
==15346== by 0x5845D9: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1061)
==15346== by 0x584965: do_command(THD*) (sql_parse.cc:788)
==15346== by 0x6224C0: do_handle_one_connection(THD*) (sql_connect.cc:1484)
==15346== by 0x6225B3: handle_one_connection (sql_connect.cc:1391)
==15346== Address 0x1a6a05fb is 11 bytes inside a block of size 131,072 alloc'd
==15346== at 0x4A078B8: malloc (vg_replace_malloc.c:270)
==15346== by 0x7D51C1: my_malloc (my_malloc.c:38)
==15346== by 0x7C4172: init_io_cache (mf_iocache.c:232)
==15346== by 0x96BC38: mi_extra (mi_extra.c:137)
==15346== by 0x5ED396: select_union::create_result_table(THD*, List<Item>*, bool, unsigned long long, char const*) (sql_union.cc:129)
==15346== by 0x560FFB: mysql_derived_prepare(THD*, LEX*, TABLE_LIST*) (sql_derived.cc:174)
==15346== by 0x560C28: mysql_handle_derived(LEX*, bool (*)(THD*, LEX*, TABLE_LIST*)) (sql_derived.cc:60)
==15346== by 0x547AE1: open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) (sql_base.cc:5550)
==15346== by 0x57C75A: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_base.h:475)
==15346== by 0x57F93D: mysql_execute_command(THD*) (sql_parse.cc:2284)
==15346== by 0x583112: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5811)
==15346== by 0x5845D9: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1061)
==15346== by 0x584965: do_command(THD*) (sql_parse.cc:788)
==15346== by 0x6224C0: do_handle_one_connection(THD*) (sql_connect.cc:1484)
==15346== by 0x6225B3: handle_one_connection (sql_connect.cc:1391)
==15346== by 0x38E260677C: start_thread (pthread_create.c:301)
==15346==
==15346== Syscall param pwrite64(buf) points to uninitialised byte(s)
==15346== at 0x38E260E598: ??? (in /lib64/libpthread-2.5.so)
==15346== by 0x7D5C53: my_pwrite (my_pread.c:185)
==15346== by 0x968013: mi_nommap_pwrite (mysql_file.h:1201)
==15346== by 0x96A01D: _mi_write_part_record (mi_dynrec.c:766)
==15346== by 0x96ACBA: _mi_write_blob_record (mi_dynrec.c:370)
==15346== by 0x981FE9: mi_write (mi_write.c:142)
==15346== by 0x9518C2: ha_myisam::write_row(unsigned char*) (ha_myisam.cc:831)
==15346== by 0x69B7E1: handler::ha_write_row(unsigned char*) (handler.cc:5359)
==15346== by 0x5ED458: select_union::send_data(List<Item>&) (sql_union.cc:67)
==15346== by 0x5A27E3: end_send(JOIN*, st_join_table*, bool) (sql_select.cc:12722)
==15346== by 0x5AC73A: evaluate_join_record(JOIN*, st_join_table*, int) (sql_select.cc:11934)
==15346== by 0x5AC82C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:11787)
==15346== by 0x5ADF7F: do_select(JOIN*, List<Item>*, TABLE*, Procedure*) (sql_select.cc:11552)
==15346== by 0x5BDB77: JOIN::exec() (sql_select.cc:2400)
==15346== by 0x5EEC64: st_select_lex_unit::exec() (sql_union.cc:518)
==15346== by 0x5EF9AC: mysql_union(THD*, LEX*, select_result*, st_select_lex_unit*, unsigned long) (sql_union.cc:38)
==15346== Address 0x15c35893 is 35 bytes inside a block of size 117 alloc'd
==15346== at 0x4A078B8: malloc (vg_replace_malloc.c:270)
==15346== by 0x7D51C1: my_malloc (my_malloc.c:38)
==15346== by 0x96ABC2: _mi_write_blob_record (mi_dynrec.c:284)
==15346== by 0x981FE9: mi_write (mi_write.c:142)
==15346== by 0x9518C2: ha_myisam::write_row(unsigned char*) (ha_myisam.cc:831)
==15346== by 0x69B7E1: handler::ha_write_row(unsigned char*) (handler.cc:5359)
==15346== by 0x5ED458: select_union::send_data(List<Item>&) (sql_union.cc:67)
==15346== by 0x5A27E3: end_send(JOIN*, st_join_table*, bool) (sql_select.cc:12722)
==15346== by 0x5AC73A: evaluate_join_record(JOIN*, st_join_table*, int) (sql_select.cc:11934)
==15346== by 0x5AC82C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:11787)
==15346== by 0x5ADF7F: do_select(JOIN*, List<Item>*, TABLE*, Procedure*) (sql_select.cc:11552)
==15346== by 0x5BDB77: JOIN::exec() (sql_select.cc:2400)
==15346== by 0x5EEC64: st_select_lex_unit::exec() (sql_union.cc:518)
==15346== by 0x5EF9AC: mysql_union(THD*, LEX*, select_result*, st_select_lex_unit*, unsigned long) (sql_union.cc:38)
==15346== by 0x5BF829: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:290)
==15346== by 0x57C7AC: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:4741)
==15346==
2012-11-25T17:29:07 [26618] Query: DROP PROCEDURE IF EXISTS w ; CREATE PROCEDURE w ( IN l CHAR( 7 ) ) BEGIN SELECT COUNT( `c53` ) INTO @a FROM `table100_innodb_compressed_int` ; END ; CALL w(@a);
2012-11-25T17:29:07 [26618] Query: SET GLOBAL innodb_kill_idle_transaction = 60

Initial analysis thanks to Alexey:
- Stacktraces are almost identical to those reported in bug 789131 (found when testing our MEMORY engine improvements)
- The problem is benign, and should not occur when the binary is compiled with Valgrind support.
- A suppression can be added to avoid this kind of errors with regular builds.

This bug report to add such a suppression.

[Roel Van de Paar (roel11)]

Similar warnings during another run

==7142== Thread 40:
==7142== Syscall param pwrite64(buf) points to uninitialised byte(s)
==7142== at 0x4E3DEC3: ??? (in /lib64/libpthread-2.12.so)
==7142== by 0x7D6083: my_pwrite (my_pread.c:185)
==7142== by 0x94B5D3: mi_nommap_pwrite (mysql_file.h:1201)
==7142== by 0x94D5DD: _mi_write_part_record (mi_dynrec.c:766)
==7142== by 0x94E27A: _mi_write_blob_record (mi_dynrec.c:370)
==7142== by 0x9655A9: mi_write (mi_write.c:142)
==7142== by 0x934E82: ha_myisam::write_row(unsigned char*) (ha_myisam.cc:831)
==7142== by 0x69BBC1: handler::ha_write_row(unsigned char*) (handler.cc:5359)
==7142== by 0x5ED848: select_union::send_data(List<Item>&) (sql_union.cc:67)
==7142== by 0x5A4243: end_send(JOIN*, st_join_table*, bool) (sql_select.cc:12731)
==7142== by 0x5AE31A: evaluate_join_record(JOIN*, st_join_table*, int) (sql_select.cc:11935)
==7142== by 0x5AE40C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:11788)
==7142== by 0x5AE7DF: do_select(JOIN*, List<Item>*, TABLE*, Procedure*) (sql_select.cc:11553)
==7142== by 0x5BDF47: JOIN::exec() (sql_select.cc:2401)
==7142== by 0x5EF054: st_select_lex_unit::exec() (sql_union.cc:518)
==7142== by 0x5EFD9C: mysql_union(THD*, LEX*, select_result*, st_select_lex_unit*, unsigned long) (sql_union.cc:38)
==7142== Address 0xffadac3 is 35 bytes inside a block of size 115 alloc'd
==7142== at 0x4C278FE: malloc (vg_replace_malloc.c:270)
==7142== by 0x7D55F1: my_malloc (my_malloc.c:38)
==7142== by 0x94E182: _mi_write_blob_record (mi_dynrec.c:284)
==7142== by 0x9655A9: mi_write (mi_write.c:142)
==7142== by 0x934E82: ha_myisam::write_row(unsigned char*) (ha_myisam.cc:831)
==7142== by 0x69BBC1: handler::ha_write_row(unsigned char*) (handler.cc:5359)
==7142== by 0x5ED848: select_union::send_data(List<Item>&) (sql_union.cc:67)
==7142== by 0x5A4243: end_send(JOIN*, st_join_table*, bool) (sql_select.cc:12731)
==7142== by 0x5AE31A: evaluate_join_record(JOIN*, st_join_table*, int) (sql_select.cc:11935)
==7142== by 0x5AE40C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:11788)
==7142== by 0x5AE7DF: do_select(JOIN*, List<Item>*, TABLE*, Procedure*) (sql_select.cc:11553)
==7142== by 0x5BDF47: JOIN::exec() (sql_select.cc:2401)
==7142== by 0x5EF054: st_select_lex_unit::exec() (sql_union.cc:518)
==7142== by 0x5EFD9C: mysql_union(THD*, LEX*, select_result*, st_select_lex_unit*, unsigned long) (sql_union.cc:38)
==7142== by 0x5BFBF9: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:291)
==7142== by 0x57CABC: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:4741)
==7142==
==7142== Syscall param write(buf) points to uninitialised byte(s)
==7142== at 0x4E3D4ED: ??? (in /lib64/libpthread-2.12.so)
==7142== by 0x7D80E4: my_write (my_write.c:41)
==7142== by 0x7C62C7: my_b_flush_io_cache (mysql_file.h:1134)
==7142== by 0x7C637B: end_io_cache (mf_iocache.c:1851)
==7142== by 0x94F64E: mi_extra (mi_extra.c:156)
==7142== by 0x5ED5A4: select_union::flush() (sql_union.cc:87)
==7142== by 0x5EF0C6: st_select_lex_unit::exec() (sql_union.cc:532)
==7142== by 0x5EF...

[Roel Van de Paar (roel11)]

Just a quick update to note it's still seen in revno Percona-Server-5.5.28-rel29.3-450.Linux.x86_64

[Roel Van de Paar (roel11)]

upstream? added temporary tag

[Laurynas Biveinis (laurynas-biveinis)]

The previous preliminary analysis suggests that it is not upstream but rather our MEMORY engine.

[Valerii Kravchuk (valerii-kravchuk)]

Can somebody explain what exact test one should run to reproduce this?

[Laurynas Biveinis (laurynas-biveinis)]

FWIW this Valgrind stacktrace is not seen in any MTR testcase on 5.6. (but it did not come from MTR in 5.5 neither)

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.6 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.5 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1953