Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Sync Writes has to enable WAL" RocksDBException during sweeping #888

Closed
RatanRSur opened this issue May 8, 2020 · 1 comment · Fixed by #929
Closed

"Sync Writes has to enable WAL" RocksDBException during sweeping #888

RatanRSur opened this issue May 8, 2020 · 1 comment · Fixed by #929
Assignees
Labels
bug Something isn't working P2 High (ex: Degrading performance issues, unexpected behavior of core features (DevP2P, syncing, etc))

Comments

@RatanRSur
Copy link
Contributor

RatanRSur commented May 8, 2020

2020-05-08 10:25:33.886-04:00 | EthScheduler-Services-5 (importBlock) | INFO  | FullImportBlockStep | Import reached block 2000 (0x0c0c..bae4), Peers: 1
2020-05-08 10:25:33.932-04:00 | StatePruning-0 | ERROR | Besu | Uncaught exception in thread "StatePruning-0"
org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: Sync writes has to enable WAL.
        at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage.tryDelete(RocksDBColumnarKeyValueStorage.java:203) ~[besu-plugin-rocksdb-1.4.6-SNAPSHOT.jar:1.4.6-dev-13527060]
        at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage.tryDelete(RocksDBColumnarKeyValueStorage.java:62) ~[besu-plugin-rocksdb-1.4.6-SNAPSHOT.jar:1.4.6-dev-13527060]
        at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageAdapter.tryDelete(SegmentedKeyValueStorageAdapter.java:70) ~[besu-kvstore-1.4.6-SNAPSHOT.jar:1.4.6-dev-13527060]
        at org.hyperledger.besu.ethereum.storage.keyvalue.WorldStateKeyValueStorage.lambda$prune$0(WorldStateKeyValueStorage.java:102) ~[besu-core-1.4.6-SNAPSHOT.jar:1.4.6-dev-13527060]
        at java.util.Iterator.forEachRemaining(Iterator.java:133) ~[?:?]
        at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801) ~[?:?]
        at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658) ~[?:?]
        at org.hyperledger.besu.ethereum.storage.keyvalue.WorldStateKeyValueStorage.prune(WorldStateKeyValueStorage.java:98) ~[besu-core-1.4.6-SNAPSHOT.jar:1.4.6-dev-13527060]
        at org.hyperledger.besu.ethereum.worldstate.MarkSweepPruner.sweepBefore(MarkSweepPruner.java:150) ~[besu-core-1.4.6-SNAPSHOT.jar:1.4.6-dev-13527060]
        at org.hyperledger.besu.ethereum.worldstate.Pruner.lambda$sweep$2(Pruner.java:152) ~[besu-core-1.4.6-SNAPSHOT.jar:1.4.6-dev-13527060]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.rocksdb.RocksDBException: Sync writes has to enable WAL.
        at org.rocksdb.RocksDB.delete(Native Method) ~[rocksdbjni-6.4.6.jar:?]
        at org.rocksdb.RocksDB.delete(RocksDB.java:985) ~[rocksdbjni-6.4.6.jar:?]
        at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage.tryDelete(RocksDBColumnarKeyValueStorage.java:197) ~[besu-plugin-rocksdb-1.4.6-SNAPSHOT.jar:1.4.6-dev-13527060]
        ... 12 more

Steps to Reproduce (Bug)

  1. run canRemoveThroughSegmentIteration test until failure
@RatanRSur RatanRSur added the bug Something isn't working label May 8, 2020
@RatanRSur RatanRSur assigned RatanRSur and unassigned RatanRSur May 8, 2020
@RatanRSur RatanRSur changed the title Sync Writes has to enable WAL exception during sweeping "Sync Writes has to enable WAL" RocksDBException during sweeping May 8, 2020
@timbeiko timbeiko added the P2 High (ex: Degrading performance issues, unexpected behavior of core features (DevP2P, syncing, etc)) label May 13, 2020
@matkt
Copy link
Contributor

matkt commented May 15, 2020

WAL Exception

The issue comes from an error in the closing of WriteOptions (RocksDBColumnarKeyValueStorage)

When we call new WriteOptions() this will create a structure https://github.com/influxdata/rocksdb/blob/7adff3eb33001c471c48cdcadf1b55462920b123/options.go#L64

When we call WriteOptions->close() this will free the structure created
https://github.com/influxdata/rocksdb/blob/7adff3eb33001c471c48cdcadf1b55462920b123/options.go#L242

The test reveals a bug regarding the calls to WriteOptions close() methods

Scenario

1 - Create a WriteOption for the RocksDBColumnarKeyValueStorage instance (optionA)
final SegmentedKeyValueStorage<ColumnFamilyHandle> store = createSegmentedStore();

2 - Create a new transaction with a new WriteOption specific to it (optionB)
final Transaction<ColumnFamilyHandle> tx = store.startTransaction();

3 - Commits the transaction and releases the wrong instance of WriteOption (optionA+optionB)
tx.commit();

4 - Call the tryDelete method which uses the WriteOption instance of the RocksDbTransaction class. Problem this instance of WriteOption has been released and therefore may have random values
store.tryDelete(fooSegment, key)

How to fix

Do not release the WriteOption (optionA) during a transaction commit but when the RocksDBColumnarKeyValueStorage instance is closed

Adding a test that performed more than 1000 times the tests and it works. Without the fix it often fails very quickly

@matkt matkt linked a pull request May 15, 2020 that will close this issue
@matkt matkt self-assigned this May 15, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working P2 High (ex: Degrading performance issues, unexpected behavior of core features (DevP2P, syncing, etc))
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants