[
https://issues.apache.org/jira/browse/HBASE-22539?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16855688#comment-16855688
]
Wellington Chevreuil commented on HBASE-22539:
----------------------------------------------
Symptoms:
Upon an RS crash that required log split/replay, RSes splitting WALs would
eventually fail and crash with the following stack trace error:
{noformat}
ERROR org.apache.hadoop.hbase.executor.EventHandler: Caught throwable while
processing event RS_LOG_REPLAY
java.lang.ArrayIndexOutOfBoundsException: 18056
at org.apache.hadoop.hbase.KeyValue.getFamilyLength(KeyValue.java:1365)
at org.apache.hadoop.hbase.KeyValue.getFamilyLength(KeyValue.java:1358)
at
org.apache.hadoop.hbase.PrivateCellUtil.matchingFamily(PrivateCellUtil.java:735)
at org.apache.hadoop.hbase.CellUtil.matchingFamily(CellUtil.java:816)
at
org.apache.hadoop.hbase.wal.WALEdit.isMetaEditFamily(WALEdit.java:143)
at org.apache.hadoop.hbase.wal.WALEdit.isMetaEdit(WALEdit.java:148)
at
org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:297)
at
org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:195)
at
org.apache.hadoop.hbase.regionserver.SplitLogWorker$1.exec(SplitLogWorker.java:100)
{noformat}
Trying to read given wal file with WalPP also gets:
{noformat}
Cell Codec Class: org.apache.hadoop.hbase.regionserver.wal.WALCellCodec
Exception in thread "main" java.lang.IllegalArgumentException: offset (537087)
+ length (8) exceed the capacity of the array: 1066
at
org.apache.hadoop.hbase.util.Bytes.explainWrongLengthOrOffset(Bytes.java:830)
at org.apache.hadoop.hbase.util.Bytes.toLong(Bytes.java:813)
at org.apache.hadoop.hbase.util.Bytes.toLong(Bytes.java:798)
at org.apache.hadoop.hbase.KeyValue.getTimestamp(KeyValue.java:1488)
at org.apache.hadoop.hbase.KeyValue.getTimestamp(KeyValue.java:1479)
at
org.apache.hadoop.hbase.wal.WALPrettyPrinter.toStringMap(WALPrettyPrinter.java:359)
at
org.apache.hadoop.hbase.wal.WALPrettyPrinter.processFile(WALPrettyPrinter.java:305)
at
org.apache.hadoop.hbase.wal.WALPrettyPrinter.run(WALPrettyPrinter.java:444)
{noformat}
After applying the changes committed on [my fork branch
HBASE-22539|https://github.com/wchevreuil/hbase/tree/HBASE-22539], the
following exception logged on this cluster led to conclude the corruption
happens when copying from BB to array
[here|https://github.com/wchevreuil/hbase/blob/HBASE-22539/hbase-common/src/main/java/org/apache/hadoop/hbase/io/ByteBufferWriterOutputStream.java#L92]:
{noformat}
2019-05-30 13:10:26,240 WARN org.apache.hadoop.hbase.KeyValueUtil: Got a KV
validation error while writing. Just logging it for now and allowing to
continue:
java.lang.IllegalArgumentException: Invalid key length in KeyValue.
keyLength=40723827, KeyValueBytesHex=...
\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
...
00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,
offset=0, length=2098
at
org.apache.hadoop.hbase.KeyValueUtil.checkKeyValueBytes(KeyValueUtil.java:555)
at
org.apache.hadoop.hbase.KeyValueUtil.isBufferValid(KeyValueUtil.java:532)
at
org.apache.hadoop.hbase.io.ByteBufferWriterOutputStream.write(ByteBufferWriterOutputStream.java:99)
at
org.apache.hadoop.hbase.util.ByteBufferUtils.copyBufferToStream(ByteBufferUtils.java:451)
at
org.apache.hadoop.hbase.ByteBufferKeyValue.write(ByteBufferKeyValue.java:277)
at org.apache.hadoop.hbase.KeyValueUtil.oswrite(KeyValueUtil.java:794)
at
org.apache.hadoop.hbase.regionserver.wal.WALCellCodec$EnsureKvEncoder.write(WALCellCodec.java:382)
at
org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.append(ProtobufLogWriter.java:54)
at
org.apache.hadoop.hbase.regionserver.wal.FSHLog.doAppend(FSHLog.java:302)
at
org.apache.hadoop.hbase.regionserver.wal.FSHLog.doAppend(FSHLog.java:67)
at
org.apache.hadoop.hbase.regionserver.wal.AbstractFSWAL.append(AbstractFSWAL.java:918)
at
org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEventHandler.append(FSHLog.java:1082)
at
org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEventHandler.onEvent(FSHLog.java:973)
at
org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEventHandler.onEvent(FSHLog.java:881)
at
com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
at java.lang.Thread.run(Thread.java:748)
2019-05-30 13:10:26,293 WARN
org.apache.hadoop.hbase.io.ByteBufferWriterOutputStream: DBB copy via unsafe is
corrupt.
DBB offset: 155
bytes to copy: 2098
Will check normal copy next...
{noformat}
Note the check fails
[here|https://github.com/wchevreuil/hbase/blob/HBASE-22539/hbase-common/src/main/java/org/apache/hadoop/hbase/io/ByteBufferWriterOutputStream.java#L99],
where it's validating this *testBuf* byte[], which is an exact copy of the
resulting array from *ByteBufferUtils.copyFromBufferToArray(this.buf, b, off +
totalCopied, 0, bytesToCopy);* call
[here|https://github.com/wchevreuil/hbase/blob/HBASE-22539/hbase-common/src/main/java/org/apache/hadoop/hbase/io/ByteBufferWriterOutputStream.java#L92].
When the check from line #99 fails (printing the first WARN with IAE and stack
trace), it copies again from DBB to this test byte[], but instead of using
*Unsafe.copyMemory*, it uses *ByteBuffer.get* method, and check the resulting
byte[] on line #106, but this second validation passes. This leads to conclude
the error happens on this *ByteBufferUtils.copyFromBufferToArray(this.buf, b,
off + totalCopied, 0, bytesToCopy);* call, which uses Unsafe.copyMemory
underneath it.
I can't see anything suspicious, however, on current implementation for
*UnsafeCopy.unsafeCopy* (apart from minor improvement reported on HBASE-22496,
which shouldn't be causing this corruption). A remote possibility could be due
to thread contention, as I noticed Compaction executions happening at same
time, and those would also rely on on *UnsafeCopy.unsafeCopy* calls, but that's
a high guess, would think a bit unusual for this *UnsafeAccess.copyMemory* not
be thread safe. Could it be an specific issue on this *UnsafeAccess.copyMemory*
method? ** Maybe folks with better understanding of such implementation could
share some useful insights here.
Additional observations:
1) The main workaround for now is to complete disable the usage of
DirectByteBuffer and the need for unsafe copies by switching
*hbase.rpc.server.impl* back to SimpleRpcServer. After applying this change and
running for some weeks, no corruption has been observed.
2) RSes on the given cluster have been running on hosts suffering memory
contention, including swapping has been observed. Ain't sure if that would be
relevant for unsafe copy.
3) Prior to switching rpc server implementation, we had also suspected on
AsyncFSWal, but switching to FSHLog didn't prevent given corruptions from
re-occur. Those were only gone after the change applied on #1.
Special thanks to [~psomogyi], [~busbey], [~elserj] for the continuing
assistance with this investigation.
> Potential WAL corruption due to Unsafe.copyMemory usage when DBB are in place
> -----------------------------------------------------------------------------
>
> Key: HBASE-22539
> URL: https://issues.apache.org/jira/browse/HBASE-22539
> Project: HBase
> Issue Type: Bug
> Affects Versions: 2.1.1
> Reporter: Wellington Chevreuil
> Priority: Blocker
>
> Summary
> We had been chasing a WAL corruption issue reported on one of our customers
> deployments running release 2.1.1 (CDH 6.1.0). After providing a custom
> modified jar with the extra sanity checks implemented by HBASE-21401 applied
> on some code points, plus additional debugging messages, we believe it is
> related to DirectByteBuffer usage, and Unsafe copy from offheap memory to
> on-heap array triggered
> [here|https://github.com/apache/hbase/blob/branch-2.1/hbase-common/src/main/java/org/apache/hadoop/hbase/util/ByteBufferUtils.java#L1157],
> such as when writing into a non ByteBufferWriter type, as done
> [here|https://github.com/apache/hbase/blob/branch-2.1/hbase-common/src/main/java/org/apache/hadoop/hbase/io/ByteBufferWriterOutputStream.java#L84].
> More details on the following comment.
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
