[
https://issues.apache.org/jira/browse/HBASE-30341?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18108018#comment-18108018
]
Ray Mattingly commented on HBASE-30341:
---------------------------------------
oh actually, it looks like maybe this was fixed in
https://issues.apache.org/jira/browse/HBASE-27231 for 3.0+, but never
backported to 2.x
> FSHLog WAL lockup from an uncaught exception in publishSyncOnRingBuffer
> -----------------------------------------------------------------------
>
> Key: HBASE-30341
> URL: https://issues.apache.org/jira/browse/HBASE-30341
> Project: HBase
> Issue Type: Bug
> Components: wal
> Affects Versions: 2.6.7
> Reporter: Ray Mattingly
> Priority: Major
>
> h2. Summary
> In {{FSHLog.publishSyncOnRingBuffer(long, boolean)}} the Disruptor ring
> buffer sequence is claimed by the caller *before* {{getSyncFuture()}} is
> invoked, and {{getSyncFuture()}} sits outside the {{try}} block:
> {code:java}
> protected SyncFuture publishSyncOnRingBuffer(long sequence, boolean
> forceSync) {
> // here we use ring buffer sequence as transaction id
> SyncFuture syncFuture = getSyncFuture(sequence, forceSync); // <-- can
> throw
> try {
> RingBufferTruck truck = this.disruptor.getRingBuffer().get(sequence);
> truck.load(syncFuture);
> } finally {
> this.disruptor.getRingBuffer().publish(sequence); // <--
> skipped
> }
> return syncFuture;
> }
> {code}
> The sequence comes from {{getSequenceOnRingBuffer()}} (i.e.
> {{{}RingBuffer.next(){}}}), so if {{getSyncFuture()}} throws, that slot is
> claimed and {*}never published{*}.
> Disruptor's consumer waits on a sequence barrier for a contiguous published
> sequence. An unpublished hole means {{RingBufferEventHandler}} can never
> advance past it, so every subsequent append and sync on that WAL blocks
> forever. A single failed request is thereby converted into a permanently
> wedged WAL and, in practice, a dead RegionServer.
> h2. Observed in production
> Seen once on a 2.6.x cluster running {{{}hbase.wal.provider=filesystem{}}}.
> The trigger was an NPE out of {{SyncFutureCache.getIfPresentOrNew()}} – the
> Guava {{LocalCache}} write-queue was in an inconsistent state, so removing
> the entry double-unlinked it:
> {code:java}
> ERROR org.apache.hadoop.hbase.ipc.RpcServer: Unexpected throwable object
> java.lang.NullPointerException: Cannot invoke
>
> "org.apache.hbase.thirdparty.com.google.common.cache.ReferenceEntry.setNextInWriteQueue(...)"
> because "previous" is null
> at ...common.cache.LocalCache.connectWriteOrder(LocalCache.java:1818)
> at ...common.cache.LocalCache$WriteQueue.remove(LocalCache.java:3725)
> at
> ...common.cache.LocalCache$Segment.removeValueFromChain(LocalCache.java:3249)
> at ...common.cache.LocalCache$Segment.remove(LocalCache.java:3079)
> at ...common.cache.LocalCache.remove(LocalCache.java:4273)
> at
> org.apache.hadoop.hbase.regionserver.wal.SyncFutureCache.getIfPresentOrNew(SyncFutureCache.java:61)
> at
> org.apache.hadoop.hbase.regionserver.wal.AbstractFSWAL.getSyncFuture(AbstractFSWAL.java:1093)
> at
> org.apache.hadoop.hbase.regionserver.wal.FSHLog.publishSyncOnRingBuffer(FSHLog.java:789)
> at
> org.apache.hadoop.hbase.regionserver.wal.FSHLog.publishSyncOnRingBuffer(FSHLog.java:784)
> at
> org.apache.hadoop.hbase.regionserver.wal.FSHLog.publishSyncThenBlockOnCompletion(FSHLog.java:801)
> at org.apache.hadoop.hbase.regionserver.wal.FSHLog.doSync(FSHLog.java:836)
> at
> org.apache.hadoop.hbase.regionserver.wal.AbstractFSWAL.sync(AbstractFSWAL.java:605)
> at org.apache.hadoop.hbase.regionserver.HRegion.sync(HRegion.java:8383)
> at
> org.apache.hadoop.hbase.regionserver.HRegion.doWALAppend(HRegion.java:7956)
> at
> org.apache.hadoop.hbase.regionserver.HRegion.doMiniBatchMutate(HRegion.java:4672)
> at
> org.apache.hadoop.hbase.regionserver.HRegion.batchMutate(HRegion.java:4597)
> at
> org.apache.hadoop.hbase.regionserver.RSRpcServices.doBatchOp(RSRpcServices.java:1078)
> at
> org.apache.hadoop.hbase.regionserver.RSRpcServices.multi(RSRpcServices.java:2933)
> {code}
> Timeline on the affected RegionServer, which was hosting 51 regions:
> ||Time (UTC)||Event||
> |14:44:56.379|NPE above. WAL write path wedges immediately.|
> |14:44:56.382|First mutation that will hang for 30s begins.|
> |14:45:03 - :09|{{{}LruBlockCache{}}}, {{{}BucketCache{}}},
> {{LocatedBlocksRefresher}} and replication stats all still logging normally –
> the JVM is healthy.|
> |14:45:26|Three {{Multi}} calls surface as {{responseTooSlow}} at
> {{{}processingtimems=30001{}}}, {{{}fsreadtime=0{}}}, {{{}queuetimems=0{}}}.
> Logging then goes quiet.|
> |14:45:30 - :45|RPC call-queue backlog grows ~33% in 15s.|
> |14:45:48|External supervisor kills the host on an availability threshold.|
> |14:45:50|Master sees the server as CRASHED, schedules ServerCrashProcedure.|
> |14:45:51|RegionServer's own report gets {{{}YouAreDeadException{}}}, begins
> abort.|
> |14:46:06|"Aborting region server timed out, terminating forcibly and does
> not wait for any running shutdown hooks or finalizers."|
> |14:46:16|SCP completes; 51 regions reassigned after splitting 65 WAL files.|
> Notes on the failure shape:
> * No {{JvmPauseMonitor}} entries and no slow-sync warnings in the window.
> This was not GC, HDFS, or load – the {{responseTooSlow}} rate had been flat
> for the preceding two hours and then stopped entirely.
> * Background threads kept logging on schedule throughout, so only the WAL
> write path was affected.
> * Because reads and writes share the RPC handler pool, handlers accumulated
> in {{blockOnSync}} and were never returned. Read and write downtime for this
> server were measured as effectively identical (149040 ms vs 149034 ms in one
> minute; 45015 ms vs 45016 ms in the next). A write-path-only bug produced
> full read and write unavailability.
> * The abort path itself could not complete – closing regions requires
> flushing memstores, which requires the wedged WAL – so the process needed
> forcible termination and recovery depended entirely on WAL replay.
> h2. Proposed fix
> Two independent changes; the first is the one that prevents the lockup.
> # Make the publish unconditional. Move {{getSyncFuture()}} inside the
> {{try}} so a throw still publishes the claimed sequence and the consumer can
> drain. The truck needs to carry the failure (or be published empty) so that
> {{RingBufferEventHandler}} can complete the entry rather than trip over an
> unloaded truck. This turns a wedged WAL into one failed request.
> # Make {{SyncFutureCache.getIfPresentOrNew()}} non-throwing – catch
> {{RuntimeException}} from the {{asMap().remove()}} and fall back to {{{}new
> SyncFuture(){}}}. The cache is purely an allocation optimisation and should
> never be able to fail a write.
> More generally, any exception thrown between {{RingBuffer.next()}} and
> {{RingBuffer.publish()}} is unrecoverable for the WAL. It may be worth
> auditing the other claim sites for the same pattern.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
