| Bug #73111 | Suppression typo causing spurious MTR Valgrind failures | ||
|---|---|---|---|
| Submitted: | 25 Jun 2014 9:41 | Modified: | 15 Apr 2018 18:17 |
| Reporter: | Laurynas Biveinis (OCA) | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Tests | Severity: | S3 (Non-critical) |
| Version: | 5.5 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | mtr, valgrind | ||
[27 Jun 2014 14:06]
Valeriy Kravchuk
I wonder what exact 5.5.x version and on what exact Linux was tested. I can not built recent MySQL 5.5.38 I've got from bzr on updated Ubuntu 14.04 after using the cmake command presented here.
[27 Jun 2014 14:07]
Laurynas Biveinis
Right, one needs to apply a patch for bug 71250 first. For some reason this bug is not fixed in 5.6- yet. I used Ubuntu 14.04.
[12 Jul 2014 13:52]
Laurynas Biveinis
The "slightly different mangling" is in fact wildcard, I missed the header comment for the suppression telling that. The fix then reduces to
=== modified file 'mysql-test/valgrind.supp'
--- mysql-test/valgrind.supp 2012-04-19 16:51:34 +0000
+++ mysql-test/valgrind.supp 2014-07-12 13:40:16 +0000
@@ -902,7 +902,7 @@
fun:my_b_flush_io_cache
fun:_my_b_write
fun:_Z*10write_keysP13st_sort_paramPPhjP11st_io_cacheS4_
- fun:_Z*13find_all_keysP13st_sort_paramP10SQL_SELECTPPhP11st_io_cacheS6_
+ ...
fun:_Z8filesortP3THDP5TABLEP13st_sort_fieldjP10SQL_SELECTybPy
}
[9 Apr 2015 11:46]
MySQL Verification Team
I couldn't repeat with recent source server. Besides the compile options is there another condition to repeat it?. Thanks.
[9 Apr 2015 12:43]
MySQL Verification Team
Forgot to paste: [miguel@vbcentos65 mysql-test]$ ./mtr ctype_eucjpms Logging: ./mtr ctype_eucjpms 150409 8:41:37 [Note] Plugin 'FEDERATED' is disabled. MySQL Version 5.5.43 Checking supported features... - SSL connections supported - binaries are debug compiled Collecting tests... Removing old var directory... Creating var directory '/home/miguel/test/mysql-5.5/mysql-test/var'... Installing system database... ============================================================================== TEST RESULT TIME (ms) or COMMENT -------------------------------------------------------------------------- worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009 main.ctype_eucjpms [ pass ] 1219 -------------------------------------------------------------------------- The servers were restarted 0 times Spent 1.219 of 8 seconds executing testcases Completed: All 1 tests were successful.
[10 Apr 2015 8:28]
Laurynas Biveinis
Miguel, the error is of Valgrind kind, and your test run did not invoke Valgrind. Then, if CentOS does not show it, try Ubuntu 14.04. It's still here today:
$ git rev-parse HEAD
e02fe87f00dc9fdb0fb6ab13f2e87485f79f3341
$ cmake ../mysql-server/ -DWITH_DEBUG=ON -DWITH_VALGRIND=ON -DCMAKE_C_FLAGS=-DHAVE_purify -DCMAKE_CXX_FLAGS=-DHAVE_purify -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DWITH_EMBEDDED_SERVER=OFF -DENABLE_DTRACE=OFF -DWITH_EXAMPLE_STORAGE_ENGINE=1 -DWITH_SSL=system
...
$ ./mtr ctype_eucjpms --valgrind
...
main.ctype_eucjpms [ fail ] Found warnings/errors in server log file!
Test ended at 2015-04-10 11:18:38
line
==10255== Thread 13:
==10255== Syscall param write(buf) points to uninitialised byte(s)
==10255== at 0x504835D: ??? (syscall-template.S:81)
==10255== by 0x7E797E: my_write (my_write.c:43)
==10255== by 0x7D0326: my_b_flush_io_cache (mysql_file.h:1134)
==10255== by 0x7D09A0: _my_b_write (mf_iocache.c:1549)
==10255== by 0x6A1BE1: write_keys(st_sort_param*, unsigned char**, unsigned int, st_io_cache*, st_io_cache*) (filesort.cc:760)
==10255== by 0x6A3EDC: filesort(THD*, TABLE*, st_sort_field*, unsigned int, SQL_SELECT*, unsigned long long, bool, unsigned long long*) (filesort.cc:662)
==10255== by 0x5BED9E: create_sort_index(THD*, JOIN*, st_order*, unsigned long long, unsigned long long, bool) (sql_select.cc:14262)
==10255== by 0x5D1CCC: JOIN::exec() (sql_select.cc:2354)
==10255== by 0x5CBDB9: mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:2604)
==10255== by 0x5CBFB0: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:297)
==10255== by 0x582516: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:4625)
==10255== by 0x588719: mysql_execute_command(THD*) (sql_parse.cc:2176)
==10255== by 0x58FE9B: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5777)
==10255== by 0x591726: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1038)
==10255== by 0x593595: do_command(THD*) (sql_parse.cc:773)
==10255== by 0x63F30D: do_handle_one_connection(THD*) (sql_connect.cc:862)
==10255== Address 0x102becb7 is 23 bytes inside a block of size 65,536 alloc'd
==10255== at 0x4C2AB80: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==10255== by 0x7E3A74: my_malloc (my_malloc.c:38)
==10255== by 0x7CFAF1: init_io_cache (mf_iocache.c:232)
==10255== by 0x7CD116: open_cached_file (mf_cache.c:69)
==10255== by 0x6A1B50: write_keys(st_sort_param*, unsigned char**, unsigned int, st_io_cache*, st_io_cache*) (filesort.cc:750)
==10255== by 0x6A3EDC: filesort(THD*, TABLE*, st_sort_field*, unsigned int, SQL_SELECT*, unsigned long long, bool, unsigned long long*) (filesort.cc:662)
==10255== by 0x5BED9E: create_sort_index(THD*, JOIN*, st_order*, unsigned long long, unsigned long long, bool) (sql_select.cc:14262)
==10255== by 0x5D1CCC: JOIN::exec() (sql_select.cc:2354)
==10255== by 0x5CBDB9: mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:2604)
==10255== by 0x5CBFB0: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:297)
==10255== by 0x582516: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:4625)
==10255== by 0x588719: mysql_execute_command(THD*) (sql_parse.cc:2176)
==10255== by 0x58FE9B: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5777)
==10255== by 0x591726: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1038)
==10255== by 0x593595: do_command(THD*) (sql_parse.cc:773)
==10255== by 0x63F30D: do_handle_one_connection(THD*) (sql_connect.cc:862)
^ Found warnings in /home/laurynas/percona/obj-5.5-valgrind/mysql-test/var/log/mysqld.1.err
[10 Apr 2015 8:29]
Laurynas Biveinis
The previous command output only show the initial Valgrind errors for this bug. It will also include numerous errors of bug 73126.
[15 Apr 2018 18:17]
MySQL Verification Team
With recent source server there is still fail test, not exactly valgrind warnings:
miguel@tikal:~/tmp/2018APR04/mysql-5.5/mysql-test $ ./mtr ctype_eucjpms --valgrind
Logging: ./mtr ctype_eucjpms --valgrind
180415 15:07:29 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
180415 15:07:29 [Note] /home/miguel/tmp/2018APR04/mysql-5.5/sql/mysqld (mysqld 5.5.61-debug) starting as process 18540 ...
180415 15:07:29 [Note] Plugin 'FEDERATED' is disabled.
MySQL Version 5.5.61
Turning on valgrind for all executables
Running valgrind with options " --show-reachable=yes "
Checking supported features...
- SSL connections supported
- binaries are debug compiled
Collecting tests...
Removing old var directory...
Creating var directory '/home/miguel/tmp/2018APR04/mysql-5.5/mysql-test/var'...
Installing system database...
==============================================================================
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 18562, winpid: 18562, exit: 256] died after mysql-test-run waited 0.2 seconds for /home/miguel/tmp/2018APR04/mysql-5.5/mysql-test/var/run/mysqld.1.pid to be created.
main.ctype_eucjpms [ fail ]
Test ended at 2018-04-15 15:07:34
Server log is:
safe_process[18562]: FATAL ERROR, Failed to exec child
error: 2, No such file or directory
Failed to start mysqld.1
- saving '/home/miguel/tmp/2018APR04/mysql-5.5/mysql-test/var/log/main.ctype_eucjpms/' to '/home/miguel/tmp/2018APR04/mysql-5.5/mysql-test/var/log/main.ctype_eucjpms/'
valgrind_report [ pass ]
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 6 seconds executing testcases
Completed: Failed 1/2 tests, 50.00% were successful.
Failing test(s): main.ctype_eucjpms
The log files in var/log may give you some hint of what went wrong.
If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
mysql-test-run: *** ERROR: there were failing test cases
miguel@tikal:~/tmp/2018APR04/mysql-5.5/mysql-test $
Description: main.ctype_eucjpms [ fail ] Found warnings/errors in server log file! Test ended at 2014-06-25 11:34:38 line ==1327== Thread 13: ==1327== Syscall param write(buf) points to uninitialised byte(s) ==1327== at 0x504835D: ??? (syscall-template.S:81) ==1327== by 0x7E52DE: my_write (my_write.c:43) ==1327== by 0x7CDD16: my_b_flush_io_cache (mysql_file.h:1134) ==1327== by 0x7CE390: _my_b_write (mf_iocache.c:1549) ==1327== by 0x6A06D1: write_keys(st_sort_param*, unsigned char**, unsigned int, st_io_cache*, st_io_cache*) (filesort.cc:760) ==1327== by 0x6A29CC: filesort(THD*, TABLE*, st_sort_field*, unsigned int, SQL_SELECT*, unsigned long long, bool, unsigned long long*) (filesort.cc:662) ==1327== by 0x5BDD1F: create_sort_index(THD*, JOIN*, st_order*, unsigned long long, unsigned long long, bool) (sql_select.cc:14254) ==1327== by 0x5D0C4C: JOIN::exec() (sql_select.cc:2354) ==1327== by 0x5CAD39: mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:2604) ==1327== by 0x5CAF30: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:297) ==1327== by 0x5815B6: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:4625) ==1327== by 0x587A80: mysql_execute_command(THD*) (sql_parse.cc:2176) ==1327== by 0x58F20B: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5662) ==1327== by 0x590A96: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1038) ==1327== by 0x592905: do_command(THD*) (sql_parse.cc:773) ==1327== by 0x63DEAD: do_handle_one_connection(THD*) (sql_connect.cc:862) ==1327== Address 0x10abaf57 is 23 bytes inside a block of size 65,536 alloc'd ==1327== at 0x4C2AB80: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so) ==1327== by 0x7E13D4: my_malloc (my_malloc.c:38) ==1327== by 0x7CD4E1: init_io_cache (mf_iocache.c:232) ==1327== by 0x7CAB06: open_cached_file (mf_cache.c:69) ==1327== by 0x6A0640: write_keys(st_sort_param*, unsigned char**, unsigned int, st_io_cache*, st_io_cache*) (filesort.cc:750) ==1327== by 0x6A29CC: filesort(THD*, TABLE*, st_sort_field*, unsigned int, SQL_SELECT*, unsigned long long, bool, unsigned long long*) (filesort.cc:662) ==1327== by 0x5BDD1F: create_sort_index(THD*, JOIN*, st_order*, unsigned long long, unsigned long long, bool) (sql_select.cc:14254) ==1327== by 0x5D0C4C: JOIN::exec() (sql_select.cc:2354) ==1327== by 0x5CAD39: mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:2604) ==1327== by 0x5CAF30: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:297) ==1327== by 0x5815B6: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:4625) ==1327== by 0x587A80: mysql_execute_command(THD*) (sql_parse.cc:2176) ==1327== by 0x58F20B: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5662) ==1327== by 0x590A96: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1038) ==1327== by 0x592905: do_command(THD*) (sql_parse.cc:773) ==1327== by 0x63DEAD: do_handle_one_connection(THD*) (sql_connect.cc:862) Affected tests: ctype_eucjpms, ctype_sjis, ctype_tis620 ctype_ujis ctype_ujis_ucs2 ctype_cp932_binlog_stm subselect sum_distinct, all in main suite. How to repeat: Server built with -DWITH_DEBUG=ON -DWITH_VALGRIND=ON -DCMAKE_C_FLAGS=-DHAVE_purify -DCMAKE_CXX_FLAGS=-DHAVE_purify -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DWITH_EMBEDDED_SERVER=OFF -DENABLE_DTRACE=OFF -DWITH_EXAMPLE_STORAGE_ENGINE=1 -DWITH_SSL=system Suggested fix: There are existing suppressions that attempt to address this, the closest one being { Bug#12856915 VALGRIND FAILURE IN FILESORT/CREATE_SORT_INDEX / one Memcheck:Param write(buf) obj:*/libpthread*.so fun:my_write ... fun:my_b_flush_io_cache fun:_my_b_write fun:_Z10write_keysP13st_sort_paramPPhjP11st_io_cacheS4_ fun:_Z13find_all_keysP13st_sort_paramP10SQL_SELECTPPhP11st_io_cacheS6_ fun:_Z8filesortP3THDP5TABLEP13st_sort_fieldjP10SQL_SELECTybPy } It does not account for find_all_keys missing in the stacktrace, and write_keys needs slightly different mangling at least on my system. Changing it as follows fixes the issue. === modified file 'mysql-test/valgrind.supp' --- mysql-test/valgrind.supp 2012-02-14 07:11:28 +0000 +++ mysql-test/valgrind.supp 2014-06-25 09:16:58 +0000 @@ -892,8 +892,8 @@ ... fun:my_b_flush_io_cache fun:_my_b_write - fun:_Z*10write_keysP13st_sort_paramPPhjP11st_io_cacheS4_ - fun:_Z*13find_all_keysP13st_sort_paramP10SQL_SELECTPPhP11st_io_cacheS6_ + fun:_ZL10write_keysP13st_sort_paramPPhjP11st_io_cacheS4_ + ... fun:_Z8filesortP3THDP5TABLEP13st_sort_fieldjP10SQL_SELECTybPy }