Rocksdb: core dump when opening many rocksdb database files

[gaojieliu]

I was using the debug version of the latest code of master branch, and this core dump happened when opening a lot of database files, and we didn't see this issue with 5.15.10, and we started seeing this issue from 5.17.2.

Here is the stacktrace:

#0  0x00007fc71ee4e207 in raise () from /usr/lib64/libc.so.6
#1  0x00007fc71ee4f8f8 in abort () from /usr/lib64/libc.so.6
#2  0x00007fc5049d97d5 in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib64/libstdc++.so.6
#3  0x00007fc5049d7746 in ?? () from /usr/lib64/libstdc++.so.6
#4  0x00007fc5049d7773 in std::terminate() () from /usr/lib64/libstdc++.so.6
#5  0x00007fc5049d7993 in __cxa_throw () from /usr/lib64/libstdc++.so.6
#6  0x00007fc504a2cc70 in std::__throw_system_error(int) () from /usr/lib64/libstdc++.so.6
#7  0x00007fc504a2e3a9 in std::thread::_M_start_thread(std::shared_ptr<std::thread::_Impl_base>) () from /usr/lib64/libstdc++.so.6
#8  0x00007fc4b76c5ed4 in std::thread::thread<std::function<void ()>&>(std::function<void ()>&) (this=0x7fba60346628, __f=...)
    at /usr/include/c++/4.8.2/thread:135
#9  0x00007fc4b76c554a in __gnu_cxx::new_allocator<std::thread>::construct<std::thread<std::function<void ()>&> > (this=0x7fc71fa27420, 
    __p=0x7fba60346628) at /usr/include/c++/4.8.2/ext/new_allocator.h:120
#10 0x00007fc4b76c414b in std::allocator_traits<std::allocator<std::thread> >::_S_construct<std::thread<std::function<void ()>&> >(std::allocator<std::thread>&, std::allocator_traits<std::allocator<std::thread> >::__construct_helper*, (std::thread<std::function<void ()>&>&&)...) (__a=..., 
    __p=0x7fba60346628) at /usr/include/c++/4.8.2/bits/alloc_traits.h:254
#11 0x00007fc4b76c296b in std::allocator_traits<std::allocator<std::thread> >::construct<std::thread<std::function<void ()>&> >(std::allocator<std::thread>&, std::thread<std::function<void ()>&>*, (std::thread<std::function<void ()>&>&&)...) (__a=..., __p=0x7fba60346628)
    at /usr/include/c++/4.8.2/bits/alloc_traits.h:393
#12 0x00007fc4b76c1965 in std::vector<std::thread, std::allocator<std::thread> >::emplace_back<std::function<void ()>&>(std::function<void ()>&) (
    this=0x7fc71fa27420) at /usr/include/c++/4.8.2/bits/vector.tcc:96
#13 0x00007fc4b76c0c5d in rocksdb::VersionBuilder::Rep::LoadTableHandlers (this=0x7fba60347ca0, internal_stats=0x7fba603478d0, max_threads=16, 
    prefetch_index_and_filter_in_cache=false, is_initial_load=true, prefix_extractor=0x0) at db/version_builder.cc:479
#14 0x00007fc4b76bdf47 in rocksdb::VersionBuilder::LoadTableHandlers (this=0x7fba60347c80, internal_stats=0x7fba603478d0, max_threads=16, 
    prefetch_index_and_filter_in_cache=false, is_initial_load=true, prefix_extractor=0x0) at db/version_builder.cc:536
#15 0x00007fc4b76e1ebd in rocksdb::VersionSet::Recover (this=0x7fba6033cec0, column_families=std::vector of length 1, capacity 1 = {...}, 
    read_only=false, db_id=0x7fba60335498) at db/version_set.cc:4494
#16 0x00007fc4b7605610 in rocksdb::DBImpl::Recover (this=0x7fba60335480, column_families=std::vector of length 1, capacity 1 = {...}, 
    read_only=false, error_if_log_file_exist=false, error_if_data_exists_in_logs=false) at db/db_impl/db_impl_open.cc:403
#17 0x00007fc4b760b387 in rocksdb::DBImpl::Open (db_options=..., dbname="/mnt/u001/venice/data/rocksdb/StylizedGeoNames_v15/StylizedGeoNames_v15_19", 
    column_families=std::vector of length 1, capacity 1 = {...}, handles=0x7fc71fa29990, dbptr=0x7fc71fa29fa8, seq_per_batch=false, 
    batch_per_txn=true) at db/db_impl/db_impl_open.cc:1383
#18 0x00007fc4b760a901 in rocksdb::DB::Open (db_options=..., dbname="/mnt/u001/venice/data/rocksdb/StylizedGeoNames_v15/StylizedGeoNames_v15_19", 
    column_families=std::vector of length 1, capacity 1 = {...}, handles=0x7fc71fa29990, dbptr=0x7fc71fa29fa8) at db/db_impl/db_impl_open.cc:1277
#19 0x00007fc4b760a6a5 in rocksdb::DB::Open (options=..., dbname="/mnt/u001/venice/data/rocksdb/StylizedGeoNames_v15/StylizedGeoNames_v15_19", 
    dbptr=0x7fc71fa29fa8) at db/db_impl/db_impl_open.cc:1254
#20 0x00007fc4b74ab0b0 in std::_Function_handler<rocksdb::Status (rocksdb::Options const&, std::string const&, rocksdb::DB**), rocksdb::Status (*)(rocksdb::Options const&, std::string const&, rocksdb::DB**)>::_M_invoke(std::_Any_data const&, rocksdb::Options const&, std::string const&, rocksdb::DB**)
    (__functor=..., __args#0=..., __args#1="/mnt/u001/venice/data/rocksdb/StylizedGeoNames_v15/StylizedGeoNames_v15_19", __args#2=0x7fc71fa29fa8)
    at /usr/include/c++/4.8.2/functional:2057
#21 0x00007fc4b74a7d00 in std::function<rocksdb::Status (rocksdb::Options const&, std::string const&, rocksdb::DB**)>::operator()(rocksdb::Options const&, std::string const&, rocksdb::DB**) const (this=0x7fc71fa2a010, __args#0=..., 
    __args#1="/mnt/u001/venice/data/rocksdb/StylizedGeoNames_v15/StylizedGeoNames_v15_19", __args#2=0x7fc71fa29fa8)
---Type <return> to continue, or q <return> to quit---
    at /usr/include/c++/4.8.2/functional:2471
#22 0x00007fc4b749a243 in rocksdb_open_helper(JNIEnv_*, long, _jstring*, std::function<rocksdb::Status (rocksdb::Options const&, std::string const&, rocksdb::DB**)>) (env=0x7fc7180151e0, jopt_handle=140438453816160, jdb_path=0x7fc71fa2a058, open_fn=...) at java/rocksjni/rocksjni.cc:44
#23 0x00007fc4b749a347 in Java_org_rocksdb_RocksDB_open__JLjava_lang_String_2 (env=0x7fc7180151e0, jopt_handle=140438453816160, 
    jdb_path=0x7fc71fa2a058) at java/rocksjni/rocksjni.cc:67

Let me know if you want me to extract info for any frame.

[gaojieliu]

@siying
Can you or ask someone else take a look at this issue?
This is a serious issue from my understanding.

[ltamasi]

I'm assuming you're running out of threads. This is just a stab in the dark but I think this could potentially be related to a change in 5.17.2 that creates a default SstFileManager for each database unless one is provided by the user in DBOptions (Cc @anand1976 to make sure I got that right). As a workaround, you could try creating an SstFileManager yourself in your application code, and using that single object for all the databases you open.

EDIT: For the record, I was thinking about this commit: https://github.com/facebook/rocksdb/commit/a27fce408e197f68d4d4a613aefc1d84b9a57058.

[anand1976]

Yes, a default SstFileManager object is created, which creates a DeleteScheduler object which in turn creates a background thread to handle file deletion. How many database instances are you opening in one process, and what is your max open files limit (i.e ulimit -n?

[gaojieliu]

@ltamasi
I was thinking about the same max-thread problem, but after I bumping it up to 163570, and the issue is still there.

@anand1976
There are many (10k+) databases in one instances.
ulimit -n is 4M
With version: 5.15.10, there is no crashing issue in the same instance, which seems to be wired if it is caused by the max open file limit issue with 5.17.2.

Is SstFileManager option available in java wrapper?

[ltamasi]

Is SstFileManager option available in java wrapper?

Seems so, see setSstFileManager in DBOptions.java.

Again, this is just a hunch, but if you open 10k+ databases in a single process, 5.17.2 would attempt to launch 10k+ threads (unless you share an SstFileManager between them per the above).

[gaojieliu]

@ltamasi
Make sense, since I did see a lot of threads got created with the new version.
I will try to reuse the same SstFileManager across all the databases.

Thanks a lot.

[gaojieliu]

@ltamasi
I was using the following code to setup Options:

Options newOptions = new Options();
    newOptions.setEnv(this.env);
    newOptions.setCreateIfMissing(true);
    newOptions.setWriteBufferManager(writeBufferManager);
    newOptions.setSstFileManager(sstFileManager);

The sstFileManager is shared by all the databases.

But rocksdb still crashed with the same stack (many threads), and here is the stacktrace of one thread:

(gdb) thread 4895
[Switching to thread 4895 (Thread 0x7fc2b1682700 (LWP 27928))]
#0  0x00007fc71f60ad12 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/lib64/libpthread.so.0
(gdb) bt
#0  0x00007fc71f60ad12 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/lib64/libpthread.so.0
#1  0x00007fc4b77d8d03 in rocksdb::port::CondVar::TimedWait (this=0x7fc371aa1128, abs_time_us=1575601756833723)
    at port/port_posix.cc:120
#2  0x00007fc4b77816db in rocksdb::InstrumentedCondVar::TimedWaitInternal (this=0x7fc371aa1128, abs_time_us=1575601756833723)
    at monitoring/instrumented_mutex.cc:66
#3  0x00007fc4b7781625 in rocksdb::InstrumentedCondVar::TimedWait (this=0x7fc371aa1128, abs_time_us=1575601756833723)
    at monitoring/instrumented_mutex.cc:55
#4  0x00007fc4b75a5263 in rocksdb::RepeatableThread::wait (this=0x7fc371aa10a0, delay=600000000)
    at ./util/repeatable_thread.h:90
#5  0x00007fc4b75a5416 in rocksdb::RepeatableThread::thread (this=0x7fc371aa10a0) at ./util/repeatable_thread.h:117
#6  0x00007fc4b75a4f13 in rocksdb::RepeatableThread::RepeatableThread(std::function<void ()>, std::string const&, rocksdb::Env*, unsigned long, unsigned long)::{lambda()#1}::operator()() const (__closure=0x7fc371aa0e10) at ./util/repeatable_thread.h:38
#7  0x00007fc4b75cafc0 in std::_Bind_simple<rocksdb::RepeatableThread::RepeatableThread(std::function<void ()>, std::string const&, rocksdb::Env*, unsigned long, unsigned long)::{lambda()#1} ()>::_M_invoke<>(std::_Index_tuple<>) (this=0x7fc371aa0e10)
    at /usr/include/c++/4.8.2/functional:1732
#8  0x00007fc4b75caf17 in std::_Bind_simple<rocksdb::RepeatableThread::RepeatableThread(std::function<void ()>, std::string const&, rocksdb::Env*, unsigned long, unsigned long)::{lambda()#1} ()>::operator()() (this=0x7fc371aa0e10)
    at /usr/include/c++/4.8.2/functional:1720
#9  0x00007fc4b75caeb0 in std::thread::_Impl<std::_Bind_simple<rocksdb::RepeatableThread::RepeatableThread(std::function<void ()>, std::string const&, rocksdb::Env*, unsigned long, unsigned long)::{lambda()#1} ()> >::_M_run() (this=0x7fc371aa0df8)
    at /usr/include/c++/4.8.2/thread:115
#10 0x00007fc504a2e070 in ?? () from /usr/lib64/libstdc++.so.6
#11 0x00007fc71f606dd5 in start_thread () from /usr/lib64/libpthread.so.0
#12 0x00007fc71ef15ead in clone () from /usr/lib64/libc.so.6

Maybe the java implementation didn't take care of the shared SstFileManager, could you share more insights?

[ltamasi]

No, I think you've hit a similar but separate issue: the threads that periodically dump and persist statistics are also per-database, and AFAIK there is no way to share them currently (sigh). (These are the only places in the code where RepeatableThreads are used I believe.)

As a workaround, you could try setting these two in DBOptions to zero:

  // if not zero, dump rocksdb.stats to LOG every stats_dump_period_sec
  //
  // Default: 600 (10 min)
  //
  // Dynamically changeable through SetDBOptions() API.
  unsigned int stats_dump_period_sec = 600;

  // if not zero, dump rocksdb.stats to RocksDB every stats_persist_period_sec
  // Default: 600
  unsigned int stats_persist_period_sec = 600;

[gaojieliu]

@ltamasi
I tried to set stats_dump_period_sec to be 0, but in RocksDB Java wrapper, there seems no way to set stats_persist_period_sec, so I still ran into too many thread issue, and the stack trace is exactly same as before:

0  0x00007f3343042d12 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/lib64/libpthread.so.0
#1  0x00007f30db7d8d03 in rocksdb::port::CondVar::TimedWait (this=0x7f2c8d629228, abs_time_us=1575954306169261)
    at port/port_posix.cc:120
#2  0x00007f30db7816db in rocksdb::InstrumentedCondVar::TimedWaitInternal (this=0x7f2c8d629228, abs_time_us=1575954306169261)
    at monitoring/instrumented_mutex.cc:66
#3  0x00007f30db781625 in rocksdb::InstrumentedCondVar::TimedWait (this=0x7f2c8d629228, abs_time_us=1575954306169261)
    at monitoring/instrumented_mutex.cc:55
#4  0x00007f30db5a5263 in rocksdb::RepeatableThread::wait (this=0x7f2c8d6291a0, delay=600000000)
    at ./util/repeatable_thread.h:90
#5  0x00007f30db5a5416 in rocksdb::RepeatableThread::thread (this=0x7f2c8d6291a0) at ./util/repeatable_thread.h:117
#6  0x00007f30db5a4f13 in rocksdb::RepeatableThread::RepeatableThread(std::function<void ()>, std::string const&, rocksdb::Env*, unsigned long, unsigned long)::{lambda()#1}::operator()() const (__closure=0x7f2c8d629190) at ./util/repeatable_thread.h:38
#7  0x00007f30db5cafc0 in std::_Bind_simple<rocksdb::RepeatableThread::RepeatableThread(std::function<void ()>, std::string const&, rocksdb::Env*, unsigned long, unsigned long)::{lambda()#1} ()>::_M_invoke<>(std::_Index_tuple<>) (this=0x7f2c8d629190)
    at /usr/include/c++/4.8.2/functional:1732
#8  0x00007f30db5caf17 in std::_Bind_simple<rocksdb::RepeatableThread::RepeatableThread(std::function<void ()>, std::string const&, rocksdb::Env*, unsigned long, unsigned long)::{lambda()#1} ()>::operator()() (this=0x7f2c8d629190)
    at /usr/include/c++/4.8.2/functional:1720
#9  0x00007f30db5caeb0 in std::thread::_Impl<std::_Bind_simple<rocksdb::RepeatableThread::RepeatableThread(std::function<void ()>, std::string const&, rocksdb::Env*, unsigned long, unsigned long)::{lambda()#1} ()> >::_M_run() (this=0x7f2c8d629178)
    at /usr/include/c++/4.8.2/thread:115
#10 0x00007f3130498070 in ?? () from /usr/lib64/libstdc++.so.6
#11 0x00007f334303edd5 in start_thread () from /usr/lib64/libpthread.so.0
#12 0x00007f334294dead in clone () from /usr/lib64/libc.so.6

Let me know if there is some way to disable it through RocksDB Java wrapper.

[ltamasi]

Based on my reading of the code, you should be able to set it using the setDBOptions API right after you open the database, which would shut down the background thread. (This would help assuming you're opening those 10k database consecutively as opposed to concurrently.) Otherwise, I don't think there is a way to set it through the Java API currently.

[gaojieliu]

@ltamasi
I don't think it is possible to set stats_persist_period_sec to be 0 through setDBOptions API right after opening the database since that option is not available in Java API.
I could definitely set stats_dump_period_sec through Options object.
I tried to use a debug version of rocksdb jar to set the default value of stats_persist_period_sec to be 0, the crashing issue was gone.
So the root cause is the stats thread per database.

Is it possible to add Java API to mutate stats_persist_period_sec through Options and DBOptions?

Thanks

[ltamasi]

I was thinking about using the API that enables you to dynamically set mutable options by name. @adamretter, could you confirm if that's available through the Java API? (My cursory reading of the Java code suggests so.) If not, that leaves adding the missing code to the Java wrapper. @adamretter, would you be able to help with that?

[gaojieliu]

@adamretter
Could you help prioritize this ask? and let us know if you need more details.
We were thinking to contribute this feature if RocksDB team doesn't have time to work on it, and the code change could be simply enough for the new committers.

[adamretter]

@gaojieliu sure, here you go - https://github.com/facebook/rocksdb/pull/6152

@ltamasi you can set mutable config options by name in the Java API, but they need to be known to the Java API first.

[gaojieliu]

@adamretter
Thanks a lot for the quick turn-around!
The code change looks good to me, and hope you could merge it and cut a new release soon, since it is a big blocker for us to upgrade to the latest RocksDB release.

@ltamasi
Thanks a lot for your help to debug this crashing issue.
In the long run, it seems to be reasonable to share the stats threads across all the databases, otherwise, the stats dumping logic won't scale if one instance hosts a lot of databases like us.

[adamretter]

@gaojieliu I expect it will be merged soon. You would need to ask @gfosco or @pdillinger about the release schedule

[gaojieliu]

@adamretter
Sounds good.
I will sync up with them once this gets merged.