maria-discuss team mailing list archive

[Jonas Krauss <jkrauss82@xxxxxxxxx>]

I did some more research yesterday and found out a little more about what
is going on:
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.

The MariaDB process exits with a buffer overflow message. I omitted that in
my initial post, however it is probably important:

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

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

Am Mo., 14. Jan. 2019 um 09:24 Uhr schrieb Jonas Krauss <jkrauss82@xxxxxxxxx
>:

> Hi all,
>
> 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 stops with (seemingly most useful output set to bold):
>
> 2019-01-14  9:07:47 139766003611904 [Note] RocksDB: 2 column families found
> 2019-01-14  9:07:47 139766003611904 [Note] RocksDB: Column Families at
> start:
> 2019-01-14  9:07:47 139766003611904 [Note]   cf=default
> 2019-01-14  9:07:47 139766003611904 [Note]     write_buffer_size=134217728
> 2019-01-14  9:07:47 139766003611904 [Note]
>  target_file_size_base=268435456
> 2019-01-14  9:07:47 139766003611904 [Note]   cf=__system__
> 2019-01-14  9:07:47 139766003611904 [Note]     write_buffer_size=134217728
> 2019-01-14  9:07:47 139766003611904 [Note]
>  target_file_size_base=268435456
> mysqld:
> /home/buildbot/buildbot/build/mariadb-10.2.18/storage/rocksdb/rocksdb/db/column_family.cc:1238:
> *rocksdb::ColumnFamilySet::~ColumnFamilySet(): Assertion `last_ref'
> failed.*
> 190114  9:07:58 [ERROR] mysqld got signal 6 ;
> ...
>
> The rest is a memory dump seemingly not too helpful(?). 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.
>
> *Version and OS infos*:
> MariaDB version: 10.2.18-MariaDB-10.2.18+maria~stretch-log
> Running on Debian Linux version 4.9.0-8-amd64 (
> debian-kernel@xxxxxxxxxxxxxxxx) (gcc version 6.3.0 20170516 (Debian
> 6.3.0-18+deb9u1) ) #1 SMP Debian 4.9.110-3+deb9u6 (2018-10-08)
> We use *jemalloc* as memory allocator.
> 64GB RAM machine with RAID1 SSD 256GB for logs and 10TB HDD for tables
>
> 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
>
> Does anyone have a idea what could cause this crash? 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
>
> Any help is greatly appreciated.
>
> Best regards
>
> Jonas
>
>