[ https://issues.apache.org/jira/browse/HBASE-23084?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16940131#comment-16940131 ]
ranpanfeng commented on HBASE-23084: ------------------------------------ [~zhangduo] git commit: 0ba7cc01a13dbb7fec8e6c5d599fc8b4936bae61 git tag: rel/2.1.5 > Assertion "Added a key not lexically larger than previous" or "prevKey > followed by a smaller key" caused abortion of RS > -------------------------------------------------------------------------------------------------------------------------- > > Key: HBASE-23084 > URL: https://issues.apache.org/jira/browse/HBASE-23084 > Project: HBase > Issue Type: Bug > Components: regionserver > Environment: We store many phoenix tables in hbase, only one table > trigger this issues. > When two jacent keys in wrong order, the observation as follows. > 1. the prevKey is written into hbase via Put rpc > 2. the current key via phoenix upsert statment( Multi rpc in underlying hbase) > 3. the current Cell extends 1MB. > 4. the error is easy to re-ocurr. > Reporter: ranpanfeng > Priority: Critical > > when auto flush and manual flush is invoked, cell in immutable memstore > segment is scanned one by one to build data block and bloom filter block, > during this time, two adjacent keys are compared to assert that they are in > lexicographical order, but regretfully, the assertion fails in some > scenarios, when RS encounter these assertion failure, always call abort > function to terminate abnormally. > > the version is 0ba7cc01a13dbb7fec8e6c5d599fc8b4936bae61 tag: rel/2.1.5 > > At least three cases are found. > *error case#1: getQualifierArray throws > java.lang.ArrayIndexOutOfBoundsException* > > {code:java} > 17:57:50.328 [MemStoreFlusher.0] ERROR > org.apache.hadoop.hbase.regionserver.HRegionServer - ***** ABORTING region > server ${regionserver}: Replay of WAL required. Forcing server shutdown ***** > org.apache.hadoop.hbase.DroppedSnapshotException: region: ${region}. > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushCacheAndCommit(HRegion.java:2788) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushcache(HRegion.java:2467) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushcache(HRegion.java:2439) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.flushcache(HRegion.java:2329) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.MemStoreFlusher.flushRegion(MemStoreFlusher.java:612) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.MemStoreFlusher.flushRegion(MemStoreFlusher.java:581) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.MemStoreFlusher.access$1000(MemStoreFlusher.java:68) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.MemStoreFlusher$FlushHandler.run(MemStoreFlusher.java:361) > [hbase-server-2.1.5.jar:2.1.5] > at java.lang.Thread.run(Thread.java:748) [?:1.8.0_144] > Caused by: java.lang.ArrayIndexOutOfBoundsException > at > org.apache.hadoop.hbase.util.ByteBufferUtils.copyFromBufferToArray(ByteBufferUtils.java:1155) > ~[hbase-common-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.CellUtil.copyQualifierTo(CellUtil.java:309) > ~[hbase-common-2.1.5.jar:2.1.5] > at org.apache.hadoop.hbase.CellUtil.cloneQualifier(CellUtil.java:121) > ~[hbase-common-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.ByteBufferKeyValue.getQualifierArray(ByteBufferKeyValue.java:112) > ~[hbase-common-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.CellUtil.getCellKeyAsString(CellUtil.java:1306) > ~[hbase-common-2.1.5.jar:2.1.5] > at org.apache.hadoop.hbase.CellUtil.toString(CellUtil.java:1483) > ~[hbase-common-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.ByteBufferKeyValue.toString(ByteBufferKeyValue.java:296) > ~[hbase-common-2.1.5.jar:2.1.5] > at java.lang.String.valueOf(String.java:2994) ~[?:1.8.0_144] > at java.lang.StringBuilder.append(StringBuilder.java:131) > ~[?:1.8.0_144] > at > org.apache.hadoop.hbase.regionserver.StoreScanner.checkScanOrder(StoreScanner.java:1007) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:582) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreFlusher.performFlush(StoreFlusher.java:127) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.DefaultStoreFlusher.flushSnapshot(DefaultStoreFlusher.java:69) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HStore.flushCache(HStore.java:1021) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HStore$StoreFlusherImpl.flushCache(HStore.java:2259) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushCacheAndCommit(HRegion.java:2733) > ~[hbase-server-2.1.5.jar:2.1.5] > ... 8 more > 17:57:50.332 [MemStoreFlusher.0] ERROR > org.apache.hadoop.hbase.regionserver.HRegionServer - RegionServer abort: > loaded coprocessors are: [org.apache.phoenix.coprocessor.ScanRegionObserver, > org.apache.phoenix.coprocessor.UngroupedAggregateRegionObserver, > org.apache.phoenix.hbase.index.Indexer, > org.apache.phoenix.coprocessor.GroupedAggregateRegionObserver, > org.apache.phoenix.coprocessor.ServerCachingEndpointImpl] > > {code} > > > *error case#2: StoreScanner.checkScanOrder triggers "prevKey followed by a > smaller key"* > > {code:java} > Exception in thread "RS_IN_MEMORY_COMPACTION-regionserver/${regionserver}" > java.lang.AssertionError: Key ${prevKey} followed by a smaller key ${key} > at > org.apache.hadoop.hbase.regionserver.StoreScanner.checkScanOrder(StoreScanner.java:1007) > at > org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:582) > at > org.apache.hadoop.hbase.regionserver.MemStoreCompactorSegmentsIterator.refillKVS(MemStoreCompactorSegmentsIterator.java:150) > at > org.apache.hadoop.hbase.regionserver.MemStoreCompactorSegmentsIterator.hasNext(MemStoreCompactorSegmentsIterator.java:72) > at > org.apache.hadoop.hbase.regionserver.CellChunkImmutableSegment.initializeCellSet(CellChunkImmutableSegment.java:146) > at > org.apache.hadoop.hbase.regionserver.CellChunkImmutableSegment.<init>(CellChunkImmutableSegment.java:66) > at > org.apache.hadoop.hbase.regionserver.SegmentFactory.createImmutableSegment(SegmentFactory.java:133) > at > org.apache.hadoop.hbase.regionserver.SegmentFactory.createImmutableSegmentByCompaction(SegmentFactory.java:59) > at > org.apache.hadoop.hbase.regionserver.MemStoreCompactor.createSubstitution(MemStoreCompactor.java:217) > at > org.apache.hadoop.hbase.regionserver.MemStoreCompactor.doCompaction(MemStoreCompactor.java:171) > at > org.apache.hadoop.hbase.regionserver.MemStoreCompactor.start(MemStoreCompactor.java:109) > at > org.apache.hadoop.hbase.regionserver.CompactingMemStore.flushInMemory(CompactingMemStore.java:422) > at > org.apache.hadoop.hbase.regionserver.CompactingMemStore$InMemoryFlushRunnable.run(CompactingMemStore.java:534) > 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:748) > at java.lang.Thread.run(Thread.java:748) > 12:34:07.695 [MemStoreFlusher.0] INFO > org.apache.hadoop.hbase.regionserver.HRegion - Flushing 1/1 column families, > dataSize=239.26 MB heapSize=256.00 MB > 12:34:08.476 [MemStoreFlusher.0] ERROR > org.apache.hadoop.hbase.regionserver.HRegionServer - ***** ABORTING region > server ${regionserver}: Replay of WAL required. Forcing server shutdown ***** > org.apache.hadoop.hbase.DroppedSnapshotException: region: ${region}. > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushCacheAndCommit(HRegion.java:2788) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushcache(HRegion.java:2467) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushcache(HRegion.java:2439) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.flushcache(HRegion.java:2329) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.MemStoreFlusher.flushRegion(MemStoreFlusher.java:612) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.MemStoreFlusher.flushRegion(MemStoreFlusher.java:581) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.MemStoreFlusher.access$1000(MemStoreFlusher.java:68) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.MemStoreFlusher$FlushHandler.run(MemStoreFlusher.java:361) > [hbase-server-2.1.5.jar:2.1.5] > at java.lang.Thread.run(Thread.java:748) [?:1.8.0_144] > Caused by: java.lang.AssertionError: Key ${prevKey} followed by a smaller key > ${key} > at > org.apache.hadoop.hbase.regionserver.StoreScanner.checkScanOrder(StoreScanner.java:1007) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:582) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreFlusher.performFlush(StoreFlusher.java:127) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.DefaultStoreFlusher.flushSnapshot(DefaultStoreFlusher.java:69) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HStore.flushCache(HStore.java:1021) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HStore$StoreFlusherImpl.flushCache(HStore.java:2259) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushCacheAndCommit(HRegion.java:2733) > ~[hbase-server-2.1.5.jar:2.1.5] > ... 8 more > {code} > > > > *error case#3: BloomContext.sanityCheck triggers "Added a key not lexically > larger than previous."* > so, I alter the assertion code into if stmt > {code:java} > --- > a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/ByteBufferUtils.java > +++ > b/hbase-common/src/main/java/org/apache/hadoop/hbase/util/ByteBufferUtils.java > @@ -33,6 +33,8 @@ import org.apache.hadoop.hbase.io.util.StreamUtils; > import org.apache.hadoop.io.IOUtils; > import org.apache.hadoop.io.WritableUtils; > import org.apache.yetus.audience.InterfaceAudience; > +import org.slf4j.Logger; > +import org.slf4j.LoggerFactory; > import sun.nio.ch.DirectBuffer; > > import > org.apache.hbase.thirdparty.com.google.common.annotations.VisibleForTesting; > @@ -51,6 +53,7 @@ public final class ByteBufferUtils { > @VisibleForTesting > final static boolean UNSAFE_AVAIL = UnsafeAvailChecker.isAvailable(); > public final static boolean UNSAFE_UNALIGNED = > UnsafeAvailChecker.unaligned(); > + private static Logger LOG = LoggerFactory.getLogger(ByteBufferUtils.class); > > private ByteBufferUtils() { > } > @@ -1152,7 +1155,18 @@ public final class ByteBufferUtils { > public static void copyFromBufferToArray(byte[] out, ByteBuffer in, int > sourceOffset, > int destinationOffset, int length) { > if (in.hasArray()) { > - System.arraycopy(in.array(), sourceOffset + in.arrayOffset(), out, > destinationOffset, length); > + try { > + System.arraycopy(in.array(), sourceOffset + in.arrayOffset(), out, > destinationOffset, length); > + } catch (Throwable e){ > + if (out == null) { > + LOG.warn("[QINGGUI] out=null"); > + } else if (in == null || in.array() == null) { > + LOG.warn("[QINGGUI] in=null"); > + } else { > + LOG.warn("[QINGGUI] out.length={}, in.length={}, sourceOffset={} > destinationOffset={} length={}", > + out.length, in.array().length, sourceOffset, destinationOffset, > length); > + } > + } > } else if (UNSAFE_AVAIL) { > UnsafeAccess.copy(in, sourceOffset, out, destinationOffset, length); > } else { > {code} > > re-deploy my binary, then the failure drifts to bloom filter building code. > {code:java} > 12:54:39.966 [rs(${regionserver})-flush-proc-pool3-thread-2] WARN > org.apache.hadoop.hbase.regionserver.HStore - Failed flushing store file, > retrying num=9 > java.io.IOException: Added a key not lexically larger than previous. Current > cell ... > at > org.apache.hadoop.hbase.util.BloomContext.sanityCheck(BloomContext.java:63) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.util.BloomContext.writeBloom(BloomContext.java:54) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreFileWriter.appendGeneralBloomfilter(StoreFileWriter.java:213) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreFileWriter.append(StoreFileWriter.java:232) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreFlusher.performFlush(StoreFlusher.java:133) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.DefaultStoreFlusher.flushSnapshot(DefaultStoreFlusher.java:69) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HStore.flushCache(HStore.java:1021) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HStore$StoreFlusherImpl.flushCache(HStore.java:2259) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushCacheAndCommit(HRegion.java:2733) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushcache(HRegion.java:2467) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushcache(HRegion.java:2439) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.flushcache(HRegion.java:2329) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.flush(HRegion.java:2232) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.procedure.flush.FlushTableSubprocedure$RegionFlushTask.call(FlushTableSubprocedure.java:68) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.procedure.flush.FlushTableSubprocedure$RegionFlushTask.call(FlushTableSubprocedure.java:56) > [hbase-server-2.1.5.jar:2.1.5] > at java.util.concurrent.FutureTask.run(FutureTask.java:266) > [?:1.8.0_144] > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) > [?:1.8.0_144] > at java.util.concurrent.FutureTask.run(FutureTask.java:266) > [?:1.8.0_144] > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) > [?:1.8.0_144] > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) > [?:1.8.0_144] > at java.lang.Thread.run(Thread.java:748) [?:1.8.0_144] > 12:54:39.979 [rs(${regionserver})-flush-proc-pool3-thread-2] ERROR > org.apache.hadoop.hbase.regionserver.HRegionServer - ***** ABORTING region > server ${regionserver}: Replay of WAL required. Forcing server shutdown ***** > org.apache.hadoop.hbase.DroppedSnapshotException: region: ${region}. > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushCacheAndCommit(HRegion.java:2788) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushcache(HRegion.java:2467) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushcache(HRegion.java:2439) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.flushcache(HRegion.java:2329) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.flush(HRegion.java:2232) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.procedure.flush.FlushTableSubprocedure$RegionFlushTask.call(FlushTableSubprocedure.java:68) > [hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.procedure.flush.FlushTableSubprocedure$RegionFlushTask.call(FlushTableSubprocedure.java:56) > [hbase-server-2.1.5.jar:2.1.5] > at java.util.concurrent.FutureTask.run(FutureTask.java:266) > [?:1.8.0_144] > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) > [?:1.8.0_144] > at java.util.concurrent.FutureTask.run(FutureTask.java:266) > [?:1.8.0_144] > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) > [?:1.8.0_144] > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) > [?:1.8.0_144] > at java.lang.Thread.run(Thread.java:748) [?:1.8.0_144] > Caused by: java.io.IOException: Added a key not lexically larger than > previous. Current cell = ... > at > org.apache.hadoop.hbase.util.BloomContext.sanityCheck(BloomContext.java:63) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.util.BloomContext.writeBloom(BloomContext.java:54) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreFileWriter.appendGeneralBloomfilter(StoreFileWriter.java:213) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreFileWriter.append(StoreFileWriter.java:232) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.StoreFlusher.performFlush(StoreFlusher.java:133) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.DefaultStoreFlusher.flushSnapshot(DefaultStoreFlusher.java:69) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HStore.flushCache(HStore.java:1021) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HStore$StoreFlusherImpl.flushCache(HStore.java:2259) > ~[hbase-server-2.1.5.jar:2.1.5] > at > org.apache.hadoop.hbase.regionserver.HRegion.internalFlushCacheAndCommit(HRegion.java:2733) > ~[hbase-server-2.1.5.jar:2.1.5] > ... 12 more > {code} > -- This message was sent by Atlassian Jira (v8.3.4#803005)