ozone
ozone copied to clipboard
apache
HDDS-9844. [hsync] De-synchronize write APIs
v2. WIP. Re-targeting feature branch to facilitate easier testing with other hsync/hbase related changes and improvements.
What changes were proposed in this pull request?
synchronized keyword has been added to write/hsync methods in HDDS-7907 to ensure correctness. But it is reducing hsync throughput on the same file a lot (which is a use case of HBase) as it is not allowing multiple hsync()s to interleave. It should be allowed to send a bunch of RPCs altogether one after another and then wait.
This PR aims to reduce blocking by immediately returning the future rather than waiting on it to return to allow write/hsync to interleave while ensuring correctness. (Submit the request and return immediately.) This inevitably involves some refactoring.
The dev process took a step back from #6207 that this only desync'ed hsync() first. write() desync is not optimal at this point.
- [x] Desync
hsync()to allow interleaving. - [x] Resolve
testConcurrentWriteHSyncfailure. - [x] Desync
write()(partially). - [ ] Finish TODO items added in this diff.
- [ ] Finish error handling.
What is the link to the Apache JIRA
https://issues.apache.org/jira/browse/HDDS-9844
How was this patch tested?
- [ ] All existing tests covering key stream write/hsync/close must pass.
Also, we should apply this patch too:
diff --git a/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/BlockOutputStreamEntryPool.java b/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/BlockOutputStreamEntryPool.java
index 1b7918a45a..ed1d149dd5 100644
--- a/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/BlockOutputStreamEntryPool.java
+++ b/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/BlockOutputStreamEntryPool.java
@@ -338,10 +338,10 @@ void commitKey(long offset) throws IOException {
void hsyncKey(long offset) throws IOException {
if (keyArgs != null) {
// in test, this could be null
- long length = getKeyLength();
- Preconditions.checkArgument(offset == length,
- "Expected offset: " + offset + " expected len: " + length);
- keyArgs.setDataSize(length);
+ //long length = getKeyLength();
+ //Preconditions.checkArgument(offset == length,
+ // "Expected offset: " + offset + " expected len: " + length);
+ keyArgs.setDataSize(offset);
keyArgs.setLocationInfoList(getLocationInfoList());
// When the key is multipart upload part file upload, we should not
// commit the key, as this is not an actual key, this is a just a
Additioinally, HBase RegionServer failed with this stack trace which suggests a Ratis related problem.
2024-03-28 01:55:47,076 WARN org.apache.hadoop.hbase.regionserver.wal.FSHLog: UNEXPECTED
java.lang.IllegalStateException: only the first buffer can be released: expected == ChunkBufferImplWithByteBuffer:limit=4194304@ca05f780 but computed == ChunkBufferImplWithByteBuffer:limit=4194304@c69c3ad3
at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:73)
at org.apache.ratis.util.Preconditions.assertSame(Preconditions.java:83)
at org.apache.hadoop.hdds.scm.storage.BufferPool.releaseBuffer(BufferPool.java:101)
at org.apache.hadoop.hdds.scm.storage.CommitWatcher.releaseBuffers(CommitWatcher.java:59)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.concurrent.ConcurrentSkipListMap$KeySpliterator.forEachRemaining(ConcurrentSkipListMap.java:3358)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
at org.apache.hadoop.hdds.scm.storage.AbstractCommitWatcher.adjustBuffers(AbstractCommitWatcher.java:172)
at org.apache.hadoop.hdds.scm.storage.AbstractCommitWatcher.watchForCommit(AbstractCommitWatcher.java:149)
at org.apache.hadoop.hdds.scm.storage.AbstractCommitWatcher.watchOnLastIndex(AbstractCommitWatcher.java:120)
at org.apache.hadoop.hdds.scm.storage.RatisBlockOutputStream.sendWatchForCommit(RatisBlockOutputStream.java:105)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.watchForCommit(BlockOutputStream.java:450)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.handleFlushInternal(BlockOutputStream.java:624)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.handleFlush(BlockOutputStream.java:586)
at org.apache.hadoop.hdds.scm.storage.RatisBlockOutputStream.hsync(RatisBlockOutputStream.java:138)
at org.apache.hadoop.ozone.client.io.BlockOutputStreamEntry.hsync(BlockOutputStreamEntry.java:166)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleStreamAction(KeyOutputStream.java:600)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleFlushOrClose(KeyOutputStream.java:546)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.hsync(KeyOutputStream.java:500)
at org.apache.hadoop.ozone.client.io.OzoneOutputStream.hsync(OzoneOutputStream.java:118)
at org.apache.hadoop.fs.ozone.OzoneFSOutputStream.hsync(OzoneFSOutputStream.java:70)
at org.apache.hadoop.fs.ozone.OzoneFSOutputStream.hflush(OzoneFSOutputStream.java:65)
at org.apache.hadoop.fs.FSDataOutputStream.hflush(FSDataOutputStream.java:136)
at org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.sync(ProtobufLogWriter.java:84)
at org.apache.hadoop.hbase.regionserver.wal.FSHLog$SyncRunner.run(FSHLog.java:669)
I had to apply this patch again https://github.com/apache/ozone/pull/6413#issuecomment-2030977615
after that HBase RS is failing for a similar but different error:
2024-04-02 23:53:56,326 ERROR org.apache.hadoop.hdds.scm.storage.BlockOutputStream: Failed to flush. error: only the first buffer can be released: expected == ChunkBufferImplWithByteBuffer:l
imit=4194304@cbedb8e8 but computed == ChunkBufferImplWithByteBuffer:limit=4194304@360cdac9
java.lang.IllegalStateException: only the first buffer can be released: expected == ChunkBufferImplWithByteBuffer:limit=4194304@cbedb8e8 but computed == ChunkBufferImplWithByteBuffer:limit=4
194304@360cdac9
at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:73)
at org.apache.ratis.util.Preconditions.assertSame(Preconditions.java:83)
at org.apache.hadoop.hdds.scm.storage.BufferPool.releaseBuffer(BufferPool.java:101)
at org.apache.hadoop.hdds.scm.storage.CommitWatcher.releaseBuffers(CommitWatcher.java:59)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.concurrent.ConcurrentSkipListMap$KeySpliterator.forEachRemaining(ConcurrentSkipListMap.java:3358)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
at org.apache.hadoop.hdds.scm.storage.AbstractCommitWatcher.adjustBuffers(AbstractCommitWatcher.java:172)
at org.apache.hadoop.hdds.scm.storage.AbstractCommitWatcher.watchForCommit(AbstractCommitWatcher.java:149)
at org.apache.hadoop.hdds.scm.storage.AbstractCommitWatcher.watchOnLastIndex(AbstractCommitWatcher.java:120)
at org.apache.hadoop.hdds.scm.storage.RatisBlockOutputStream.sendWatchForCommit(RatisBlockOutputStream.java:105)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.watchForCommit(BlockOutputStream.java:467)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.handleFlushInternal(BlockOutputStream.java:647)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.handleFlush(BlockOutputStream.java:600)
at org.apache.hadoop.hdds.scm.storage.RatisBlockOutputStream.hsync(RatisBlockOutputStream.java:138)
at org.apache.hadoop.ozone.client.io.BlockOutputStreamEntry.hsync(BlockOutputStreamEntry.java:166)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleStreamAction(KeyOutputStream.java:600)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleFlushOrClose(KeyOutputStream.java:546)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.hsync(KeyOutputStream.java:500)
at org.apache.hadoop.ozone.client.io.OzoneOutputStream.hsync(OzoneOutputStream.java:118)
at org.apache.hadoop.fs.ozone.OzoneFSOutputStream.hsync(OzoneFSOutputStream.java:70)
at org.apache.hadoop.fs.ozone.OzoneFSOutputStream.hflush(OzoneFSOutputStream.java:65)
at org.apache.hadoop.fs.FSDataOutputStream.hflush(FSDataOutputStream.java:136)
at org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.sync(ProtobufLogWriter.java:84)
at org.apache.hadoop.hbase.regionserver.wal.FSHLog$SyncRunner.run(FSHLog.java:669)
2024-04-02 23:53:56,328 WARN org.apache.hadoop.hbase.regionserver.wal.FSHLog: UNEXPECTED
If the outer write APIs are de-synchronized, the inner data structures must be thread safe. synchronized. Curretly, BufferPool is not thread safe. We probably need to synchronize it. Not sure if there are other data structures need to be synchronized.
TestHSync.testConcurrentWriteHSync() has an error, but we need to let it catch&throw IllegalArgumentException too.
Suggest to apply this patch and you'll see the exception:
diff --git a/hadoop-ozone/integration-test/src/test/java/org/apache/hadoop/fs/ozone/TestHSync.java b/hadoop-ozone/integration-test/src/test/java/org/apache/hadoop/fs/ozone/TestHSync.java
index 1050b5b48b..0e2c05c104 100644
--- a/hadoop-ozone/integration-test/src/test/java/org/apache/hadoop/fs/ozone/TestHSync.java
+++ b/hadoop-ozone/integration-test/src/test/java/org/apache/hadoop/fs/ozone/TestHSync.java
@@ -578,7 +578,7 @@ private void runConcurrentWriteHSync(Path file,
try {
out.write(data);
} catch (IOException e) {
- writerException.set(e);
+ writerException.set(new IOException(e));
throw new RuntimeException(e);
}
}
@@ -588,8 +588,8 @@ private void runConcurrentWriteHSync(Path file,
while ((Time.monotonicNow() - start < 10000)) {
try {
out.hsync();
- } catch (IOException e) {
- syncerException.set(e);
+ } catch (Throwable e) {
+ syncerException.set(new IOException(e));
throw new RuntimeException(e);
}
}
Apply this patch to address the bug:
diff --git a/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/BlockOutputStreamEntryPool.java b/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/BlockOutputStreamEntryPool.java
index 1b7918a45a..ed1d149dd5 100644
--- a/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/BlockOutputStreamEntryPool.java
+++ b/hadoop-ozone/client/src/main/java/org/apache/hadoop/ozone/client/io/BlockOutputStreamEntryPool.java
@@ -338,10 +338,10 @@ void commitKey(long offset) throws IOException {
void hsyncKey(long offset) throws IOException {
if (keyArgs != null) {
// in test, this could be null
- long length = getKeyLength();
- Preconditions.checkArgument(offset == length,
- "Expected offset: " + offset + " expected len: " + length);
- keyArgs.setDataSize(length);
+ //long length = getKeyLength();
+ //Preconditions.checkArgument(offset == length,
+ // "Expected offset: " + offset + " expected len: " + length);
+ keyArgs.setDataSize(offset);
keyArgs.setLocationInfoList(getLocationInfoList());
// When the key is multipart upload part file upload, we should not
// commit the key, as this is not an actual key, this is a just a
We need to synchronize at few places in BlockOutputStream.
Check this commit for reference: https://github.com/jojochuang/ozone/commit/357d224a3db3761f83ab04db45abd007b98aaf99
TestHsync#testUncommittedBlocks would time out running the latest PR.
ALL integration tests failed. it's broken atm
fyi with the latest commit as of a few seconds ago there are still two known issues when running testKeyLargerThan2GB with --key-size set to 5 MB (at least 2 chunk buffers allocated. If it is set to 4 MB or less, it seems to always pass with only 1 chunk buffer ever allocated). The testKeyLargerThan2GB sometimes passes and sometimes not (flaky).
-
BlockOutputStream has been closedthrown fromhandleFlushInternal. Regardless of whethertestKeyLargerThan2GBhas passed or not:
2024-04-10 14:31:34,838 [pool-234-thread-1] WARN io.KeyOutputStream (KeyOutputStream.java:handleFlushOrClose(571)) - !!! handleFlushOrClose(op = FULL)
2024-04-10 14:31:34,840 [pool-234-thread-1] WARN storage.BlockOutputStream (BlockOutputStream.java:handleFlushInternal(659)) - handleFlushInternal(close = true)
2024-04-10 14:31:34,852 [client-write-TID-1] ERROR storage.BlockOutputStream (BlockOutputStream.java:lambda$handleFlushInternal$4(702)) - IOException caught but ignored in this POC
java.io.IOException: BlockOutputStream has been closed.
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.checkOpen(BlockOutputStream.java:791)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.watchForCommit(BlockOutputStream.java:498)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.lambda$handleFlushInternal$4(BlockOutputStream.java:693)
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591)
at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:456)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
2024-04-10 14:31:34,852 [pool-234-thread-1] ERROR storage.BlockOutputStream (BlockOutputStream.java:close(717)) - InterruptedException or ExecutionException caught but ignored in this POC
java.util.concurrent.ExecutionException: java.io.IOException: BlockOutputStream has been closed.
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1908)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.close(BlockOutputStream.java:714)
at org.apache.hadoop.ozone.client.io.BlockOutputStreamEntry.close(BlockOutputStreamEntry.java:174)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleStreamAction(KeyOutputStream.java:630)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleFlushOrClose(KeyOutputStream.java:580)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleWrite(KeyOutputStream.java:284)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.write(KeyOutputStream.java:242)
at org.apache.hadoop.ozone.client.io.OzoneOutputStream.write(OzoneOutputStream.java:94)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.createKey(RandomKeyGenerator.java:823)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.access$1200(RandomKeyGenerator.java:90)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator$ObjectCreator.run(RandomKeyGenerator.java:717)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
Caused by: java.io.IOException: BlockOutputStream has been closed.
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.checkOpen(BlockOutputStream.java:791)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.watchForCommit(BlockOutputStream.java:498)
at org.apache.hadoop.hdds.scm.storage.BlockOutputStream.lambda$handleFlushInternal$4(BlockOutputStream.java:693)
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591)
at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:456)
... 3 more
2024-04-10 14:31:34,854 [pool-234-thread-1] WARN storage.BufferPool (BufferPool.java:allocateBuffer(94)) - !! allocateBuffer(increment = 0): capacity = 2, currentBufferIndex = 1, nextBufferIndex = 1, bufferList.size() = 2
2024-04-10 14:31:34,913 [client-write-TID-0] WARN storage.BufferPool (BufferPool.java:releaseBuffer(110)) - !! releaseBuffer(chunkBuffer = ChunkBufferImplWithByteBuffer:limit=1048576@1):currentBufferIndex = 1, bufferList.indexOf(chunkBuffer) = 0
- When
testKeyLargerThan2GBfails, it still indicates some "buffer not released" issue:
2024-04-10 14:31:34,959 [pool-234-thread-1] ERROR freon.RandomKeyGenerator (RandomKeyGenerator.java:createKey(848)) - Exception while adding key: key-0-10754 in bucket: bucket-0-45857 of volume: vol-0-11123.
java.lang.IllegalStateException: capacity: expected == 0 but computed == 1048576
at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:76)
at org.apache.ratis.util.Preconditions.assertSame(Preconditions.java:81)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.release(CodecBuffer.java:299)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.close(CodecBuffer.java:291)
at org.apache.hadoop.ozone.common.ChunkBufferImplWithByteBuffer.close(ChunkBufferImplWithByteBuffer.java:50)
at java.util.ArrayList.forEach(ArrayList.java:1259)
at org.apache.hadoop.hdds.scm.storage.BufferPool.clearBufferPool(BufferPool.java:130)
at org.apache.hadoop.ozone.client.io.BlockOutputStreamEntryPool.cleanup(BlockOutputStreamEntryPool.java:407)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.markStreamClosed(KeyOutputStream.java:424)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleWrite(KeyOutputStream.java:289)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.write(KeyOutputStream.java:242)
at org.apache.hadoop.ozone.client.io.OzoneOutputStream.write(OzoneOutputStream.java:94)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.createKey(RandomKeyGenerator.java:823)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.access$1200(RandomKeyGenerator.java:90)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator$ObjectCreator.run(RandomKeyGenerator.java:717)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
Suppressed: java.lang.IllegalStateException: capacity: expected == 0 but computed == 1048576
at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:76)
at org.apache.ratis.util.Preconditions.assertSame(Preconditions.java:81)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.release(CodecBuffer.java:299)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.close(CodecBuffer.java:291)
at org.apache.hadoop.ozone.common.ChunkBufferImplWithByteBuffer.close(ChunkBufferImplWithByteBuffer.java:50)
at java.util.ArrayList.forEach(ArrayList.java:1259)
at org.apache.hadoop.hdds.scm.storage.BufferPool.clearBufferPool(BufferPool.java:130)
at org.apache.hadoop.ozone.client.io.BlockOutputStreamEntryPool.cleanup(BlockOutputStreamEntryPool.java:407)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.close(KeyOutputStream.java:685)
at org.apache.hadoop.ozone.client.io.OzoneOutputStream.close(OzoneOutputStream.java:105)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.createKey(RandomKeyGenerator.java:833)
... 5 more
2024-04-10 14:31:35,400 [Thread-649] INFO freon.ProgressBar (ProgressBar.java:logProgressBar(168)) - Progress: 0.00 % (0 out of 1)
2024-04-10 14:31:36,412 [Thread-649] INFO freon.ProgressBar (ProgressBar.java:logProgressBar(168)) - Progress: 0.00 % (0 out of 1)
2024-04-10 14:31:37,418 [Thread-649] INFO freon.ProgressBar (ProgressBar.java:logProgressBar(168)) - Progress: 0.00 % (0 out of 1)
2024-04-10 14:31:38,423 [Thread-649] INFO freon.ProgressBar (ProgressBar.java:logProgressBar(168)) - Progress: 0.00 % (0 out of 1)
2024-04-10 14:31:39,456 [Thread-649] INFO freon.ProgressBar (ProgressBar.java:logProgressBar(168)) - Progress: 0.00 % (0 out of 1)
2024-04-10 14:31:40,461 [Thread-649] INFO freon.ProgressBar (ProgressBar.java:logProgressBar(168)) - Progress: 0.00 % (0 out of 1)
java.lang.RuntimeException: java.lang.IllegalStateException: capacity: expected == 0 but computed == 1048576
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.call(RandomKeyGenerator.java:391)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.call(RandomKeyGenerator.java:83)
at picocli.CommandLine.executeUserObject(CommandLine.java:2041)
at picocli.CommandLine.access$1500(CommandLine.java:148)
at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2461)
at picocli.CommandLine$RunLast.handle(CommandLine.java:2453)
at picocli.CommandLine$RunLast.handle(CommandLine.java:2415)
at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2273)
at picocli.CommandLine$RunLast.execute(CommandLine.java:2417)
at picocli.CommandLine.execute(CommandLine.java:2170)
at org.apache.hadoop.ozone.freon.TestRandomKeyGenerator.testKeyLargerThan2GB(TestRandomKeyGenerator.java:164)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728)
at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
at java.util.ArrayList.forEach(ArrayList.java:1259)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
at java.util.ArrayList.forEach(ArrayList.java:1259)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85)
at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47)
at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:63)
at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57)
at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)
Caused by: java.lang.IllegalStateException: capacity: expected == 0 but computed == 1048576
at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:76)
at org.apache.ratis.util.Preconditions.assertSame(Preconditions.java:81)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.release(CodecBuffer.java:299)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.close(CodecBuffer.java:291)
at org.apache.hadoop.ozone.common.ChunkBufferImplWithByteBuffer.close(ChunkBufferImplWithByteBuffer.java:50)
at java.util.ArrayList.forEach(ArrayList.java:1259)
at org.apache.hadoop.hdds.scm.storage.BufferPool.clearBufferPool(BufferPool.java:130)
at org.apache.hadoop.ozone.client.io.BlockOutputStreamEntryPool.cleanup(BlockOutputStreamEntryPool.java:407)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.markStreamClosed(KeyOutputStream.java:424)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.handleWrite(KeyOutputStream.java:289)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.write(KeyOutputStream.java:242)
at org.apache.hadoop.ozone.client.io.OzoneOutputStream.write(OzoneOutputStream.java:94)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.createKey(RandomKeyGenerator.java:823)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.access$1200(RandomKeyGenerator.java:90)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator$ObjectCreator.run(RandomKeyGenerator.java:717)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:750)
Suppressed: java.lang.IllegalStateException: capacity: expected == 0 but computed == 1048576
at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:76)
at org.apache.ratis.util.Preconditions.assertSame(Preconditions.java:81)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.release(CodecBuffer.java:299)
at org.apache.hadoop.hdds.utils.db.CodecBuffer.close(CodecBuffer.java:291)
at org.apache.hadoop.ozone.common.ChunkBufferImplWithByteBuffer.close(ChunkBufferImplWithByteBuffer.java:50)
at java.util.ArrayList.forEach(ArrayList.java:1259)
at org.apache.hadoop.hdds.scm.storage.BufferPool.clearBufferPool(BufferPool.java:130)
at org.apache.hadoop.ozone.client.io.BlockOutputStreamEntryPool.cleanup(BlockOutputStreamEntryPool.java:407)
at org.apache.hadoop.ozone.client.io.KeyOutputStream.close(KeyOutputStream.java:685)
at org.apache.hadoop.ozone.client.io.OzoneOutputStream.close(OzoneOutputStream.java:105)
at org.apache.hadoop.ozone.freon.RandomKeyGenerator.createKey(RandomKeyGenerator.java:833)
... 5 more
org.opentest4j.AssertionFailedError:
Expected :1
Actual :0
Discussed with @szetszwo offline about the latter. We tried a few approaches (synchronizing submission, which this PR has included), but so far no dice.
The implementation so far still has consistency issue (out-of-order or missing writes?). I'll keep looking:
https://github.com/smengcl/hadoop-ozone/actions/runs/8639955657/job/23687774865#step:6:1720
Error: org.apache.hadoop.ozone.client.rpc.TestBlockOutputStreamWithFailures.testWatchForCommitDatanodeFailure(boolean)[2] Time elapsed: 44.059 s <<< ERROR!
java.io.IOException: Inconsistent read for blockID=conID: 1 locID: 113750153625600001 bcsId: 15 length=800 position=500 numBytesToRead=800 numBytesRead=500
at org.apache.hadoop.ozone.client.io.KeyInputStream.checkPartBytesRead(KeyInputStream.java:195)
at org.apache.hadoop.hdds.scm.storage.MultipartInputStream.readWithStrategy(MultipartInputStream.java:97)
at org.apache.hadoop.hdds.scm.storage.ExtendedInputStream.read(ExtendedInputStream.java:56)
at org.apache.hadoop.ozone.client.io.OzoneInputStream.read(OzoneInputStream.java:56)
at java.io.InputStream.read(InputStream.java:101)
In order to fix the problem where the buffer would be written to by another thread when currentBuffer is already submitted to DN, I have forced the currentBuffer to be swapped whenever it is submitted to DN. This is done in b6131ff51700d5de99233cc67054910e13425d34.
Current issues:
- The above measure his could cause excessive buffer allocation (increased memory pressure) if: i) DN is slow to respond ii) and client does hsync very frequently
Observed OutOfMemoryError: GC overhead limit exceeded in TestOzoneFileSystemWithStreaming that may not may not be related to (i): https://github.com/smengcl/hadoop-ozone/actions/runs/8907642899/job/24462549982
- More race condition in buffer access that are unresolved. e.g.
TestBlockDeletion.testBlockDeletion: https://github.com/smengcl/hadoop-ozone/actions/runs/8907642899/job/24462551568#step:6:2352
One more thought:
- Ditching
watchForCommit(#6014) first might help in resolving the buffer access race condition