[MDEV-13904] rocksdb.add_index_inplace_sstfilewriter, rocksdb.bulk_load_rev_cf failed in buildbot (timeout, crash) Created: 2017-09-25  Updated: 2018-05-14  Resolved: 2018-05-14

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - RocksDB, Tests
Affects Version/s: 10.2
Fix Version/s: 10.2.15

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-13599 rocksdb.add_index_inplace_sstfilewrit... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1218/steps/test_1/logs/stdio

rocksdb.add_index_inplace_sstfilewriter  w1 [ fail ]  timeout after 7200 seconds
 
        Test ended at 2017-09-23 18:11:07
 
 
 
Test case timeout after 7200 seconds
 
 
 
== /mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/1/log/add_index_inplace_sstfilewriter.log == 
drop table if exists t1;
 
CREATE TABLE t1(pk CHAR(5) PRIMARY KEY, a char(30), b char(30)) COLLATE 'latin1_bin';
 
set rocksdb_bulk_load=1;
 
set rocksdb_bulk_load_size=100000;
 
LOAD DATA INFILE <input_file> INTO TABLE t1;
 
set rocksdb_bulk_load=0;
 
select count(pk) from t1;
 
count(pk)
 
3000000
 
select count(a) from t1;
 
count(a)
 
3000000
 
select count(b) from t1;
 
count(b)
 
3000000
 
ALTER TABLE t1 ADD INDEX kb(b), ALGORITHM=INPLACE;
 
ALTER TABLE t1 ADD INDEX kb_copy(b), ALGORITHM=COPY;
 
 
 
 == /mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/1/tmp/analyze-timeout-mysqld.1.err ==
 
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/tmp/1/mysqld.1' (111)

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1218/steps/test_1/logs/mysqld.1.err.1

CURRENT_TEST: rocksdb.add_index_inplace_sstfilewriter
 
2017-09-23 18:11:08 139752104999168 [Note] /mnt/buildbot/build/mariadb-10.2.9/sql/mysqld (mysqld 10.2.9-MariaDB-log) starting as process 12410 ...
 
2017-09-23 18:11:08 139752104999168 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
 
2017-09-23 18:11:08 139752104999168 [Warning] setrlimit could not change the size of core files to 'infinity';  We may not be able to generate a core file on signals
 
2017-09-23 18:11:08 139752104999168 [Note] RocksDB: Got ENOENT when listing column families
 
2017-09-23 18:11:08 139752104999168 [Note] RocksDB:   assuming that we're creating a new database
 
2017-09-23 18:11:08 139752104999168 [Note] RocksDB: Column Families at start:
 
2017-09-23 18:11:08 139752104999168 [Note]   cf=default
 
2017-09-23 18:11:08 139752104999168 [Note]     write_buffer_size=67108864
 
2017-09-23 18:11:08 139752104999168 [Note]     target_file_size_base=67108864
 
2017-09-23 18:11:08 139752104999168 [Note] RocksDB: creating a column family __system__
 
2017-09-23 18:11:08 139752104999168 [Note]     write_buffer_size=67108864
 
2017-09-23 18:11:08 139752104999168 [Note]     target_file_size_base=67108864
 
2017-09-23 18:11:08 139752104999168 [Note] RocksDB: Table_store: loaded DDL data for 0 tables
 
2017-09-23 18:11:08 139752104999168 [Note] RocksDB: global statistics using get_sched_indexer_t indexer
 
2017-09-23 18:11:08 139752104999168 [Note] MyRocks storage engine plugin has been successfully initialized.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'SEQUENCE' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'partition' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'InnoDB' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_LOCKS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_CMPMEM' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_CMP_PER_INDEX' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_CMP' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_TRX' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_METRICS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'user_variables' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-09-23 18:11:08 139752104999168 [Warning] /mnt/buildbot/build/mariadb-10.2.9/sql/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
 
2017-09-23 18:11:08 139752104999168 [Warning] /mnt/buildbot/build/mariadb-10.2.9/sql/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
 
2017-09-23 18:11:08 139752104999168 [Warning] /mnt/buildbot/build/mariadb-10.2.9/sql/mysqld: unknown variable 'loose-feedback-debug-interval=60'
 
2017-09-23 18:11:08 139752104999168 [Warning] /mnt/buildbot/build/mariadb-10.2.9/sql/mysqld: unknown option '--loose-pam-debug'
 
2017-09-23 18:11:08 139752104999168 [Warning] /mnt/buildbot/build/mariadb-10.2.9/sql/mysqld: unknown option '--loose-enable-rocksdb_lock_info'
 
2017-09-23 18:11:08 139752104999168 [Warning] /mnt/buildbot/build/mariadb-10.2.9/sql/mysqld: unknown variable 'loose-debug-sync-timeout=300'
 
2017-09-23 18:11:08 139752104999168 [Note] Server socket created on IP: '127.0.0.1'.
 
2017-09-23 18:11:08 139752104999168 [Note] /mnt/buildbot/build/mariadb-10.2.9/sql/mysqld: ready for connections.
 
Version: '10.2.9-MariaDB-log'  socket: '/mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/tmp/1/mysqld.1.sock'  port: 16000  MariaDB Server
 
2017-09-23 18:11:09 139751855527680 [Note] RocksDB: Manual memtable flush.
 
2017-09-23 18:13:33 139751855527680 [Note] RocksDB: Begin index creation (0,257)
 
170923 20:11:12 [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.2.9-MariaDB-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=1
 
max_threads=153
 
thread_count=2
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62992 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 0x49000
 
/usr/lib/x86_64-linux-gnu/libasan.so.2(+0x4a077)[0x7f1a9188b077]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(my_print_stacktrace+0xcc)[0x558e0e4e85dc]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(handle_fatal_signal+0x6ec)[0x558e0d5b5e9c]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f1a902b7390]
 
/lib/x86_64-linux-gnu/libc.so.6(__poll+0x2d)[0x7f1a8f94cb5d]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(_Z26handle_connections_socketsv+0x4b7)[0x558e0cf79347]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(_Z11mysqld_mainiPPc+0x41a8)[0x558e0cf87808]
 
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7f1a8f872830]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(_start+0x29)[0x558e0cf6ca59]
 
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.

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1218/steps/test_2/logs/stdio

rocksdb.bulk_load_rev_cf                 w2 [ fail ]  timeout after 7200 seconds
 
        Test ended at 2017-09-24 01:37:01
 
 
 
Test case timeout after 7200 seconds
 
 
 
== /mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/2/log/bulk_load_rev_cf.log == 
a CHAR(30),
 
b CHAR(30),
 
PRIMARY KEY(pk) COMMENT "rev:cf1",
 
KEY(a)
 
) COLLATE 'latin1_bin' PARTITION BY KEY() PARTITIONS 4;
 
connect  other,localhost,root,,;
 
set session transaction isolation level repeatable read;
 
select * from information_schema.rocksdb_dbstats where stat_type='DB_NUM_SNAPSHOTS';
 
STAT_TYPE	VALUE
 
DB_NUM_SNAPSHOTS	0
 
start transaction with consistent snapshot;
 
select * from information_schema.rocksdb_dbstats where stat_type='DB_NUM_SNAPSHOTS';
 
STAT_TYPE	VALUE
 
DB_NUM_SNAPSHOTS	1
 
connection default;
 
set rocksdb_bulk_load=1;
 
set rocksdb_bulk_load_size=100000;
 
LOAD DATA INFILE <input_file> INTO TABLE t1;
 
LOAD DATA INFILE <input_file> INTO TABLE t2;
 
LOAD DATA INFILE <input_file> INTO TABLE t3;
 
 
 
 == /mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/2/tmp/analyze-timeout-mysqld.1.err ==
 
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/tmp/2/mysqld.1' (111)

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1218/steps/test_2/logs/mysqld.1.err.2

CURRENT_TEST: rocksdb.bulk_load_rev_cf
 
2017-09-23 23:36:05 140244040525568 [Note] RocksDB: Manual memtable flush.
 
2017-09-23 23:36:05 140244040525568 [Note] RocksDB: creating a column family rev:cf1
 
2017-09-23 23:36:05 140244040525568 [Note]     write_buffer_size=67108864
 
2017-09-23 23:36:05 140244040525568 [Note]     target_file_size_base=67108864
 
170924  1:36:07 [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.2.9-MariaDB-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=2
 
max_threads=153
 
thread_count=3
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62992 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 0x49000
 
/usr/lib/x86_64-linux-gnu/libasan.so.2(+0x4a077)[0x7f8d2a0ce077]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(my_print_stacktrace+0xcc)[0x557a55fcd5dc]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(handle_fatal_signal+0x6ec)[0x557a5509ae9c]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f8d28afa390]
 
/lib/x86_64-linux-gnu/libc.so.6(__poll+0x2d)[0x7f8d2818fb5d]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(_Z26handle_connections_socketsv+0x4b7)[0x557a54a5e347]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(_Z11mysqld_mainiPPc+0x41a8)[0x557a54a6c808]
 
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7f8d280b5830]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(_start+0x29)[0x557a54a51a59]
 
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



 Comments   
Comment by Sergei Petrunia [ 2017-10-20 ]

On the latest 10.2 tree I get this:

rocksdb.add_index_inplace_sstfilewriter  [ pass ]  1229832

1,229,832 ms = 1229 sec = 20 min
This is a laptop, rotating disk and mtr is run without --mem.

Comment by Sergei Petrunia [ 2017-10-20 ] 

rocksdb.bulk_load_rev_cf                 [ pass ]  1104111

1104111 ms = 1,104 sec = ~20 minutes as well.

Comment by Sergei Petrunia [ 2017-10-20 ]

Running in-memory on a desktop doesn't help much:

rocksdb.add_index_inplace_sstfilewriter  [ pass ]  1035317

1,035,317 ms= 1,035 sec. = 17 min

Comment by Sergei Petrunia [ 2017-10-20 ]

Desktop machine and --mem:

rocksdb.bulk_load_rev_cf                 [ pass ]  1020817

1020817 = 17 min.

Comment by Sergei Petrunia [ 2017-10-20 ]

On a releaase build and --mem:

rocksdb.bulk_load_rev_cf                 [ pass ]  161932
 
rocksdb.add_index_inplace_sstfilewriter  [ pass ]  185647

So the tests take 2.6 min and 3.08 min respectively.

Comment by Sergei Petrunia [ 2017-10-22 ]

Still fails on current 10.2 in BB. http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1275/steps/test_2/logs/stdio.

rocksdb.add_index_inplace_sstfilewriter  w1 [ fail ]  timeout after 7200 seconds

When running a similar build locally (release +ASAN) and --mem, it passes in 733 seconds for me:

rocksdb.add_index_inplace_sstfilewriter  [ pass ]  733083

Comment by Sergei Petrunia [ 2017-10-22 ]

Taking another test for comparison, again from http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1275/steps/test_2/logs/stdio.

rocksdb.bulk_load_rev_cf                 w2 [ pass ]  6,077,539

On my machine (same release+ASAN build and --mem) I get:

rocksdb.bulk_load_rev_cf                 [ pass ]  715,123

Comment by Sergei Petrunia [ 2017-10-22 ]

Checking other execution time difference on the same pairs of machines:
http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1275/steps/test_2/logs/stdio
gives

main.log_tables-big                      w1 [ pass ]  163,080 -- psergey-desktop
 
main.log_tables-big                      [ pass ]  163,047    -- BB


main.sum_distinct-big 'innodb'           [ pass ]  194,068      -- psergey-desktop
 
main.sum_distinct-big 'innodb'           w1 [ pass ]  408,281  -- BB

Comment by Sergei Petrunia [ 2017-10-23 ]

So

  • for regular tests fulltest2 build is 1x-2x slower than my machine
  • but for MyRocks tests it is 8.5x slower
    not sure why is it so much slower for MyRocks.
Comment by Sergei Petrunia [ 2018-05-14 ]

add_index_inplace_sstfilewriter has been scaled down by me in

commit e5678c3fac27af7ca5a8503cccf1fdf3ad4f6fce
 
Author:	Sergei Petrunia <psergey@askmonty.org>  Sun Oct 29 13:21:23 2017
 
Committer:	Sergei Petrunia <psergey@askmonty.org>  Sun Oct 29 13:21:23 2017
 
 
 
MDEV-13904: rocksdb.add_index_inplace_sstfilewriter timed out

I wasn't able to find mentions of it timing out after that.

Comment by Sergei Petrunia [ 2018-05-14 ]

Down-scaled rocksdb.bulk_load* by 2x, too.
The tests are not run by the buildbot ATM so it is impossible to check if they started to work in BB

Generated at Thu Feb 08 08:09:19 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.