[HBASE-24090] Regions Stuck in RIT in OPEN state

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Cannot Reproduce
• Component/s: amv2
• Assignee: Unassigned
• Reporter: Pankaj Kumar
• Created: 31/Mar/20 08:07
• Updated: 30/Jun/20 11:58
• Resolved: 30/Jun/20 11:58

Description

Observed few regions stuck in RIT in OPEN state in a cluster restart scenario.

Analysis:
1. All RS were killed abruptly.

2. HMaster start SCP and initiated region assignments

2020-03-24 22:27:08,821 | INFO  | PEWorker-20 | Initialized subprocedures=[
{pid=49703, ppid=46611, state=RUNNABLE:REGION_STATE_TRANSITION_GET_ASSIGN_CANDIDATE; TransitRegionStateProcedure table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6, ASSIGN},...] | org.apache.hadoop.hbase.procedure2.ProcedureExecutor.execProcedure(ProcedureExecutor.java:1697)

But HMaster failover happens before it complete.

4. New active master load the previous procedures and restore to RIT

2020-03-24 22:30:04,815 | INFO  | master/HM-IP:HM-PORT:becomeActiveMaster | Attach pid=49703, ppid=46611, state=RUNNABLE:REGION_STATE_TRANSITION_GET_ASSIGN_CANDIDATE; TransitRegionStateProcedure table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6, ASSIGN to rit=OFFLINE, location=null, table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6 to restore RIT | org.apache.hadoop.hbase.master.assignment.AssignmentManager.lambda$setupRIT$0(AssignmentManager.java:280)
---
2020-03-24 22:32:52,153 | WARN  | ProcExecTimeout | STUCK Region-In-Transition rit=OPEN, location=RS-IP,RS-Port,1585057875346, table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6 | org.apache.hadoop.hbase.master.assignment.AssignmentManager.handleRegionOverStuckWarningThreshold(AssignmentManager.java:1340)
---
2020-03-24 22:41:51,837 | WARN  | master/HM-IP:HM-PORT.Chore.1 | unknown_server=RS-IP,RS-Port,1585057875346/usertable01,user10268,1585053943990.871858cf2ef25a9e0e6b4f022a16ebc9.,.... | org.apache.hadoop.hbase.master.CatalogJanitor.scan(CatalogJanitor.java:181)

Region assignment was slow as we are testing with huge number of regions per RS, so RIT WARN message logged.

5. Finally region was assigned
HM log:

2020-03-24 22:42:26,386 | INFO  | PEWorker-11 | Took xlock for pid=49703, ppid=46611, state=RUNNABLE:REGION_STATE_TRANSITION_GET_ASSIGN_CANDIDATE; TransitRegionStateProcedure table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6, ASSIGN | org.apache.hadoop.hbase.master.procedure.MasterProcedureScheduler.waitRegions(MasterProcedureScheduler.java:737)
2020-03-24 22:42:26,446 | INFO  | PEWorker-11 | Starting pid=49703, ppid=46611, state=RUNNABLE:REGION_STATE_TRANSITION_GET_ASSIGN_CANDIDATE, locked=true; TransitRegionStateProcedure table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6, ASSIGN; rit=OPEN, location=null; forceNewPlan=true, retain=false | org.apache.hadoop.hbase.master.assignment.TransitRegionStateProcedure.queueAssign(TransitRegionStateProcedure.java:189)
2020-03-24 22:42:26,717 | INFO  | PEWorker-17 | pid=49703 updating hbase:meta row=75a79e978362d6f4ee1a3e27dfc5d4b6, regionState=OPENING, regionLocation=RS-IP,RS-Port,1585060304365 | org.apache.hadoop.hbase.master.assignment.RegionStateStore.updateUserRegionLocation(RegionStateStore.java:201)
2020-03-24 22:42:27,439 | INFO  | PEWorker-19 | pid=49703 updating hbase:meta row=75a79e978362d6f4ee1a3e27dfc5d4b6, regionState=OPEN, openSeqNum=5, regionLocation=RS-IP,RS-Port,1585060304365 | org.apache.hadoop.hbase.master.assignment.RegionStateStore.updateUserRegionLocation(RegionStateStore.java:201)
2020-03-24 22:42:27,701 | INFO  | PEWorker-19 | Finished subprocedure pid=73705, resume processing parent pid=49703, ppid=46611, state=RUNNABLE:REGION_STATE_TRANSITION_CONFIRM_OPENED, locked=true; TransitRegionStateProcedure table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6, ASSIGN | org.apache.hadoop.hbase.procedure2.ProcedureExecutor.countDownChildren(ProcedureExecutor.java:1837)
2020-03-24 22:42:27,821 | INFO  | PEWorker-15 | Finished pid=49703, ppid=46611, state=SUCCESS; TransitRegionStateProcedure table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6, ASSIGN in 15mins, 18.888sec | org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeProcedure(ProcedureExecutor.java:1427)

RS Log:

2020-03-24 22:42:27,230 | INFO  | RS_OPEN_REGION-regionserver/RS-IP:RS-Port-34 | Open usertable18,user29616,1585055007688.75a79e978362d6f4ee1a3e27dfc5d4b6. | org.apache.hadoop.hbase.regionserver.handler.AssignRegionHandler.process(AssignRegionHandler.java:123)
2020-03-24 22:42:27,241 | INFO  | StoreOpener-75a79e978362d6f4ee1a3e27dfc5d4b6-1 | Created cacheConfig: cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false for family {NAME => 'family', VERSIONS => '1', EVICT_BLOCKS_ON_CLOSE => 'false', NEW_VERSION_BEHAVIOR => 'false', KEEP_DELETED_CELLS => 'FALSE', CACHE_DATA_ON_WRITE => 'false', DATA_BLOCK_ENCODING => 'NONE', TTL => 'FOREVER', MIN_VERSIONS => '0', REPLICATION_SCOPE => '0', BLOOMFILTER => 'ROW', CACHE_INDEX_ON_WRITE => 'false', IN_MEMORY => 'false', CACHE_BLOOMS_ON_WRITE => 'false', PREFETCH_BLOCKS_ON_OPEN => 'false', COMPRESSION => 'NONE', BLOCKCACHE => 'true', BLOCKSIZE => '65536'} with blockCache=LruBlockCache{blockCount=0, currentSize=5.74 MB, freeSize=7.64 GB, maxSize=7.65 GB, heapSize=5.74 MB, minSize=7.27 GB, minFactor=0.95, multiSize=3.63 GB, multiFactor=0.5, singleSize=1.82 GB, singleFactor=0.25} | org.apache.hadoop.hbase.io.hfile.CacheConfig.<init>(CacheConfig.java:174)
2020-03-24 22:42:27,242 | INFO  | StoreOpener-75a79e978362d6f4ee1a3e27dfc5d4b6-1 | size [128 MB, 8.00 EB, 8.00 EB); files [6, 10); ratio 1.200000; off-peak ratio 5.000000; throttle point 1610612736; major period 604800000, major jitter 0.500000, min locality to compact 0.000000; tiered compaction: max_age 9223372036854775807, incoming window min 6, compaction policy for tiered window org.apache.hadoop.hbase.regionserver.compactions.ExploringCompactionPolicy, single output for minor true, compaction window factory org.apache.hadoop.hbase.regionserver.compactions.ExponentialCompactionWindowFactory | org.apache.hadoop.hbase.regionserver.compactions.CompactionConfiguration.<init>(CompactionConfiguration.java:147)
2020-03-24 22:42:27,243 | INFO  | StoreOpener-75a79e978362d6f4ee1a3e27dfc5d4b6-1 | Store=family,  memstore type=DefaultMemStore, storagePolicy=HOT, verifyBulkLoads=false, parallelPutCountPrintThreshold=50, encoding=NONE, compression=NONE | org.apache.hadoop.hbase.regionserver.HStore.<init>(HStore.java:335)
2020-03-24 22:42:27,252 | INFO  | RS_OPEN_REGION-regionserver/RS-IP:RS-Port-34 | Opened 75a79e978362d6f4ee1a3e27dfc5d4b6; next sequenceid=5 | org.apache.hadoop.hbase.regionserver.HRegion.initializeRegionInternals(HRegion.java:1067)
2020-03-24 22:42:27,254 | INFO  | RS_OPEN_REGION-regionserver/RS-IP:RS-Port-34 | Post open deploy tasks for usertable18,user29616,1585055007688.75a79e978362d6f4ee1a3e27dfc5d4b6., openProcId=73705, masterSystemTime=1585060947225 | org.apache.hadoop.hbase.regionserver.HRegionServer.postOpenDeployTasks(HRegionServer.java:2379)
2020-03-24 22:42:27,320 | INFO  | RS_OPEN_REGION-regionserver/RS-IP:RS-Port-34 | Opened usertable18,user29616,1585055007688.75a79e978362d6f4ee1a3e27dfc5d4b6. | org.apache.hadoop.hbase.regionserver.handler.AssignRegionHandler.process(AssignRegionHandler.java:141)

6. Evn though region was opened successfully but still the region in RIT, in OPEN state

2020-03-24 22:49:05,432 | WARN  | ProcExecTimeout | STUCK Region-In-Transition rit=OPEN, location=RS-IP,RS-Port,1585060304365, table=usertable18, region=75a79e978362d6f4ee1a3e27dfc5d4b6 | org.apache.hadoop.hbase.master.assignment.AssignmentManager.handleRegionOverStuckWarningThreshold(AssignmentManager.java:1340)

This WARN message keep occuring in HM log.

HBase version: 2.2.3