[
https://issues.apache.org/jira/browse/HDDS-17212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andrey Yarovoy reassigned HDDS-17212:
-------------------------------------
Assignee: Andrey Yarovoy
> KeyOutputStream.close() fails with "refCnt: expected == 0 but computed == 1"
> after the key is committed
> -------------------------------------------------------------------------------------------------------
>
> Key: HDDS-17212
> URL: https://issues.apache.org/jira/browse/HDDS-17212
> Project: Apache Ozone
> Issue Type: Bug
> Components: Ozone Client
> Reporter: Andrey Yarovoy
> Assignee: Andrey Yarovoy
> Priority: Major
>
> ## Summary
> KeyOutputStream.close() fails with "refCnt: expected == 0 but computed == 1"
> after the key has been committed
> ## Description
> ### Problem
> Closing a key output stream failed while releasing its buffers. The key had
> already been committed:
> ```
> java.lang.IllegalStateException: refCnt: expected == 0 but computed == 1
> at org.apache.ratis.util.Preconditions.assertTrue(Preconditions.java:77)
> at org.apache.ratis.util.Preconditions.assertSame(Preconditions.java:82)
> at
> org.apache.hadoop.hdds.utils.db.CodecBuffer.assertRefCnt(CodecBuffer.java:262)
> at org.apache.hadoop.hdds.utils.db.CodecBuffer.release(CodecBuffer.java:304)
> at org.apache.hadoop.hdds.utils.db.CodecBuffer.close(CodecBuffer.java:293)
> at
> org.apache.hadoop.ozone.common.ChunkBufferImplWithByteBuffer.close(ChunkBufferImplWithByteBuffer.java:50)
> at java.lang.Iterable.forEach(Iterable.java:75)
> at
> org.apache.hadoop.hdds.scm.storage.BufferPool.clearBufferPool(BufferPool.java:166)
> at
> org.apache.hadoop.ozone.client.io.BlockOutputStreamEntryPool.cleanup(BlockOutputStreamEntryPool.java:413)
> at
> org.apache.hadoop.ozone.client.io.KeyOutputStream.closeInternal(KeyOutputStream.java:670)
> at
> org.apache.hadoop.ozone.client.io.KeyOutputStream.doInWriteLock(KeyOutputStream.java:259)
> at
> org.apache.hadoop.ozone.client.io.KeyOutputStream.close(KeyOutputStream.java:646)
> at
> org.apache.hadoop.ozone.client.io.OzoneOutputStream.close(OzoneOutputStream.java:104)
> at
> org.apache.hadoop.fs.ozone.OzoneFSOutputStream.close(OzoneFSOutputStream.java:64)
> at org.apache.hadoop.fs.FSDataOutputStream.close(FSDataOutputStream.java:106)
> at org.apache.hadoop.io.SequenceFile$Writer.close(SequenceFile.java:1437)
> at
> org.apache.hadoop.fs.TestDFSIO$ControlFileCreateTask.run(TestDFSIO.java:326)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
> ```
> Seen once, during TestDFSIO's control-file creation. TestDFSIO writes one
> small SequenceFile per map task from a
> thread pool, so many `KeyOutputStream`s in one client JVM are written and
> closed concurrently. Here that was 250
> files on a RATIS/THREE FSO bucket over `ofs://`. The exception aborted the
> whole TestDFSIO job. Environment: 12
> datanodes, Ozone 2.2.0, Kerberos, `hdds.grpc.tls.enabled=true`.
> It's rare. It hit once in about 960 TestDFSIO jobs, which closed several
> hundred thousand control-file streams, so
> reproducing it will probably need a stress loop.
> ### Analysis
> `CodecBuffer.release()`:
> ```java
> if (buf.release()) {
> assertRefCnt(0); // <- fails: computed == 1
> } else \{ ... }
> ```
> The `if` branch was taken, so `buf.release()` returned true: Netty
> decremented the reference count from 1 to 0 and
> deallocated the buffer. For a buffer from `PooledByteBufAllocator`,
> deallocation returns both the memory and the
> `PooledByteBuf` object itself (through Netty's `Recycler`) to the pools. A
> count of 1 on the next line means the
> object had already been handed out to a new allocation, which resets the
> count to 1.
> So `assertRefCnt(0)` after a successful `release()` reads a pooled object
> that may no longer belong to this
> `CodecBuffer`. That's a use-after-release, and the check can fail for a
> release that was correct. Netty already
> guarantees that `release()` returning true means the count reached 0, so the
> second check adds nothing.
> Not yet determined: which concurrent allocation reused the object. Netty
> normally recycles an object to the pool
> of the thread that created it, and here the allocating and closing thread
> look like the same `ControlFileCreateTask`
> pool thread. A real double ownership, where two owners release the same
> `ByteBuf`, would also produce this, so it
> can't be ruled out yet.
> ### Impact
> Whatever the trigger, two problems in the close path turn it into a failure
> of a successful write:
> 1. **close() fails after commitKey().** `KeyOutputStream.closeInternal()`
> commits the key and then runs
> `blockOutputStreamEntryPool.cleanup()` in `finally`. An exception from buffer
> cleanup reaches the caller even
> though the key is complete and visible. Callers treat the write as failed:
> TestDFSIO aborts the job, and other
> applications may retry or delete a good file.
> 2. **clearBufferPool() stops at the first failure.**
> `allocated.forEach(ChunkBuffer::close)` and
> `released.forEach(ChunkBuffer::close)` propagate the first exception. The
> remaining direct buffers are never
> released (a direct-memory leak), and `allocated`/`released`/`currentBuffer`
> aren't cleared.
> ### Proposed fix
> 1. `CodecBuffer.release()`: don't read `refCnt()` after `buf.release()`
> returns true. Either drop the check, or
> check `refCnt() == 1` before releasing, while the buffer is still owned.
> 2. `BufferPool.clearBufferPool()`: close each buffer independently,
> collecting failures (log them, or rethrow one
> with the rest suppressed after everything has been released), and always
> clear the lists.
> 3. `KeyOutputStream.closeInternal()` (and the other key output streams that
> clean up after commit): once the key is
> committed, log a buffer-cleanup failure rather than failing `close()`.
> Fix 1 removes the trigger if the race hypothesis holds; 2 and 3 make the
> close path tolerate any cleanup failure.
> ### How to reproduce
> Not reproduced deliberately yet. Candidate stress test: in one client JVM, N
> threads (eg. 64) each repeatedly
> create, write a few KB to, and close their own key on a RATIS/THREE bucket,
> until `close()` throws
> `IllegalStateException: refCnt`. Or run `TestDFSIO -write -nrFiles 1000`
> repeatedly; the failure is in the client
> before any map task starts.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
