Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2(EOL)
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...
|
Attachments
Issue Links
Activity
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
|
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 ;
|
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
|
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.
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
|
Cannot repeat in the latest bb-10.2-serg (as of709d9068651) with --ps --embedded or without.