[MDEV-11639] Server crashes in update_virtual_field, gcol.innodb_virtual_basic fails in buildbot Created: 2016-12-22  Updated: 2017-07-05  Resolved: 2017-07-05

Status: Closed
Project: MariaDB Server
Component/s: Tests, Virtual Columns
Affects Version/s: 10.2
Fix Version/s: 10.2.7

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: 10.2-ga

Issue Links:
Relates
relates to MDEV-5800 indexes on virtual (not materialized)... Closed
relates to MDEV-7069 Fix buildbot failures in main server ... Stalled

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-quantal-x86/builds/5541

gcol.innodb_virtual_basic 'innodb'       w3 [ fail ]
        Test ended at 2016-12-22 13:31:49
 
CURRENT_TEST: gcol.innodb_virtual_basic
mysqltest: In included file "/usr/local/mariadb-10.2.3-linux-i686/mysql-test/suite/gcol/inc/innodb_v_large_col.inc": 
included from /usr/local/mariadb-10.2.3-linux-i686/mysql-test/suite/gcol/t/innodb_virtual_basic.test at line 736:
At line 43: query 'CALL DELETE_insert_t()' failed: 2013: Lost connection to MySQL server during query

161222 13:31:46 [ERROR] mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.2.3-MariaDB-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=2
max_threads=153
thread_count=8
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61814 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x95009008
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...
stack_bottom = 0x973fb20c thread_stack 0x48c00
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(my_print_stacktrace+0x2d)[0xb71440bd]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(handle_fatal_signal+0x4f2)[0xb6b57d02]
[0xb668d400]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(_ZN5TABLE20update_virtual_fieldEP5Field+0x29)[0xb6a653f9]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(+0x62d18f)[0xb6cdd18f]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(+0x75eb1c)[0xb6e0eb1c]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(+0x72f650)[0xb6ddf650]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(+0x72facf)[0xb6ddfacf]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(+0x7315df)[0xb6de15df]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(+0x731c0f)[0xb6de1c0f]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(+0x6e21b5)[0xb6d921b5]
/usr/local/mariadb-10.2.3-linux-i686/bin/mysqld(+0x76b0ef)[0xb6e1b0ef]
/lib/i386-linux-gnu/libpthread.so.0(+0x6d4c)[0xb662ed4c]
/lib/i386-linux-gnu/libc.so.6(clone+0x5e)[0xb6456d3e]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x0): 
Connection ID (thread ID): 2
Status: NOT_KILLED

More decent stack trace, but from ps-embedded:
http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/6590/steps/test_5/logs/stdio

gcol.innodb_virtual_basic 'innodb'       w1 [ fail ]
        Test ended at 2016-12-20 19:43:36
 
CURRENT_TEST: gcol.innodb_virtual_basic
mysqltest got signal 11
read_command_buf (0x9484440): CALL DELETE_insert_t()AULT, 1);                 SET i = i + 1;         END WHILE; ENDol_VARCHAR_key VARCHAR(2) GENERATED ALWAYS AS(CONCAT(col_VARCHAR_nokey, col_VARCHAR_nokey)), KEY (col_INT_key), KEY (col_VARCHAR_key), KEY (col_date_key), KEY (col_time_key), KEY (col_datetime_key), KEY (col_INT_key, col_VARCHAR_key), KEY (col_INT_key, col_VARCHAR_key, col_date_key, col_time_key, col_datetime_key) )
conn->name (0xacb9f50): 
conn->cur_query (0xad2fd98): CALL DELETE_insert_t()
Attempting backtrace...
stack_bottom = 0x0 thread_stack 0x48c00
/mnt/buildbot/build/mariadb-10.2.3/libmysqld/examples/mysqltest_embedded(my_print_stacktrace+0x32)[0x8272dfa]
/mnt/buildbot/build/mariadb-10.2.3/libmysqld/examples/mysqltest_embedded[0x8255a97]
/mnt/buildbot/build/mariadb-10.2.3/libmysqld/examples/mysqltest_embedded[0x8255ad5]
[0xb7730400]
/mnt/buildbot/build/mariadb-10.2.3/libmysqld/examples/mysqltest_embedded(_ZN3THD28reset_arena_for_cached_itemsEP11Query_arena+0x9)[0x837c6b5]
/mnt/buildbot/build/mariadb-10.2.3/libmysqld/examples/mysqltest_embedded(_ZN5TABLE20update_virtual_fieldEP5Field+0x56)[0x83c0c2c]
/mnt/buildbot/build/mariadb-10.2.3/libmysqld/examples/mysqltest_embedded[0x8891f1a]
/mnt/buildbot/build/mariadb-10.2.3/libmysqld/examples/mysqltest_embedded[0x8a23673]
mysys/stacktrace.c:267(my_print_stacktrace)[0x8a24477]
sql/sql_class.h:4072(THD::reset_arena_for_cached_items(Query_arena*))[0x8a0b012]
/mnt/buildbot/build/mariadb-10.2.3/libmysqld/examples/mysqltest_embedded[0x8a0b7d8]
handler/ha_innodb.cc:23810(innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, dict_table_t const*, upd_t*, dict_foreign_t*))[0x8a0bc23]
row/row0vers.cc:484(row_vers_build_clust_v_col)[0x8a0be02]
row/row0purge.cc:975(row_purge_record_func)[0x8a0c9c0]
row/row0purge.cc:1031(row_purge)[0x8a0cbde]
row/row0purge.cc:1112(row_purge_step(que_thr_t*))[0x8a0ceb1]
que/que0que.cc:1056(que_thr_step)[0x8a15206]
que/que0que.cc:1118(que_run_threads_low)[0x8a1540f]
que/que0que.cc:1160(que_run_threads(que_thr_t*))[0x8a155e6]
trx/trx0purge.cc:1861(trx_purge(unsigned long, unsigned long, bool))[0x88c3a90]
srv/srv0srv.cc:2880(srv_do_purge)[0x8b1df24]
srv/srv0srv.cc:3058(srv_purge_coordinator_thread)[0x8b1e669]
/lib/i386-linux-gnu/libpthread.so.0(+0x6d4c)[0xb7713d4c]
/lib/i386-linux-gnu/libc.so.6(clone+0x5e)[0xb72c8ace]
Writing a core file...



 Comments   
Comment by Sergei Golubchik [ 2017-02-09 ]

Cannot repeat in the latest bb-10.2-serg (as of709d9068651) with --ps --embedded or without.

Comment by Elena Stepanova [ 2017-02-14 ]

It still fails in buildbot on 10.2, even after the merge:
http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-trusty-x86/builds/128

gcol.innodb_virtual_basic 'innodb'       w2 [ fail ]
        Test ended at 2017-02-14 07:04:08
 
CURRENT_TEST: gcol.innodb_virtual_basic
mysqltest: At line 432: query 'CALL DELETE_insert_t()' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
< snip >
UPDATE t SET a = REPEAT(CAST(1 AS CHAR), 1000) WHERE h = 1;
CREATE PROCEDURE UPDATE_t()
begin
DECLARE i INT DEFAULT 1;
WHILE (i <= 200) DO
UPDATE t SET a = REPEAT(CAST(i AS CHAR), 2000) WHERE h = 1;
SET i = i + 1;
END WHILE;
END|
CREATE PROCEDURE DELETE_insert_t()
begin
DECLARE i INT DEFAULT 1;
WHILE (i <= 200) DO
DELETE FROM t WHERE h = 1;
INSERT INTO t VALUES (REPEAT(CAST(i AS CHAR), 2000) ,  REPEAT('b', 2000), DEFAULT, DEFAULT, DEFAULT, 1);
SET i = i + 1;
END WHILE;
END|
CALL UPDATE_t();
CALL DELETE_insert_t();
 
More results from queries before failure can be found in /usr/local/mariadb-10.2.4-linux-i686/mysql-test/var/2/log/innodb_virtual_basic.log
 
 
Server [mysqld.1 - pid: 8192, winpid: 8192, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:05 3055695680 [Note] InnoDB: Online DDL : Completed
2017-02-14  7:04:06 3055695680 [Note] InnoDB: Online DDL : Start
2017-02-14  7:04:06 3055695680 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
2017-02-14  7:04:06 3055695680 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
2017-02-14  7:04:06 3055695680 [Note] InnoDB: Online DDL : Start applying row log
2017-02-14  7:04:06 3055695680 [Note] InnoDB: Online DDL : End of applying row log
2017-02-14  7:04:06 3055695680 [Note] InnoDB: Online DDL : Completed
170214  7:04:06 [ERROR] mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.2.4-MariaDB-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=2
max_threads=153
thread_count=8
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61815 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0xa3009008
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

stack_bottom = 0xa47f919c thread_stack 0x48c00
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(my_print_stacktrace+0x2d)[0xb712c47d]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(handle_fatal_signal+0x344)[0xb6b0d374]
[0xb6655400]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(_ZN11Query_arena15set_query_arenaEPS_+0x9)[0xb692de49]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(_ZN3THD25set_n_backup_active_arenaEP11Query_arenaS1_+0x28)[0xb692dfe8]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(_ZN5TABLE20update_virtual_fieldEP5Field+0x45)[0xb6a187e5]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(+0x63f828)[0xb6cb7828]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(+0x7720ff)[0xb6dea0ff]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(+0x7432cd)[0xb6dbb2cd]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(+0x744a8c)[0xb6dbca8c]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(+0x7462db)[0xb6dbe2db]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(+0x6f635d)[0xb6d6e35d]
/usr/local/mariadb-10.2.4-linux-i686/bin/mysqld(+0x7815db)[0xb6df95db]
/lib/i386-linux-gnu/libpthread.so.0(+0x6f70)[0xb65f2f70]
/lib/i386-linux-gnu/libc.so.6(clone+0x5e)[0xb63f4d7e]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x0): 
Connection ID (thread ID): 3
Status: NOT_KILLED

Comment by Elena Stepanova [ 2017-02-14 ]

Failed for me locally with valgrind – first produced an 'invalid read' warning, then crashed:

10.2 2bf07556e8ba35ea166b -DWITH_VALGRIND=YES

==16003== Thread 18:
==16003== Invalid read of size 8
==16003==    at 0x66990E: Query_arena::set_query_arena(Query_arena*) (sql_class.cc:3535)
==16003==    by 0x669D3B: THD::set_n_backup_active_arena(Query_arena*, Query_arena*) (sql_class.cc:3623)
==16003==    by 0x7BA77F: TABLE::update_virtual_field(Field*) (table.cc:7412)
==16003==    by 0xBA100E: innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE
*, dict_table_t const*, upd_t*, dict_foreign_t*) (ha_innodb.cc:22477)
==16003==    by 0xD3D25F: row_vers_build_clust_v_col(dtuple_t*, dict_index_t*, dict_index_t*, mem_block_info_t*) (row0vers.cc:498)
==16003==    by 0xD3E077: row_vers_old_has_index_entry(unsigned long, unsigned char const*, mtr_t*, dict_index_t*, dtuple_t const*, unsigned long, unsigned long) (row0vers.cc:934)
==16003==    by 0xCF5542: row_purge_poss_sec(purge_node_t*, dict_index_t*, dtuple_t const*) (row0purge.cc:264)
==16003==    by 0xCF5CD2: row_purge_remove_sec_if_poss_leaf(purge_node_t*, dict_index_t*, dtuple_t const*) (row0purge.cc:481)
==16003==    by 0xCF617F: row_purge_remove_sec_if_poss(purge_node_t*, dict_index_t*, dtuple_t const*) (row0purge.cc:587)
==16003==    by 0xCF637C: row_purge_del_mark(purge_node_t*) (row0purge.cc:657)
==16003==    by 0xCF6EF6: row_purge_record_func(purge_node_t*, unsigned char*, que_thr_t const*, bool) (row0purge.cc:975)
==16003==    by 0xCF7122: row_purge(purge_node_t*, unsigned char*, que_thr_t*) (row0purge.cc:1031)
==16003==    by 0xCF73E5: row_purge_step(que_thr_t*) (row0purge.cc:1110)
==16003==    by 0xC810DD: que_thr_step(que_thr_t*) (que0que.cc:1057)
==16003==    by 0xC812DF: que_run_threads_low(que_thr_t*) (que0que.cc:1119)
==16003==    by 0xC81491: que_run_threads(que_thr_t*) (que0que.cc:1159)
==16003==  Address 0x28 is not stack'd, malloc'd or (recently) free'd
==16003== 
170214 23:31:56 [ERROR] mysqld got signal 11 ;

Comment by Elena Stepanova [ 2017-04-08 ]

It is still reproducible on the current 10.2 tree (as of a33653eedb42a99), just sporadically.

10.2 a33653eedb42a99

==463== Thread 18:
==463== Invalid read of size 8
==463==    at 0x66C13C: Query_arena::set_query_arena(Query_arena*) (sql_class.cc:3537)
==463==    by 0x66C569: THD::set_n_backup_active_arena(Query_arena*, Query_arena*) (sql_class.cc:3625)
==463==    by 0x7BDEA9: TABLE::update_virtual_field(Field*) (table.cc:7415)
==463==    by 0xC6ED62: innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**
, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, dict_table_t const*, upd_t*, dict_foreign_t*) (ha_innodb.cc:22536)
==463==    by 0xDFE3CF: row_vers_build_clust_v_col(dtuple_t*, dict_index_t*, dict_index_t*, mem_block_info_t*) (row0vers.cc:493)
==463==    by 0xDFF1CA: row_vers_old_has_index_entry(unsigned long, unsigned char const*, mtr_t*, dict_index_t*, dtuple_t const*,
 unsigned long, unsigned long) (row0vers.cc:929)
==463==    by 0xDB8631: row_purge_poss_sec(purge_node_t*, dict_index_t*, dtuple_t const*) (row0purge.cc:259)
==463==    by 0xDB8DF7: row_purge_remove_sec_if_poss_leaf(purge_node_t*, dict_index_t*, dtuple_t const*) (row0purge.cc:471)
==463==    by 0xDB92AB: row_purge_remove_sec_if_poss(purge_node_t*, dict_index_t*, dtuple_t const*) (row0purge.cc:577)
==463==    by 0xDB94A8: row_purge_del_mark(purge_node_t*) (row0purge.cc:647)
==463==    by 0xDBA02B: row_purge_record_func(purge_node_t*, unsigned char*, que_thr_t const*, bool) (row0purge.cc:955)
==463==    by 0xDBA257: row_purge(purge_node_t*, unsigned char*, que_thr_t*) (row0purge.cc:1011)
==463==    by 0xDBA508: row_purge_step(que_thr_t*) (row0purge.cc:1090)
==463==    by 0xD45FBF: que_thr_step(que_thr_t*) (que0que.cc:1052)
==463==    by 0xD461BD: que_run_threads_low(que_thr_t*) (que0que.cc:1114)
==463==    by 0xD46366: que_run_threads(que_thr_t*) (que0que.cc:1154)
==463==  Address 0x28 is not stack'd, malloc'd or (recently) free'd
==463== 
170408 21:59:13 [ERROR] mysqld got signal 11 ;

Build

cmake . -DCMAKE_BUILD_TYPE=Debug -DWITH_VALGRIND=YES && make -j6

command line

perl ./mtr gcol.innodb_virtual_basic --valgrind --mem --repeat=20

Comment by Marko Mäkelä [ 2017-06-22 ]

This appears fully reproducible in bb-10.3-marko with a work-in-progress MDEV-12288 patch. The issue is that a NULL pointer is being dereferenced:

#0  0x0000555555b2c376 in Query_arena::set_query_arena (this=0x7fffca7095a0, set=0x18)
    at /mariadb/10.3/sql/sql_class.cc:3604
#1  0x0000555555b2c7ab in THD::set_n_backup_active_arena (this=0x0, set=0x7fffc400e000, 
    backup=0x7fffca7095a0) at /mariadb/10.3/sql/sql_class.cc:3692
#2  0x0000555555c89c8c in TABLE::update_virtual_field (this=0x7fffc400c8a8, vf=0x7fffc4013220)
    at /mariadb/10.3/sql/table.cc:7483
#3  0x00005555560667ae in innobase_get_computed_value (row=0x7fffc000c8d8, col=0x7fff980c4130, 
    index=0x7fff980c4d48, local_heap=0x7fffca70a370, heap=0x7fffc000c800, ifield=0x0, 
    thd=0x7fffc0000a98, mysql_table=0x7fffc400c8a8, old_table=0x0, parent_update=0x0, foreign=0x0)
    at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:21795
#4  0x0000555556206c66 in row_vers_build_clust_v_col (row=0x7fffc000c8d8, 
    clust_index=0x7fff980c4d48, index=0x7fff980c1748, heap=0x7fffc000c800)
    at /mariadb/10.3/storage/innobase/row/row0vers.cc:506
#5  0x0000555556207a4d in row_vers_old_has_index_entry (also_curr=1, rec=0x7fffebfc807e "\200", 
    mtr=0x7fffca70a4a0, index=0x7fff980c1748, ientry=0x7fffc000c2d8, roll_ptr=14073748861620244, 
    trx_id=5393) at /mariadb/10.3/storage/innobase/row/row0vers.cc:942
#6  0x00005555561bd4c1 in row_purge_poss_sec (node=0x5555584779f8, index=0x7fff980c1748, 
    entry=0x7fffc000c2d8) at /mariadb/10.3/storage/innobase/row/row0purge.cc:259
#7  0x00005555561bdc8e in row_purge_remove_sec_if_poss_leaf (node=0x5555584779f8, 
    index=0x7fff980c1748, entry=0x7fffc000c2d8)
    at /mariadb/10.3/storage/innobase/row/row0purge.cc:474
#8  0x00005555561be14a in row_purge_remove_sec_if_poss (node=0x5555584779f8, index=0x7fff980c1748, 
    entry=0x7fffc000c2d8) at /mariadb/10.3/storage/innobase/row/row0purge.cc:581
#9  0x00005555561bea3b in row_purge_upd_exist_or_extern_func (thr=0x555558477840, 
    node=0x5555584779f8, undo_rec=0x555558477fa8 "\020\\\f")
    at /mariadb/10.3/storage/innobase/row/row0purge.cc:776
#10 0x00005555561bf50b in row_purge_record_func (node=0x5555584779f8, 
    undo_rec=0x555558477fa8 "\020\\\f", thr=0x555558477840, updated_extern=false)
    at /mariadb/10.3/storage/innobase/row/row0purge.cc:1047
#11 0x00005555561bf69d in row_purge (node=0x5555584779f8, undo_rec=0x555558477fa8 "\020\\\f", 
    thr=0x555558477840) at /mariadb/10.3/storage/innobase/row/row0purge.cc:1091
#12 0x00005555561bf93b in row_purge_step (thr=0x555558477840)
    at /mariadb/10.3/storage/innobase/row/row0purge.cc:1170
#13 0x0000555556146e8d in que_thr_step (thr=0x555558477840)
    at /mariadb/10.3/storage/innobase/que/que0que.cc:1054
#14 0x0000555556147090 in que_run_threads_low (thr=0x555558477840)
    at /mariadb/10.3/storage/innobase/que/que0que.cc:1116
#15 0x000055555614723c in que_run_threads (thr=0x555558477840)
    at /mariadb/10.3/storage/innobase/que/que0que.cc:1156
#16 0x000055555621148a in srv_task_execute () at /mariadb/10.3/storage/innobase/srv/srv0srv.cc:2593
#17 0x00005555562115cb in srv_worker_thread (arg=0x0)
    at /mariadb/10.3/storage/innobase/srv/srv0srv.cc:2640
#18 0x00007ffff7bc3494 in start_thread (arg=0x7fffca70c700) at pthread_create.c:333
#19 0x00007ffff6608aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

To debug, simply run:

./mtr --manual-gdb gcol.innodb_virtual_basic

Note that the include/wait_innodb_all_purged.inc is not working as intended in some gcol tests, maybe also this one, so the purge code does not get a chance to run often.
We should replace that broken logic with

SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
--source include/wait_all_purged.inc

like we have in innodb.truncate_purge_debug. But see the latest comments in MDEV-12754 regarding randomly lost DEBUG_SYNC signals.

Comment by Marko Mäkelä [ 2017-07-03 ]

Here is a reduced test case that reproduces a problem with Valgrind:

--source include/have_innodb.inc
let $row_format=DYNAMIC;
--source inc/innodb_v_large_col.inc

This triggers a problem on the 13th invocation of ha_innobase::write_row(), which is inserting on top of a purgeable delete-marked record.
The statement is like this, executed as part of CALL DELETE_insert_t():

INSERT INTO t VALUES (REPEAT(CAST( NAME_CONST('i',10) AS CHAR), 2000) ,  REPEAT('b', 2000), DEFAULT, DEFAULT, DEFAULT, 1);

According to Valgrind, InnoDB wrongly thinks that this would insert 4000 bytes into column a, and the correct amount of 2000 bytes into column b.
Only the first 2000 bytes of the column a value are initialized according to Valgrind V bits (monitor get_vbits).

To debug:

./mtr --manual-gdb gcol.ivb
valgrind --vgdb=yes --vgdb-error=0 build/sql/mysqld [the args from the gdb file]
gdb build/sql/mysqld
target remote |vgdb
c

Here is the stack trace for noticing that only the first 2000 bytes of column a are initialized:

#0  dfield_dup (field=0xc941a18, heap=0xc940940)
    at /mariadb/10.2-o/storage/innobase/include/data0data.ic:285
#1  0x0000000000cf78d1 in row_upd_index_replace_new_col_val (
    dfield=0xc941a18, field=0x1bb6de28, col=0x1bb53b58, uf=0x1bbb8ac0, 
    heap=0xc940940, page_size=...)
    at /mariadb/10.2-o/storage/innobase/row/row0upd.cc:1238
#2  0x0000000000cf7aff in row_upd_index_replace_new_col_vals_index_pos (
    entry=0xc941988, index=0xc9432b8, update=0x1bbb8a98, order_only=0, 
    heap=0xc940940) at /mariadb/10.2-o/storage/innobase/row/row0upd.cc:1318
#3  0x0000000000daed02 in btr_cur_optimistic_update (flags=0, 
    cursor=0x4129fa0, offsets=0x4129f48, heap=0x4129f40, update=0x1bbb8a98, 
    cmpl_info=0, thr=0x15f28db0, trx_id=1534, mtr=0x412a3c0)
    at /mariadb/10.2-o/storage/innobase/btr/btr0cur.cc:3876
#4  0x0000000000c72679 in row_ins_clust_index_entry_by_modify (
    pcur=0x4129fa0, flags=0, mode=2, offsets=0x4129f48, 
    offsets_heap=0x4129f40, heap=0x1bbb8a10, entry=0x15f65428, 
    thr=0x15f28db0, mtr=0x412a3c0)
    at /mariadb/10.2-o/storage/innobase/row/row0ins.cc:370
#5  0x0000000000c77f25 in row_ins_clust_index_entry_low (flags=0, mode=2, 
    index=0xc9432b8, n_uniq=1, entry=0x15f65428, n_ext=0, thr=0x15f28db0, 
    dup_chk_only=false)
    at /mariadb/10.2-o/storage/innobase/row/row0ins.cc:2693
#6  0x0000000000c79694 in row_ins_clust_index_entry (index=0xc9432b8, 
    entry=0x15f65428, thr=0x15f28db0, n_ext=0, dup_chk_only=false)
    at /mariadb/10.2-o/storage/innobase/row/row0ins.cc:3207
#7  0x0000000000c79a51 in row_ins_index_entry (index=0xc9432b8, 
    entry=0x15f65428, thr=0x15f28db0)
    at /mariadb/10.2-o/storage/innobase/row/row0ins.cc:3316
#8  0x0000000000c79f46 in row_ins_index_entry_step (node=0x1063a4c8, 
    thr=0x15f28db0) at /mariadb/10.2-o/storage/innobase/row/row0ins.cc:3466
#9  0x0000000000c7a304 in row_ins (node=0x1063a4c8, thr=0x15f28db0)
    at /mariadb/10.2-o/storage/innobase/row/row0ins.cc:3608
#10 0x0000000000c7a8ff in row_ins_step (thr=0x15f28db0)
---Type <return> to continue, or q <return> to quit---
    at /mariadb/10.2-o/storage/innobase/row/row0ins.cc:3792
#11 0x0000000000c99fd2 in row_insert_for_mysql (
    mysql_rec=0x1bc7d7a0 "\340\320\a1001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001"..., 
    prebuilt=0xc9f88f8)
    at /mariadb/10.2-o/storage/innobase/row/row0mysql.cc:1484
#12 0x0000000000b4ab50 in ha_innobase::write_row (this=0xc9f4bc0, 
    record=0x1bc7d7a0 "\340\320\a1001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001"...)
    at /mariadb/10.2-o/storage/innobase/handler/ha_innodb.cc:8646
#13 0x00000000009425a0 in handler::ha_write_row (this=0xc9f4bc0, 
    buf=0x1bc7d7a0 "\340\320\a1001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001001"...)
    at /mariadb/10.2-o/sql/handler.cc:5950
#14 0x000000000069a018 in write_record (thd=0xc8fc438, table=0xc9f3fe8, 
    info=0x412b490) at /mariadb/10.2-o/sql/sql_insert.cc:1927
#15 0x0000000000697bb5 in mysql_insert (thd=0xc8fc438, table_list=0xcc0ba80, 
    fields=..., values_list=..., update_fields=..., update_values=..., 
    duplic=DUP_ERROR, ignore=false) at /mariadb/10.2-o/sql/sql_insert.cc:1055
#16 0x00000000006bf398 in mysql_execute_command (thd=0xc8fc438)
    at /mariadb/10.2-o/sql/sql_parse.cc:4413
#17 0x0000000000ab1ba6 in sp_instr_stmt::exec_core (this=0xcc0d510, 
    thd=0xc8fc438, nextp=0x412c184) at /mariadb/10.2-o/sql/sp_head.cc:3235
#18 0x0000000000ab1226 in sp_lex_keeper::reset_lex_and_exec_core (
    this=0xcc0d558, thd=0xc8fc438, nextp=0x412c184, open_tables=false, 
    instr=0xcc0d510) at /mariadb/10.2-o/sql/sp_head.cc:2998
#19 0x0000000000ab1857 in sp_instr_stmt::execute (this=0xcc0d510, 
    thd=0xc8fc438, nextp=0x412c184) at /mariadb/10.2-o/sql/sp_head.cc:3151
#20 0x0000000000aacaa6 in sp_head::execute (this=0x15e8af90, thd=0xc8fc438, 
    merge_da_on_success=true) at /mariadb/10.2-o/sql/sp_head.cc:1324

Generated at Thu Feb 08 07:51:31 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.