Bug #69203 Valgrind warnings and crash on select from an InnoDB table
Submitted: 11 May 2013 17:35 Modified: 8 Nov 2013 9:58
Reporter: Elena Stepanova Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S3 (Non-critical)
Version:5.7 OS:Linux (Ubuntu 12.04 64-bit)
Assigned to: Assigned Account CPU Architecture:Any

[11 May 2013 17:35] Elena Stepanova
Description:
The server is built with BUILD/compile-pentium-debug-max-no-ndb. All I do is run the test from 'How to repeat' section via MTR with --valgrind-mysqld. The error log contains a valgrind warning first, and the the server crashes with SIGSEGV. If the test is run without valgrind, no crash.

==26676== Thread 18:
==26676== Jump to the invalid address stated on the next line
==26676==    at 0xFFFFFFFFFF600800: ???
==26676==    by 0xB906FC: ib_counter_t<unsigned long, 64, get_sched_indexer_t>::add(unsigned long) (ut0counter.h:177)
==26676==    by 0xB90538: ib_counter_t<unsigned long, 64, get_sched_indexer_t>::inc() (ut0counter.h:172)
==26676==    by 0xB7FDA4: ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) (ha_innodb.cc:7428)
==26676==    by 0xB80A7F: ha_innobase::index_first(unsigned char*) (ha_innodb.cc:7792)
==26676==    by 0x63B3AF: handler::ha_index_first(unsigned char*) (handler.cc:2867)
==26676==    by 0x7A1103: join_read_first(st_join_table*) (sql_executor.cc:2538)
==26676==    by 0x79E35A: sub_select(JOIN*, st_join_table*, bool) (sql_executor.cc:1253)
==26676==    by 0x79DDCA: do_select(JOIN*) (sql_executor.cc:930)
==26676==    by 0x79BDE3: JOIN::exec() (sql_executor.cc:191)
==26676==    by 0x7EE735: mysql_execute_select(THD*, st_select_lex*, bool) (sql_select.cc:1100)
==26676==    by 0x7EEA32: mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, SQL_I_List<st_order>*, SQL_I_List<st_order>*, Item*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:1221)
==26676==    by 0x7ECA8B: handle_select(THD*, select_result*, unsigned long) (sql_select.cc:110)
==26676==    by 0x7C6C93: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:4846)
==26676==    by 0x7BFA61: mysql_execute_command(THD*) (sql_parse.cc:2461)
==26676==    by 0x7C9393: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5994)
==26676==  Address 0xffffffffff600800 is not stack'd, malloc'd or (recently) free'd
==26676== 
17:33:56 UTC - mysqld got signal 11 ;

...

Thread pointer: 0xf43c810
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
==26676== Invalid read of size 1
==26676==    at 0x5EA1066: ??? (in /lib/x86_64-linux-gnu/libgcc_s.so.1)
==26676==    by 0x5EA1D7C: _Unwind_Backtrace (in /lib/x86_64-linux-gnu/libgcc_s.so.1)
==26676==    by 0x61B29C7: backtrace (backtrace.c:110)
==26676==    by 0xA917F2: my_print_stacktrace (stacktrace.c:224)
==26676==    by 0x724A60: handle_fatal_signal (signal_handler.cc:163)
==26676==    by 0x5688CAF: ??? (in /lib/x86_64-linux-gnu/libpthread-2.15.so)
==26676==    by 0xFFFFFFFFFF6007FF: ???
==26676==    by 0xB906FC: ib_counter_t<unsigned long, 64, get_sched_indexer_t>::add(unsigned long) (ut0counter.h:177)
==26676==    by 0xB90538: ib_counter_t<unsigned long, 64, get_sched_indexer_t>::inc() (ut0counter.h:172)
==26676==    by 0xB7FDA4: ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) (ha_inno
db.cc:7428)
==26676==    by 0xB80A7F: ha_innobase::index_first(unsigned char*) (ha_innodb.cc:7792)
==26676==    by 0x63B3AF: handler::ha_index_first(unsigned char*) (handler.cc:2867)
==26676==    by 0x7A1103: join_read_first(st_join_table*) (sql_executor.cc:2538)
==26676==    by 0x79E35A: sub_select(JOIN*, st_join_table*, bool) (sql_executor.cc:1253)
==26676==    by 0x79DDCA: do_select(JOIN*) (sql_executor.cc:930)
==26676==    by 0x79BDE3: JOIN::exec() (sql_executor.cc:191)
==26676==  Address 0xffffffffff600800 is not stack'd, malloc'd or (recently) free'd
==26676== 
==26676== Invalid read of size 8
==26676==    at 0x5EA1079: ??? (in /lib/x86_64-linux-gnu/libgcc_s.so.1)
==26676==    by 0x5EA1D7C: _Unwind_Backtrace (in /lib/x86_64-linux-gnu/libgcc_s.so.1)
==26676==    by 0x61B29C7: backtrace (backtrace.c:110)
==26676==    by 0xA917F2: my_print_stacktrace (stacktrace.c:224)
==26676==    by 0x724A60: handle_fatal_signal (signal_handler.cc:163)
==26676==    by 0x5688CAF: ??? (in /lib/x86_64-linux-gnu/libpthread-2.15.so)
==26676==    by 0xFFFFFFFFFF6007FF: ???
==26676==    by 0xB906FC: ib_counter_t<unsigned long, 64, get_sched_indexer_t>::add(unsigned long) (ut0counter.h:177)
==26676==    by 0xB90538: ib_counter_t<unsigned long, 64, get_sched_indexer_t>::inc() (ut0counter.h:172)
==26676==    by 0xB7FDA4: ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) (ha_inno
db.cc:7428)
==26676==    by 0xB80A7F: ha_innobase::index_first(unsigned char*) (ha_innodb.cc:7792)
==26676==    by 0x63B3AF: handler::ha_index_first(unsigned char*) (handler.cc:2867)
==26676==    by 0x7A1103: join_read_first(st_join_table*) (sql_executor.cc:2538)
==26676==    by 0x79E35A: sub_select(JOIN*, st_join_table*, bool) (sql_executor.cc:1253)
==26676==    by 0x79DDCA: do_select(JOIN*) (sql_executor.cc:930)
==26676==    by 0x79BDE3: JOIN::exec() (sql_executor.cc:191)
==26676==  Address 0xffffffffff600801 is not stack'd, malloc'd or (recently) free'd
==26676== 
stack_bottom = 40bcdf0 thread_stack 0x40000
/data/repo/bzr/mysql-5.7/sql/mysqld(my_print_stacktrace+0x35)[0xa917f3]
/data/repo/bzr/mysql-5.7/sql/mysqld(handle_fatal_signal+0x402)[0x724a61]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfcb0)[0x5688cb0]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (bd11b80): SELECT * FROM t1
Connection ID (thread ID): 1
Status: NOT_KILLED

How to repeat:
CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t1 VALUES (10),(11);

SELECT * FROM t1;
[12 May 2013 13:33] MySQL Verification Team
Sounds like this?
Bug 16761469 - CRASH UNDER VALGRIND IN GET_SCHED_INDEXER AT UT0COUNTER.H DURING JOIN EXECUTION
[12 May 2013 19:51] MySQL Verification Team
Thank you for the bug report. Which is your Valgrind version? If it prior of 3.8.1 please upgrade and test again. Thanks.
[13 May 2013 6:12] MySQL Verification Team
I can not repeat described behavior with valgrind-3.8.1

[ushastry@ushastry mysql-test]$ valgrind --version
valgrind-3.8.1
[ushastry@ushastry mysql-test]$ ./mysql-test-run.pl --valgrind-mysqld uVal
Logging: ./mysql-test-run.pl  --valgrind-mysqld uVal
2013-05-13 11:38:20 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151  table_cache: 431
2013-05-13 11:38:20 23500 [Note] Plugin 'FEDERATED' is disabled.
2013-05-13 11:38:20 23500 [Note] Binlog end
2013-05-13 11:38:20 23500 [Note] Shutting down plugin 'CSV'
2013-05-13 11:38:20 23500 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.7.1
Turning on valgrind for mysqld(s) only
Running valgrind with options " --show-reachable=yes "
Turning off --check-testcases to save time when valgrinding
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/ushastry/mybuilds/mysql-5.7.1/mysql-test/var'...
Installing system database...
Using server port 52239

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

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t1 VALUES (10),(11);
SELECT * FROM t1;
pk
10
11
main.uVal                                [ pass ]   3400
valgrind_report                          [ pass ]       
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 3.400 of 33 seconds executing testcases

Completed: All 2 tests were successful.

[ushastry@ushastry mysql-test]$ 
[ushastry@ushastry mysql-test]$ cat t/uVal.test 
CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t1 VALUES (10),(11);

SELECT * FROM t1;
[14 May 2013 13:10] Elena Stepanova
It is 3.7.0 which happens to be the latest version offered by official repos for Ubuntu 12.04 (indicated in OS field), which, in turn, is the latest LTS release of Ubuntu. 

sudo apt-get install valgrind
Reading package lists... Done
Building dependency tree       
Reading state information... Done
valgrind is already the newest version.
...

valgrind --version
valgrind-3.7.0
[15 May 2013 18:48] MySQL Verification Team
Thank you for the feedback. Please test with >= 3.8.1 version which isn't repeatable this bug report a similar internal bug report was closed !bug.

On Centos 6.3 isn't repeatable:

[miguel@tikal 5.5]$ cat /etc/issue
CentOS release 6.4 (Final)
Kernel \r on an \m

[miguel@tikal 5.5]$ valgrind --version
valgrind-3.8.1
[miguel@tikal 5.5]$
[15 May 2013 19:27] Elena Stepanova
>> Please test with >= 3.8.1 

I trust your results if you're saying it's not repeatable with 3.8.1. If it's a good enough reason to consider it not to be a bug, please go ahead and close.