[MDEV-12637] main.range_vs_index_merge_innodb fails in buildbot with timeout Created: 2017-04-29  Updated: 2018-03-15  Resolved: 2018-03-15

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB, Tests
Affects Version/s: 10.1
Fix Version/s: 10.1.23

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Cannot Reproduce Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-12602 InnoDB: Failing assertion: space->n_p... Closed
Sprint: 10.1.32

 Description   

http://buildbot.askmonty.org/buildbot/builders/work-amd64-valgrind/builds/10024/steps/test/logs/stdio

main.range_vs_index_merge_innodb 'xtradb' w4 [ fail ]  timeout after 9000 seconds
        Test ended at 2017-04-28 01:02:38
 
Test case timeout after 9000 seconds
 
== /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/mysql-test/var/4/log/range_vs_index_merge_innodb.log == 
create table t1 (
id int unsigned auto_increment primary key,
c1 char(12),
c2 char(15),
c3 char(1)
);
insert into t1 (c3) values ('1'), ('2');
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
insert into t1 (c3) select c3 from t1;
update t1 set c1=lpad(id+1000, 12, ' '), c2=lpad(id+10000, 15, ' ');
 
The server [mysqld.1 - pid: 5073, winpid: 5073, exit: 256] crashed while running 'analyze-timeout'
Server log from this test:
----------SERVER LOG START-----------
2017-04-27 22:32:00 68532992 [Note] InnoDB: Created tablespace for space 416 name world/Country key_id 0 encryption 0.
2017-04-27 22:32:00 68532992 [Note] InnoDB: Created tablespace for space 417 name world/City key_id 0 encryption 0.
2017-04-27 22:32:01 68532992 [Note] InnoDB: Created tablespace for space 418 name world/CountryLanguage key_id 0 encryption 0.
2017-04-27 22:53:02 68532992 [Note] InnoDB: Created tablespace for space 419 name test/t1 key_id 0 encryption 0.
2017-04-28  0:14:41 68532992 [Note] InnoDB: Created tablespace for space 420 name test/t1 key_id 0 encryption 0.
2017-04-28  0:33:10 68532992 [Note] InnoDB: Created tablespace for space 421 name test/t1 key_id 0 encryption 0.
2017-04-28  0:46:39 68532992 [Note] InnoDB: Created tablespace for space 422 name test/t1 key_id 0 encryption 0.
170428  1:01:57 [ERROR] mysqld got signal 6 ;
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.1.23-MariaDB-debug
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63027 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
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 = 0x0 thread_stack 0x48400
/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld(my_print_stacktrace+0x38)[0xf20d95]
mysys/stacktrace.c:267(my_print_stacktrace)[0x868233]
/lib64/libpthread.so.0(+0xf9f0)[0x4e439f0]
/lib64/libc.so.6(__poll+0x2d)[0x6b2006d]
sql/mysqld.cc:6484(handle_connections_sockets())[0x552e78]
sql/mysqld.cc:5914(mysqld_main(int, char**))[0x551e44]
sql/main.cc:26(main)[0x546d58]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x6a63be5]
x86_64/start.S:125(_start)[0x546c49]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file
----------SERVER LOG END-------------



 Comments   
Comment by Marko Mäkelä [ 2018-03-15 ]

I cannot repeat the hang, and there is no stack trace. The failure was reported for this commit that claimed to fix MDEV-12253. I remember this commit and the development of MariaDB 10.1.23 very well. It was part of a very much needed fixes of race conditions and hangs in MariaDB 10.1. This commit appeared in MariaDB 10.1.23. I seem to remember that it caused some regressions, the last of which was fixed in MDEV-12602, which was included in the MariaDB 10.1.23 release.

Based on the client log excerpt, the hang occurred during the execution of the following statement:

alter table t1 add unique index (c1), add unique index (c2), add index (c3);

Based on the server log excerpt, the server had completed 4 CREATE TABLE t1 statements. This agrees with the test case contents. The ALTER TABLE statement would be executed in-place (adding secondary indexes), because there already is a PRIMARY KEY defined on the table.

I do not remember details very clearly after so long time, but I am sure that encryption used to have hangs especially during DDL operations. I also remember that MDEV-12602 fixed an issue that was caused by some earlier commit during the 10.1.23 development. This issue would affect all data files, not only encrypted ones.

What exactly caused this hang? It is difficult to say. But as long as I remember, MDEV-12602 was the last major fix to hangs that were caused by the encryption changes in MariaDB 10.1. On innodb_plugin the test took quite a bit of time, but nowhere close to the 9,000,000ms limit:

main.range_vs_index_merge_innodb 'innodb_plugin' w1 [ pass ]  1304214

Before the failure, no test appears to have used encryption since the latest restart of the instance:

main.innodb_mysql_lock 'xtradb'          w4 [ pass ]  16683
main.join_outer_innodb 'xtradb'          w4 [ pass ]  32136
main.loaddata_autocom_innodb 'xtradb'    w4 [ pass ]   1968
main.log_tables_upgrade 'xtradb'         w4 [ pass ]   8970
main.lowercase_table2 'xtradb'           w4 [ skipped ]  Test requires: 'lowercase2'
main.merge_innodb 'xtradb'               w4 [ pass ]   2357
main.mrr_derived_crash_4610 'xtradb'     w4 [ pass ]   3190
main.multi_update_innodb 'xtradb'        w4 [ pass ]   3129
main.mysql_upgrade 'xtradb'              w4 [ pass ]  76296
main.mysqlcheck 'xtradb'                 w4 [ fail ]  Found warnings/errors in server log file!
main.order_by_optimizer_innodb 'xtradb'  w4 [ pass ]  38832
main.parser_bug21114_innodb 'xtradb'     w4 [ pass ]  439186
main.plugin_innodb 'xtradb'              w4 [ pass ]  34063
main.range_innodb 'xtradb'               w4 [ pass ]  606284
main.range_mrr_icp 'xtradb'              w4 [ pass ]  985291
main.range_vs_index_merge_innodb 'xtradb' w4 [ fail ]  timeout after 9000 seconds

Comment by Marko Mäkelä [ 2018-03-15 ]

I started tests locally.

./mtr --mem --valgrind --repeat=10 --parallel=auto main.range_vs_index_merge_innodb{,,,}

10.0 1bec0c45954689580e27e826dee7d1afefa82471

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
worker[2] Using MTR_BUILD_THREAD 301, with reserved ports 16020..16039
worker[4] Using MTR_BUILD_THREAD 302, with reserved ports 16040..16059
worker[3] Using MTR_BUILD_THREAD 303, with reserved ports 16060..16079
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'innodb_plugin' w3 [ pass ]  2377699
main.range_vs_index_merge_innodb 'innodb_plugin' w2 [ pass ]  2380451
main.range_vs_index_merge_innodb 'innodb_plugin' w4 [ pass ]  2382399
main.range_vs_index_merge_innodb 'innodb_plugin' w1 [ pass ]  2388440
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'innodb_plugin' w3 [ pass ]  2220613
main.range_vs_index_merge_innodb 'innodb_plugin' w4 [ pass ]  2220209
main.range_vs_index_merge_innodb 'innodb_plugin' w2 [ pass ]  2228767
main.range_vs_index_merge_innodb 'innodb_plugin' w1 [ pass ]  2219457
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'innodb_plugin' w3 [ pass ]  2235379
main.range_vs_index_merge_innodb 'innodb_plugin' w1 [ pass ]  2231888
main.range_vs_index_merge_innodb 'innodb_plugin' w2 [ pass ]  2234251
main.range_vs_index_merge_innodb 'innodb_plugin' w4 [ pass ]  2243300
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'innodb_plugin' w1 [ pass ]  2195471
main.range_vs_index_merge_innodb 'innodb_plugin' w3 [ pass ]  2208165
main.range_vs_index_merge_innodb 'innodb_plugin' w2 [ pass ]  2211816
main.range_vs_index_merge_innodb 'innodb_plugin' w4 [ pass ]  2227083
mysql-test-run: *** ERROR: Got ^C signal

At this point, I interrupted the test and restarted with xtradb, because that is where the hang was reported:

./mtr --mem --valgrind --repeat=10 --parallel=auto main.range_vs_index_merge_innodb,xtradb{,,,}

Comment by Marko Mäkelä [ 2018-03-15 ]

I was not able to repeat any hang in this way:

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
worker[3] Using MTR_BUILD_THREAD 301, with reserved ports 16020..16039
worker[2] Using MTR_BUILD_THREAD 302, with reserved ports 16040..16059
worker[4] Using MTR_BUILD_THREAD 303, with reserved ports 16060..16079
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w4 [ pass ]  2268198
main.range_vs_index_merge_innodb 'xtradb' w2 [ pass ]  2272657
main.range_vs_index_merge_innodb 'xtradb' w3 [ pass ]  2283271
main.range_vs_index_merge_innodb 'xtradb' w1 [ pass ]  2321484
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w4 [ pass ]  2379181
main.range_vs_index_merge_innodb 'xtradb' w3 [ pass ]  2374475
worker[2] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w2 [ pass ]  2409713
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w1 [ pass ]  2409291
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w3 [ pass ]  2439826
main.range_vs_index_merge_innodb 'xtradb' w4 [ pass ]  2477677
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w2 [ pass ]  2473013
main.range_vs_index_merge_innodb 'xtradb' w1 [ pass ]  2521295
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w3 [ pass ]  2323561
main.range_vs_index_merge_innodb 'xtradb' w4 [ pass ]  2314867
main.range_vs_index_merge_innodb 'xtradb' w2 [ pass ]  2342171
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w1 [ pass ]  2406380
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w3 [ pass ]  2599272
main.range_vs_index_merge_innodb 'xtradb' w4 [ pass ]  2604337
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w2 [ pass ]  2620441
main.range_vs_index_merge_innodb 'xtradb' w1 [ pass ]  2575754
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w3 [ pass ]  2268703
main.range_vs_index_merge_innodb 'xtradb' w4 [ pass ]  2295956
main.range_vs_index_merge_innodb 'xtradb' w2 [ pass ]  2280279
main.range_vs_index_merge_innodb 'xtradb' w1 [ pass ]  2299700
worker[3] Test still running: main.range_vs_index_merge_innodb
worker[4] Test still running: main.range_vs_index_merge_innodb
worker[2] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
worker[3] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w3 [ pass ]  2411915
worker[4] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' w4 [ pass ]  2408764
main.range_vs_index_merge_innodb 'xtradb' w2 [ pass ]  2394262
main.range_vs_index_merge_innodb 'xtradb' w1 [ pass ]  2390223
mysql-test-run: *** ERROR: Got ^C signal

I started one final attempt:

./mtr --mem --valgrind --no-reorder --force --retry=0 --suite=main innodb_mysql_lock,xtradb join_outer_innodb,xtradb loaddata_autocom_innodb,xtradb log_tables_upgrade,xtradb lowercase_table2,xtradb merge_innodb,xtradb mrr_derived_crash_4610,xtradb multi_update_innodb,xtradb mysql_upgrade,xtradb mysqlcheck,xtradb order_by_optimizer_innodb,xtradb parser_bug21114_innodb,xtradb plugin_innodb,xtradb range_innodb,xtradb range_mrr_icp,xtradb range_vs_index_merge_innodb,xtradb

main.innodb_mysql_lock 'xtradb'          [ pass ]  21006
main.join_outer_innodb 'xtradb'          [ pass ]  25752
main.loaddata_autocom_innodb 'xtradb'    [ pass ]   4386
main.log_tables_upgrade 'xtradb'         [ pass ]   6085
main.lowercase_table2 'xtradb'           [ skipped ]  Test requires: 'lowercase2'
main.merge_innodb 'xtradb'               [ pass ]   1822
main.mrr_derived_crash_4610 'xtradb'     [ pass ]   2449
main.multi_update_innodb 'xtradb'        [ pass ]   6482
main.mysql_upgrade 'xtradb'              [ pass ]  74682
main.mysqlcheck 'xtradb'                 [ pass ]  20717
main.order_by_optimizer_innodb 'xtradb'  [ pass ]  19643
main.parser_bug21114_innodb 'xtradb'     [ pass ]  408096
main.plugin_innodb 'xtradb'              [ pass ]  24973
main.range_innodb 'xtradb'               [ pass ]  257916
main.range_mrr_icp 'xtradb'              [ pass ]  786391
worker[1] Test still running: main.range_vs_index_merge_innodb
worker[1] Test still running: main.range_vs_index_merge_innodb
main.range_vs_index_merge_innodb 'xtradb' [ pass ]  3362975
valgrind_report                          [ pass ]       

I think that this bug may have been fixed in 10.1.23. Looking at the diff from the failing commit to the tag mariadb-10.1.23, MDEV-12602 looks most promising; it fixed a regression that was introduced by MDEV-12428 which in turn fixed a regression that was introduced by MDEV-11738.

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