Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-19395

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

    Details

      Description

      Steps to reproduce:

      1. 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'
        

      2. create database benchdb
      3. start sysbench
        1. 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
          

        2. 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
          

      4. wait 10-20 sec
      5. kill -9 the server:

        pkill -9 mysqld
        

      6. 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

            Activity

              People

              • Assignee:
                psergey Sergei Petrunia
                Reporter:
                apol Anton Polyakov
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: