[
https://issues.apache.org/jira/browse/HBASE-23591?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Guanghao Zhang updated HBASE-23591:
-----------------------------------
Fix Version/s: (was: 2.2.2)
2.2.7
> Negative memStoreSizing
> -----------------------
>
> Key: HBASE-23591
> URL: https://issues.apache.org/jira/browse/HBASE-23591
> Project: HBase
> Issue Type: Bug
> Components: read replicas
> Reporter: Szabolcs Bukros
> Priority: Major
> Fix For: 2.2.7
>
>
> After a flush on the replica region the memStoreSizing becomes negative:
> {code:java}
> 2019-12-17 08:31:59,983 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Replaying flush marker action:
> COMMIT_FLUSH table_name: "IntegrationTestRegionReplicaReplicati
> on" encoded_region_name: "544affde3e027454f67c8ea46c8f69ee"
> flush_sequence_number: 41392 store_flushes { family_name: "f1"
> store_home_dir: "f1" flush_output: "3c48a23eac784a348a18e10e337d80a2" }
> store_flushes { family_name: "f2" store_home_dir: "f2" flush_output:
> "9a5283ec95694667b4ead2398af5f01e" } store_flushes { family_name: "f3"
> store_home_dir: "f3" flush_output: "e6f25e6b0eca4d22af15d0626d0f8759" }
> region_name:
> "IntegrationTestRegionReplicaReplication,bbbbbbbb,1576599911697.544affde3e027454f67c8ea46c8f69ee."
> 2019-12-17 08:31:59,984 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Received a flush commit marker with
> seqId:41392 and a previous prepared snapshot was found
> 2019-12-17 08:31:59,993 INFO org.apache.hadoop.hbase.regionserver.HStore:
> Region: 0beaae111b0f6e98bfde31ba35be5408 added
> hdfs://replica-1:8020/hbase/data/default/IntegrationTestRegionReplicaReplication/544affde3e027454f67c8ea46c8f69ee/f1/3c48a23eac784a348a18e10e337d80a2,
> entries=32445, sequenceid=41392, filesize=27.6 M
> 2019-12-17 08:32:00,016 INFO org.apache.hadoop.hbase.regionserver.HStore:
> Region: 0beaae111b0f6e98bfde31ba35be5408 added
> hdfs://replica-1:8020/hbase/data/default/IntegrationTestRegionReplicaReplication/544affde3e027454f67c8ea46c8f69ee/f2/9a5283ec95694667b4ead2398af5f01e,
> entries=12264, sequenceid=41392, filesize=10.9 M
> 2019-12-17 08:32:00,121 INFO org.apache.hadoop.hbase.regionserver.HStore:
> Region: 0beaae111b0f6e98bfde31ba35be5408 added
> hdfs://replica-1:8020/hbase/data/default/IntegrationTestRegionReplicaReplication/544affde3e027454f67c8ea46c8f69ee/f3/e6f25e6b0eca4d22af15d0626d0f8759,
> entries=32379, sequenceid=41392, filesize=27.5 M
> 2019-12-17 08:32:00,122 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> CustomLog decrMemStoreSize. Current: dataSize=135810071,
> getHeapSize=148400960, getOffHeapSize=0, getCellsCount=167243 delta:
> dataSizeDelta=155923644, heapSizeDelta=170112320, offHeapSizeDelta=0,
> cellsCountDelta=188399
> 2019-12-17 08:32:00,122 ERROR org.apache.hadoop.hbase.regionserver.HRegion:
> Asked to modify this region's
> (IntegrationTestRegionReplicaReplication,bbbbbbbb,1576599911697_0001.0beaae111b0f6e98bfde31ba35be54
> 08.) memStoreSizing to a negative value which is incorrect. Current
> memStoreSizing=135810071, delta=-155923644
> java.lang.Exception
> at
> org.apache.hadoop.hbase.regionserver.HRegion.checkNegativeMemStoreDataSize(HRegion.java:1323)
> at
> org.apache.hadoop.hbase.regionserver.HRegion.decrMemStoreSize(HRegion.java:1316)
> at
> org.apache.hadoop.hbase.regionserver.HRegion.decrMemStoreSize(HRegion.java:1303)
> at
> org.apache.hadoop.hbase.regionserver.HRegion.replayWALFlushCommitMarker(HRegion.java:5194)
> at
> org.apache.hadoop.hbase.regionserver.HRegion.replayWALFlushMarker(HRegion.java:5025)
> at
> org.apache.hadoop.hbase.regionserver.RSRpcServices.doReplayBatchOp(RSRpcServices.java:1143)
> at
> org.apache.hadoop.hbase.regionserver.RSRpcServices.replay(RSRpcServices.java:2232)
> at
> org.apache.hadoop.hbase.shaded.protobuf.generated.AdminProtos$AdminService$2.callBlockingMethod(AdminProtos.java:29754)
> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:413)
> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:133)
> at
> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:338)
> at
> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:318)
> {code}
> I added some custom logging to the snapshot logic to be able to see snapshot
> sizes:
> {code:java}
> 2019-12-17 08:31:56,900 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Replaying flush marker action: START_FLUSH
> table_name: "IntegrationTestRegionReplicaReplication" encoded_region_name:
> "544affde3e027454f67c8ea46c8f69ee" flush_sequence_number: 41392 store_flushes
> { family_name: "f1" store_home_dir: "f1" } store_flushes { family_name: "f2"
> store_home_dir: "f2" } store_flushes { family_name: "f3" store_home_dir: "f3"
> } region_name:
> "IntegrationTestRegionReplicaReplication,bbbbbbbb,1576599911697.544affde3e027454f67c8ea46c8f69ee."
> 2019-12-17 08:31:56,900 INFO org.apache.hadoop.hbase.regionserver.HRegion:
> Flushing 0beaae111b0f6e98bfde31ba35be5408 3/3 column families,
> dataSize=126.49 MB heapSize=138.24 MB
> 2019-12-17 08:31:56,900 WARN
> org.apache.hadoop.hbase.regionserver.DefaultMemStore: Snapshot called again
> without clearing previous. Doing nothing. Another ongoing flush or did we
> fail last attempt?
> 2019-12-17 08:31:56,900 DEBUG
> org.apache.hadoop.hbase.regionserver.DefaultMemStore: CustomLog snapshot for
> region: {ENCODED => 0beaae111b0f6e98bfde31ba35be5408, NAME =>
> 'IntegrationTestRegionReplicaReplication,bbbbbbbb,1576599911697_0001.0beaae111b0f6e98bfde31ba35be5408.',
> STARTKEY => 'bbbbbbbb', ENDKEY => 'cccccccc', REPLICA_ID => 1} memstore:
> dataSize=41660529, getHeapSize=45422304, getOffHeapSize=0, getCellsCount=49951
> 2019-12-17 08:31:56,901 DEBUG
> org.apache.hadoop.hbase.regionserver.DefaultMemStore: CustomLog snapshot for
> region: {ENCODED => 0beaae111b0f6e98bfde31ba35be5408, NAME =>
> 'IntegrationTestRegionReplicaReplication,bbbbbbbb,1576599911697_0001.0beaae111b0f6e98bfde31ba35be5408.',
> STARTKEY => 'bbbbbbbb', ENDKEY => 'cccccccc', REPLICA_ID => 1} memstore:
> dataSize=72246315, getHeapSize=78890240, getOffHeapSize=0, getCellsCount=88222
> 2019-12-17 08:31:56,901 WARN
> org.apache.hadoop.hbase.regionserver.DefaultMemStore: Snapshot called again
> without clearing previous. Doing nothing. Another ongoing flush or did we
> fail last attempt?
> 2019-12-17 08:31:56,901 DEBUG
> org.apache.hadoop.hbase.regionserver.DefaultMemStore: CustomLog snapshot for
> region: {ENCODED => 0beaae111b0f6e98bfde31ba35be5408, NAME =>
> 'IntegrationTestRegionReplicaReplication,bbbbbbbb,1576599911697_0001.0beaae111b0f6e98bfde31ba35be5408.',
> STARTKEY => 'bbbbbbbb', ENDKEY => 'cccccccc', REPLICA_ID => 1} memstore:
> dataSize=42016800, getHeapSize=45799776, getOffHeapSize=0, getCellsCount=50226
> 2019-12-17 08:31:56,901 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Prepared flush with seqId:41392
> {code}
> This shows that snapshots combined size is actually bigger than the region's
> memStoreSizing. So when do we decrease memStoreSizing without actually
> flushing?
> A bit earlier in the log I found this:
> {code:java}
> 2019-12-17 08:31:43,581 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Replaying flush marker action: START_FLUSH
> table_name: "IntegrationTestRegionReplicaReplication" encoded_region_name:
> "544affde3e027454f67c8ea46c8f69ee" flush_sequence_number: 40445 store_flushes
> { family_name: "f2" store_home_dir: "f2" } region_name:
> "IntegrationTestRegionReplicaReplication,bbbbbb
> bb,1576599911697.544affde3e027454f67c8ea46c8f69ee."
> 2019-12-17 08:31:43,582 WARN org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Received a flush prepare marker with a
> larger seqId: 40445 before clearing the previous one with seqId: 20747.
> Ignoring
> 2019-12-17 08:31:43,582 TRACE org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Store files for region:
> 2019-12-17 08:31:43,582 INFO org.apache.hadoop.hbase.regionserver.HRegion:
> writing data to region
> IntegrationTestRegionReplicaReplication,bbbbbbbb,1576599911697_0001.0beaae111b0f6e98bfde31ba35be5408.
> with WAL disabled. Data may be lost in the event of a crash.
> 2019-12-17 08:31:43,586 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Replaying flush marker action:
> COMMIT_FLUSH table_name: "IntegrationTestRegionReplicaReplication"
> encoded_region_name: "544affde3e027454f67c8ea46c8f69ee"
> flush_sequence_number: 40445 store_flushes { family_name: "f2"
> store_home_dir: "f2" flush_output: "3f6a5302b36a4a65a6caa291a03f108d" }
> region_name:
> "IntegrationTestRegionReplicaReplication,bbbbbbbb,1576599911697.544affde3e027454f67c8ea46c8f69ee."
> 2019-12-17 08:31:43,586 WARN org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Received a flush commit marker with larger
> seqId: 40445 than what we have prepared with seqId:
> 20747. Picking up new file and dropping prepared memstore snapshot
> 2019-12-17 08:31:43,587 WARN org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Unexpected: flush commit marker received
> from store f2 but no associated flush context. Ignoring
> 2019-12-17 08:31:43,587 DEBUG org.apache.hadoop.hbase.regionserver.HRegion:
> CustomLog decrMemStoreSize. Current: dataSize=184492444,
> getHeapSize=201769960, getOffHeapSize=0, getCellsCount=229450 delta:
> dataSizeDelta=83677329, heapSizeDelta=91222080, offHeapSizeDelta=0,
> cellsCountDelta=100177
> 2019-12-17 08:31:43,587 INFO org.apache.hadoop.hbase.regionserver.HRegion:
> 0beaae111b0f6e98bfde31ba35be5408 : Not dropping memstore contents since
> replayed flush seqId: 40445 is smaller than current seqId:40481
> {code}
> Based on this the issues seems to originate from HRegion.replayFlushInStores.
> The StoreFlushContext is missing, we show a warning and continue the
> execution with the next StoreFlushDescriptor without actually flushing the
> snapshot in question. However replayWALFlushCommitMarker is unaware of the
> warn and continues assuming the flush was successful and decreasing the
> memStoreSizing (and doing cleanup).
>
> We should consider decreasing the memStoreSizing on a per store level instead
> of on the region level and do the negativity check before we do it,
> potentially preventing a flush if needed, to make sure we keep the
> memStoreSizing positive.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
