[MDEV-19395] Server fails to crash recover after being kill -9'd with RocksDB and binlog - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.2.21, 10.3.13
Fix Version/s: 10.2.26, 10.3.17, 10.3.18
Component/s: Storage Engine - RocksDB
Labels:
None

Description

Steps to reproduce:

Setup vanilla 10.2.21 and run it with bin-log and RocksDB enabled, i.e add to my.cnf

[mysqld]

plugin-load-add = 'ha_rocksdb'

log-bin = '/rdsdbdata/log/binlog/mysql-bin-changelog'

create database benchdb

start sysbench

first prepare

 sysbench --test=/usr/share/sysbench/tests/include/oltp_legacy/parallel_prepare.lua --mysql-port=3306 --db-driver=mysql --mysql-table-engine=rocksdb --oltp-tables-count=10 --oltp-table-size=250000 --num-threads=250 --mysql-user=root --mysql-db=benchdb  --mysql-host=127.0.0.1 run

then load

sysbench --db-driver=mysql --mysql-user=root --mysql-db=benchdb --mysql-table-engine=rocksdb --test=/usr/share/sysbench/tests/include/oltp_legacy/oltp.lua --mysql-host=127.0.0.1 --mysql-port=3306 --oltp-tables-count=10 --oltp-table-size=25000 --max-requests=0 --max-time=2000 --forced-shutdown --report-interval=1 --oltp_simple_ranges=0 --oltp-distinct-ranges=0 --oltp-sum-ranges=0 --oltp-order-ranges=0 --oltp-point-selects=0 --rand-type=uniform --num-threads=20  --oltp-skip-trx=0  --report-interval=10 run

wait 10-20 sec
kill -9 the server:
pkill -9 mysqld
try starting the server again

Actual result:
Server won't come up failing at RocksDB crash recovery. I observed at least 3 different error patterns in mysql error logs:

pthread lock: Invalid argument

190430 11:10:35 [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.3.13-MariaDB-log

key_buffer_size=16777216

read_buffer_size=262144

max_used_connections=0

max_threads=1259

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2945179 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 0x40000

/rdsdbbin/mysql/bin/mysqld(my_print_stacktrace+0x29)[0x55e144b2c8c9]

/rdsdbbin/mysql/bin/mysqld(handle_fatal_signal+0x57d)[0x55e1445f407d]

sigaction.c:0(__restore_rt)[0x2b500fc59100]

:0(__GI_raise)[0x2b500fe9b5f7]

:0(__GI_abort)[0x2b500fe9cce8]

/rdsdbbin/mariadb-10.3.13.R1/lib/plugin/ha_rocksdb.so(+0x186bf9)[0x2b5012986bf9]

/rdsdbbin/mariadb-10.3.13.R1/lib/plugin/ha_rocksdb.so(+0x4d4d85)[0x2b5012cd4d85]

/rdsdbbin/mariadb-10.3.13.R1/lib/plugin/ha_rocksdb.so(_ZN7rocksdb18GenericRateLimiterD1Ev+0x2b)[0x2b5012c7df8b]

/rdsdbbin/mariadb-10.3.13.R1/lib/plugin/ha_rocksdb.so(_ZN7rocksdb18GenericRateLimiterD0Ev+0x9)[0x2b5012c7e189]

/rdsdbbin/mariadb-10.3.13.R1/lib/plugin/ha_rocksdb.so(_ZN7rocksdb6DBImplD1Ev+0x460)[0x2b5012b03e20]

/rdsdbbin/mariadb-10.3.13.R1/lib/plugin/ha_rocksdb.so(_ZN7rocksdb6DBImplD0Ev+0x9)[0x2b5012b041e9]

/rdsdbbin/mariadb-10.3.13.R1/lib/plugin/ha_rocksdb.so(_ZN7rocksdb13TransactionDB4OpenERKNS_9DBOptionsERKNS_20TransactionDBOptionsERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKSt6vectorINS_22ColumnFamilyDescriptorESaISG_EEPSF_IPNS_18ColumnFamilyHandleESaISM_EEPPS0_+0xfd8)[0x2b5012ca93b8]

/rdsdbbin/mariadb-10.3.13.R1/lib/plugin/ha_rocksdb.so(+0x29824d)[0x2b5012a9824d]

/rdsdbbin/mysql/bin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x67)[0x55e1445f64f7]

sql/handler.cc:523(ha_initialize_handlerton(st_plugin_int*))[0x55e144437beb]

sql/sql_plugin.cc:1432(plugin_initialize)[0x55e144438d3a]

sql/sql_plugin.cc:1714(plugin_init(int*, char**, int))[0x55e144374081]

sql/mysqld.cc:5385(init_server_components)[0x55e14437a0e6]

/lib64/libc.so.6(__libc_start_main+0xf5)[0x2b500fe87b15]

/rdsdbbin/mysql/bin/mysqld(+0x5b5545)[0x55e14436d545]

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.

or

2019-05-04 21:01:06 140088851875648 [Note] RocksDB: Column Families at start:

2019-05-04 21:01:06 140088851875648 [Note]   cf=default

2019-05-04 21:01:06 140088851875648 [Note]     write_buffer_size=67108864

2019-05-04 21:01:06 140088851875648 [Note]     target_file_size_base=67108864

2019-05-04 21:01:06 140088851875648 [Note]   cf=__system__

2019-05-04 21:01:06 140088851875648 [Note]     write_buffer_size=67108864

2019-05-04 21:01:06 140088851875648 [Note]     target_file_size_base=67108864

190504 21:01:09 [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.21-MariaDB-log

key_buffer_size=16777216

read_buffer_size=262144

max_used_connections=0

max_threads=626

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1471373 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 0x40000

addr2line: 'rdsdbbin/mariadb-10.2.21.R1/bin/mysqld': No such file

rdsdbbin/mariadb-10.2.21.R1/bin/mysqld(my_print_stacktrace+0x29)[0x55e5e2c822c9]

rdsdbbin/mariadb-10.2.21.R1/bin/mysqld(handle_fatal_signal+0x57b)[0x55e5e272c28b]

sigaction.c:0(__restore_rt)[0x7f68f927b5d0]

[0x55e5e4ec7a9e]

2019-05-01  6:05:26 0 [Note]     write_buffer_size=67108864

2019-05-01  6:05:26 0 [Note]     target_file_size_base=67108864

2019-05-01  6:05:26 0 [Note]   cf=__system__

2019-05-01  6:05:26 0 [Note]     write_buffer_size=67108864

2019-05-01  6:05:26 0 [Note]     target_file_size_base=67108864

pthread lock: Invalid argument

190501  6:05:29 [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.3.13-MariaDB-log

key_buffer_size=16777216

read_buffer_size=262144

max_used_connections=0

max_threads=1259

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2945179 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 0x40000

/rdsdbbin/mysql/bin/mysqld(my_print_stacktrace+0x29)[0x55b6f333f8c9]

mysys/stacktrace.c:270(my_print_stacktrace)[0x55b6f2e0707d]

sigaction.c:0(__restore_rt)[0x2b1df6a5c100]

:0(__GI_raise)[0x2b1df6c9e5f7]

:0(__GI_abort)[0x2b1df6c9fce8]

port_posix.cc:0(rocksdb::port::PthreadCall(char const*, int) [clone .part.1])[0x2b1df9986bf9]

port/port_posix.cc:65(rocksdb::port::Mutex::Lock())[0x2b1df9cd4d85]

bits/stl_deque.h:356(std::_Deque_iterator<rocksdb::GenericRateLimiter::Req*, rocksdb::GenericRateLimiter::Req*&, rocksdb::GenericRateLimiter::Req**>::difference_type std::operator-<rocksdb::GenericRateLimiter::Req*, rocksdb::GenericRateL

imiter::Req*&, rocksdb::GenericRateLimiter::Req**>(std::_Deque_iterator<rocksdb::GenericRateLimiter::Req*, rocksdb::GenericRateLimiter::Req*&, rocksdb::GenericRateLimiter::Req**> const&, std::_Deque_iterator<rocksdb::GenericRateLimiter::

Req*, rocksdb::GenericRateLimiter::Reutil/rate_limiter.cc:90(rocksdb::GenericRateLimiter::~GenericRateLimiter())[0x2b1df9c7e189]

bits/unique_ptr.h:267(_ZNSt10unique_ptrIN7rocksdb11RateLimiterESt14default_deleteIS1_EED4Ev)[0x2b1df9b03e20]

db/db_impl.cc:460(rocksdb::DBImpl::~DBImpl())[0x2b1df9b041e9]

transactions/pessimistic_transaction_db.cc:219(rocksdb::TransactionDB::Open(rocksdb::DBOptions const&, rocksdb::TransactionDBOptions const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vec

tor<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::ColumnFamilyDescriptor> > const&, std::vector<rocksdb::ColumnFamilyHandle*, std::allocator<rocksdb::ColumnFamilyHandle*> >*, rocksdb::TransactionDB**))[0x2b1df9ca93b8]

rocksdb/ha_rocksdb.cc:5130(rocksdb_init_func)[0x2b1df9a9824d]

/rdsdbbin/mysql/bin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x67)[0x55b6f2e094f7]

sql/handler.cc:523(ha_initialize_handlerton(st_plugin_int*))[0x55b6f2c4abeb]

sql/sql_plugin.cc:1432(plugin_initialize)[0x55b6f2c4bd3a]

sql/sql_plugin.cc:1714(plugin_init(int*, char**, int))[0x55b6f2b87081]

sql/mysqld.cc:5385(init_server_components)[0x55b6f2b8d0e6]

/lib64/libc.so.6(__libc_start_main+0xf5)[0x2b1df6c8ab15]

/rdsdbbin/mysql/bin/mysqld(+0x5b5545)[0x55b6f2b80545]

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.

2019-05-01  6:06:42 0 [Note] RocksDB: 2 column families found

2019-05-01  6:06:42 0 [Note] RocksDB: Column Families at start:

2019-05-01  6:06:42 0 [Note]   cf=default

2019-05-01  6:06:42 0 [Note]     write_buffer_size=67108864

2019-05-01  6:06:42 0 [Note]     target_file_size_base=67108864

2019-05-01  6:06:42 0 [Note]   cf=__system__

2019-05-01  6:06:42 0 [Note]     write_buffer_size=67108864

2019-05-01  6:06:42 0 [Note]     target_file_size_base=67108864

pthread lock: Invalid argument

Removing "log-bin" from my.cnf makes issue go away. Verified on both 10.2.21 and 10.3.13

Attachments

Issue Links

is blocked by

MDEV-19397 rocksdb is not crash safe with binlog on

Closed

MDEV-19795 Merge upstream MyRocks: June 2019

Closed

is duplicated by

MDEV-18246 MyRocks ColumnFamilySet(): Assertion `last_ref' failed on MariaDB startup

Closed

Server fails to crash recover after being kill -9'd with RocksDB and binlog

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration