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:
None 
Category:MySQL Server: Tests Severity:S3 (Non-critical)
Version:5.5 OS:Linux
Assigned to: CPU Architecture:Any
Tags: mtr, valgrind

[25 Jun 2014 9:41] Laurynas Biveinis
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
 }
[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] Miguel Solorzano
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] Miguel Solorzano
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] Miguel Solorzano
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 $