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

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

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 10.2.18, 10.2.21
    • Fix Version/s: 10.2
    • Labels:
    • Environment:

      Description

      We had a database setup running in production for quite some time (> 5 months) and it crashed during last weekend without obvious reason. MariaDB error log shows this on startup of the server:

      2019-01-15 10:07:21 140060699941120 [Note] RocksDB: 2 column families found
      2019-01-15 10:07:21 140060699941120 [Note] RocksDB: Column Families at start:
      2019-01-15 10:07:21 140060699941120 [Note]   cf=default
      2019-01-15 10:07:21 140060699941120 [Note]     write_buffer_size=134217728
      2019-01-15 10:07:21 140060699941120 [Note]     target_file_size_base=268435456
      2019-01-15 10:07:21 140060699941120 [Note]   cf=__system__
      2019-01-15 10:07:21 140060699941120 [Note]     write_buffer_size=134217728
      2019-01-15 10:07:21 140060699941120 [Note]     target_file_size_base=268435456
      mysqld: /home/buildbot/buildbot/build/mariadb-10.2.21/storage/rocksdb/rocksdb/db/column_family.cc:1238: rocksdb::ColumnFamilySet::~ColumnFamilySet(): Assertion `last_ref' failed.
      190115 10:07:32 [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.21-MariaDB-10.2.21+maria~stretch-log
      key_buffer_size=134217728
      read_buffer_size=131072
      max_used_connections=0
      max_threads=3002
      thread_count=0
      It is possible that mysqld could use up to 
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6727382 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 0x30000
      *** buffer overflow detected ***: /usr/sbin/mysqld terminated
      ======= Backtrace: =========
      /lib/x86_64-linux-gnu/libc.so.6(+0x70bfb)[0x7f626a34ebfb]
      /lib/x86_64-linux-gnu/libc.so.6(__fortify_fail+0x37)[0x7f626a3d71f7]
      /lib/x86_64-linux-gnu/libc.so.6(+0xf7330)[0x7f626a3d5330]
      /lib/x86_64-linux-gnu/libc.so.6(+0xf916a)[0x7f626a3d716a]
      /usr/sbin/mysqld(my_addr_resolve+0xe2)[0x55c80b8c0e82]
      /usr/sbin/mysqld(my_print_stacktrace+0x1bb)[0x55c80b8a773b]
      /usr/sbin/mysqld(handle_fatal_signal+0x41d)[0x55c80b346c7d]
      /lib/x86_64-linux-gnu/libpthread.so.0(+0x110c0)[0x7f626be7c0c0]
      /lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7f626a310fff]
      /lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f626a31242a]
      /lib/x86_64-linux-gnu/libc.so.6(+0x2be67)[0x7f626a309e67]
      /lib/x86_64-linux-gnu/libc.so.6(+0x2bf12)[0x7f626a309f12]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb15ColumnFamilySetD1Ev+0x1de)[0x7f61de475b0e]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb10VersionSetD1Ev+0x4d)[0x7f61de3205cd]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb6DBImpl11CloseHelperEv+0x647)[0x7f61de260627]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb6DBImplD1Ev+0x69d)[0x7f61de26fa1d]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb6DBImplD0Ev+0x11)[0x7f61de26fa81]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb24PessimisticTransactionDBD2Ev+0x32c)[0x7f61de42e06c]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb19WriteCommittedTxnDBD0Ev+0x1f)[0x7f61de4346df]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb13TransactionDB6WrapDBEPNS_2DBERKNS_20TransactionDBOptionsERKSt6vectorImSaImEERKS6_IPNS_18ColumnFamilyHandleESaISC_EEPPS0_+0x12a)[0x7f61de430e3a]
      /usr/lib/mysql/plugin/ha_rocksdb.so(_ZN7rocksdb13TransactionDB4OpenERKNS_9DBOptionsERKNS_20TransactionDBOptionsERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKSt6vectorINS_22ColumnFamilyDescriptorESaISG_EEPSF_IPNS_18ColumnFamilyHandleESaISM_EEPPS0_+0x1341)[0x7f61de432251]
      /usr/lib/mysql/plugin/ha_rocksdb.so(+0x20e556)[0x7f61de201556]
      /usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x62)[0x55c80b3490a2]
      /usr/sbin/mysqld(+0x4cdf75)[0x55c80b1bbf75]
      /usr/sbin/mysqld(_Z11plugin_initPiPPci+0x7da)[0x55c80b1bd62a]
      /usr/sbin/mysqld(+0x427e7c)[0x55c80b115e7c]
      /usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x1d48)[0x55c80b11add8]
      /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)[0x7f626a2fe2e1]
      /usr/sbin/mysqld(_start+0x2a)[0x55c80b10e40a]
      ======= Memory map: ========
      55c80acee000-55c80bdcb000 r-xp 00000000 09:02 8528713                    /usr/sbin/mysqld
      55c80bfca000-55c80c09a000 r--p 010dc000 09:02 8528713                    /usr/sbin/mysqld
      55c80c09a000-55c80c151000 rw-p 011ac000 09:02 8528713                    /usr/sbin/mysqld
      ...
      

      We tried the various recovery modes of rocksdb_wal_recovery_mode (0,2,3) but none seems to have any effect, the output in the log is exactly the same.

      Here is the rocksdb config part of the my.cnf:

      plugin-load-add					= ha_rocksdb.so
      default-storage-engine				= rocksdb
      rocksdb_unsafe_for_binlog			= 1 # enables statement based replication
      rocksdb_datadir					= /var/local/mysql/rocksdb
      rocksdb_wal_dir					= /var/mysql_logs/rocksdb
      rocksdb_tmpdir					= /var/mysql_logs/rocksdb
      rocksdb_flush_log_at_trx_commit			= 0
      rocksdb_use_direct_io_for_flush_and_compaction	= 0
      rocksdb_use_direct_reads			= 0
      rocksdb_max_open_files				= -1
      rocksdb_max_background_jobs			= 8
      rocksdb_max_total_wal_size			= 4G
      rocksdb_block_size				= 64K
      rocksdb_block_cache_size			= 16G
      rocksdb_table_cache_numshardbits		= 6
      rocksdb_new_table_reader_for_compaction_inputs	= 1
      rocksdb_compaction_readahead_size		= 4M
      #rocksdb_db_write_buffer_size			= 0 # max write buffer across all column families, zero = disabled
      #rocksdb_wal_recovery_mode			= 1
      rocksdb_bytes_per_sync				= 4M
      rocksdb_wal_bytes_per_sync			= 4M
      rocksdb_rate_limiter_bytes_per_sec		= 80M # MB/s. Increase if you're running on higher spec machines
      rocksdb_compaction_sequential_deletes_count_sd	= 1
      rocksdb_compaction_sequential_deletes		= 199999
      rocksdb_compaction_sequential_deletes_window	= 200000
      #rocksdb_rpl_lookup_rows=0
      rocksdb_default_cf_options=write_buffer_size=128m;max_write_buffer_number=4;target_file_size_base=256m;max_bytes_for_level_base=2560m;target_file_size_multiplier=2;level0_file_num_compaction_trigger=4;level0_slowdown_writes_trigger=10;level0_stop_writes_trigger=15;compression=kSnappyCompression;bottommost_compression=kZlibCompression;compression_opts=-14:1:0;block_based_table_factory={cache_index_and_filter_blocks=1;filter_policy=bloomfilter:10:false;whole_key_filtering=1};level_compaction_dynamic_level_bytes=true;optimize_filters_for_hits=true;compaction_pri=kMinOverlappingRatio
      

      Google did not return helpful results, most similar thing anyone had is this in my search: https://github.com/facebook/mysql-5.6/issues/391

      Checking the rocksdb log it seems that the recovery phase is successfully completed, yet the rocksdb engine receives a shutdown signal from the MariaDB process. The log does not show any error message just before it goes into shutdown, so my best guess is that the shutdown signal is not internally produced but comes from MariaDB). Here is the regarding log:

      ...
      Recovering log #70212 mode 1
      2019/01/14-17:57:35.828286 7fd584e99900 [/home/buildbot/buildbot/build/mariadb-10.2.21/storage/rocksdb/rocksdb/db/db_impl_open.cc:552] Recovering log #70215 mode 1
      2019/01/14-17:57:35.828310 7fd584e99900 [/home/buildbot/buildbot/build/mariadb-10.2.21/storage/rocksdb/rocksdb/db/db_impl_open.cc:552] Recovering log #70218 mode 1
      2019/01/14-17:57:35.828642 7fd584e99900 [/home/buildbot/buildbot/build/mariadb-10.2.21/storage/rocksdb/rocksdb/db/version_set.cc:2854] Creating manifest 70220
      2019/01/14-17:57:35.937947 7fd584e99900 [WARN] [/home/buildbot/buildbot/build/mariadb-10.2.21/storage/rocksdb/rocksdb/db/version_set.cc:2496] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
      2019/01/14-17:57:35.979604 7fd584e99900 EVENT_LOG_v1 {"time_micros": 1547485055979597, "job": 1, "event": "recovery_finished"}
      2019/01/14-17:57:35.992961 7fd584e99900 [/home/buildbot/buildbot/build/mariadb-10.2.21/storage/rocksdb/rocksdb/db/db_impl_files.cc:477] [JOB 2] Delete info log file /var/local/mysql/rocksdb//LOG.old.1547441122341707
      2019/01/14-17:57:36.059847 7fd584e99900 [/home/buildbot/buildbot/build/mariadb-10.2.21/storage/rocksdb/rocksdb/db/db_impl_open.cc:1221] DB pointer 0x7fd4fea2ae00
      2019/01/14-17:57:38.210653 7fd584e99900 [/home/buildbot/buildbot/build/mariadb-10.2.21/storage/rocksdb/rocksdb/db/db_impl.cc:295] Shutdown: canceling all background work
      

      Another observation is that rocksdb created ~6600 wal files in the regarding folder, yet most of them are just empty files. Only about 50 files are filled with content up to the point in time the crash occurred. So maybe something is wrong here. We have ~2500 files in the rocksdb datadir, a couply of them are also log files which correspond to files created in the wal dir.

      I have the feeling the high number of files and the assertion failure might be connected, but it is just a guess. I could imagine that it is actually just a configuration problem which results in too many files being opened simultaneously leading to the assertion failure, just guessing wildly here.

      I increased hard and soft limits for open files to 20000 for the mysql user, however this did not solve the problem. I also tried setting a limit to rocksdb max open files, this changed the error message in the MariaDB log, however it still failed with the same assertion failure but not with a buffer overflow anymore. I upgraded MariaDB from 10.2.18 to 10.2.21 but this did not solve the problem either.

      I am happy to provide more details on request or to try out other things. Any support or ideas are greatly appreciated.

        Attachments

        1. mariadb.log
          19 kB
        2. my.cnf
          6 kB
        3. rocksdb.log
          1.17 MB

          Issue Links

            Activity

              People

              • Assignee:
                psergey Sergei Petrunia
                Reporter:
                jkrauss Jonas Krauss
              • Votes:
                4 Vote for this issue
                Watchers:
                6 Start watching this issue

                Dates

                • Created:
                  Updated: