Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Duplicate
-
10.2.18, 10.2.21
-
Debian Linux version 4.9.0-8-amd64 (debian-kernel@lists.debian.org) (gcc version 6.3.0 20170516 (Debian 6.3.0-18+deb9u1) ) #1 SMP Debian 4.9.110-3+deb9u6 (2018-10-08)
jemalloc
64GB RAM machine with RAID1 SSD 256GB for logs and 10TB HDD for tables
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
Issue Links
- duplicates
-
-
- Closed
-
- is blocked by
-
MDEV-19795 Merge upstream MyRocks: June 2019
-
- Closed
-