Ray Mattingly created HBASE-30341:
-------------------------------------
Summary: 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
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)
