facebook / facebook/rocksdb

RocksJava: Write stalls throwing exception instead of blocking

Open
#6,625 15 comments 0 reactions 0 assignees View on GitHub
java-api
Dominant language
C++
Stars
32.1k
Forks
6.9k
Avg merge
32m
Merged PRs (30d)
1

Description

> Note: Please use Issues only for bug reports. For questions, discussions, feature requests, etc. post to dev group: https://groups.google.com/forum/#!forum/rocksdb or https://www.facebook.com/groups/rocksdb.dev

I tried searching in github issue history, the facebook group, and the google mail group, and couldn't find anything so far.

### Expected behavior
Hello, I'm using RocksDB via Java. I see Write Stalls in the logs. As I understand I expect RocksDB to block my writer thread when stalls happen. However, I get a RocksDBException instead, and I'm assuming the write is lost?

### Actual behavior
Exception is thrown:
```
[ 03-24T16:15:23 ERROR ] encountered RocksDB error
org.rocksdb.RocksDBException: Write stall
at org.rocksdb.RocksDB.write0(Native Method) ~[kafka-control-2.0.24-SNAPSHOT-shaded.jar:?]
at org.rocksdb.RocksDB.write(RocksDB.java:1421) ~[kafka-control-2.0.24-SNAPSHOT-shaded.jar:?]
at com.booking.sherlock.store.RocksKVStore$WriteBatchRunnable.run(RocksKVStore.java:107) [kafka-control-2.0.24-SNAPSHOT-shaded.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]
```

### Steps to reproduce the behavior

I'm using a single WriterThread to write WriteBatches to RocksDB 6.6.4. The abbreviated code I'm running in a Java Runnable is:
```
final Map entries = this.writeQueue.poll();
if (entries != null) {
...
try {
WriteBatch writeBatch = new WriteBatch();
writeBatch.put(this.columnFamilyHandle, kv.getKey(), kv.getValue());
this.openedDB.write(new WriteOptions(), writeBatch);
writeBatch.close();
} catch (RocksDBException e) {
LOG.error("encountered RocksDB error", e);
...
}
}
```

The write stalls in RocksDB log look like this:
```
2020/03/24-12:32:43.410401 7f2624ff9700 [WARN] [lumn_family.cc:874] [streamBeta] Stalling writes because we have 20 level-0 files rate 16777216
2020/03/24-12:32:43.410505 7f2624ff9700 (Original Log Time 2020/03/24-12:32:43.409626) [mtable_list.cc:447] [streamBeta] Level-0 commit table #3948 started
2020/03/24-12:32:43.410509 7f2624ff9700 (Original Log Time 2020/03/24-12:32:43.410374) [mtable_list.cc:503] [streamBeta] Level-0 commit table #3948: memtable #1 done
2020/03/24-12:32:43.410510 7f2624ff9700 (Original Log Time 2020/03/24-12:32:43.410393) EVENT_LOG_v1 {"time_micros": 1585053163410386, "job": 544, "event": "flush_finished", "output_comp
ression": "Snappy", "lsm_state": [20, 13, 47, 67, 0, 0, 0], "immutable_memtables": 0}
2020/03/24-12:32:43.410512 7f2624ff9700 (Original Log Time 2020/03/24-12:32:43.410427) [_impl/db_impl_compaction_flush.cc:205] [streamBeta] Level summary: files[20 13 47 67 0 0 0] max s
core 3.34
2020/03/24-12:32:43.410566 7f2624ff9700 [_impl/db_impl_files.cc:353] [JOB 544] Try to delete WAL files size 91401215, prev total WAL file size 294459978, number of live WAL files 5.
2020/03/24-12:32:43.410623 7f2625ffb700 (Original Log Time 2020/03/24-12:32:43.410580) [_impl/db_impl_compaction_flush.cc:2614] Compaction nothing to do
2020/03/24-12:32:43.426225 7f2624ff9700 [_impl/db_impl_compaction_flush.cc:106] [JOB 546] Syncing log #3943
2020/03/24-12:32:43.428820 7f2624ff9700 [_impl/db_impl_compaction_flush.cc:106] [JOB 546] Syncing log #3949
2020/03/24-12:32:43.831750 7f2624ff9700 (Original Log Time 2020/03/24-12:32:43.426206) [_impl/db_impl_compaction_flush.cc:2197] Calling FlushMemTableToOutputFile with column family [str
eamAlpha], flush slots available 1, compaction slots available 10, flush slots scheduled 1, compaction slots scheduled 4
2020/03/24-12:32:43.831759 7f2624ff9700 [ush_job.cc:320] [streamAlpha] [JOB 546] Flushing memtable with next log file: 3949
2020/03/24-12:32:43.831767 7f2624ff9700 [ush_job.cc:320] [streamAlpha] [JOB 546] Flushing memtable with next log file: 3950
2020/03/24-12:32:43.831795 7f2624ff9700 EVENT_LOG_v1 {"time_micros": 1585053163831784, "job": 546, "event": "flush_started", "num_memtables": 2, "num_entries": 131236, "num_deletes": 0,
"total_data_size": 128496144, "memory_usage": 130891104, "flush_reason": "Write Buffer Full"}
2020/03/24-12:32:43.831800 7f2624ff9700 [ush_job.cc:349] [streamAlpha] [JOB 546] Level-0 flush table #3952: started
2020/03/24-12:32:43.832143 7f26752d4700 [mpaction/compaction_job.cc:1350] [streamBeta] [JOB 403] Generated table #3762: 143137 keys, 67507447 bytes
2020/03/24-12:32:43.832191 7f26752d4700 EVENT_LOG_v1 {"time_micros": 1585053163832158, "cf_name": "streamBeta", "job": 403, "event": "table_file_creation", "file_number": 3762, "file_si
ze": 67507447, "table_properties": {"data_size": 67110868, "index_size": 679668, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 0, "index_value_is_delta_enco
ded": 0, "filter_size": 0, "raw_key_size": 2290192, "raw_average_key_size": 16, "raw_value_size": 92420930, "raw_average_value_size": 645, "num_data_blocks": 23539, "num_entries": 14313
7, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "streamBeta", "column_famil
y_id": 2, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "Snappy", "compression
_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; ", "creation_time": 1585006719, "oldest_key_time": 0, "file_creation_time": 15
85053098}}
2020/03/24-12:32:43.855594 7f26752d4700 [mpaction/compaction_job.cc:1350] [streamBeta] [JOB 403] Generated table #3953: 1311 keys, 630420 bytes
2020/03/24-12:32:43.855640 7f26752d4700 EVENT_LOG_v1 {"time_micros": 1585053163855613, "cf_name": "streamBeta", "job": 403, "event": "table_file_creation", "file_number": 3953, "file_si
ze": 630420, "table_properties": {"data_size": 626194, "index_size": 6061, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 0, "index_value_is_delta_encoded":
0, "filter_size": 0, "raw_key_size": 20976, "raw_average_key_size": 16, "raw_value_size": 846638, "raw_average_value_size": 645, "num_data_blocks": 217, "num_entries": 1311, "num_deleti
ons": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "streamBeta", "column_family_id": 2, "com
parator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "Snappy", "compression_options": "wi
ndow_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; ", "creation_time": 1585006719, "oldest_key_time": 0, "file_creation_time": 1585053163}}
2020/03/24-12:32:43.859493 7f26752d4700 [mpaction/compaction_job.cc:1416] [streamBeta] [JOB 403] Compacted 1@2 + 1@3 files to L3 => 68137867 bytes
2020/03/24-12:32:43.860266 7f26752d4700 [WARN] [lumn_family.cc:874] [streamBeta] Stalling writes because we have 20 level-0 files rate 10066329
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.