You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Jacobo Coll (JIRA)" <ji...@apache.org> on 2019/07/04 12:44:00 UTC
[jira] [Commented] (HBASE-20817) Infinite loop when executing
ReopenTableRegionsProcedure
[ https://issues.apache.org/jira/browse/HBASE-20817?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16878622#comment-16878622 ]
Jacobo Coll commented on HBASE-20817:
-------------------------------------
Hi team,
I'm not sure if I should open a new ticket or not.
I am having this same issue in a Hortonworks HBase [2.0.2.3.1.2.1-1|https://repo.hortonworks.com/content/repositories/releases/org/apache/hbase/hbase-server/2.0.2.3.1.2.1-1/] , where it should be fixed (I've checked that this patch was applied to that build)
Just after creating a "view" in phoenix over an existing table, the "ModifyTableProcedure" triggers a "ReopenTableRegionsProcedure" that enters into this infinite loop of "MoveRegionProcedure". This loop has a lapse of ~5s, and it fills up the list of procedures, and the procedure wal is not cleanup, as it never finishes the running procedure.
Please, find here a selected portion of the hbase-master log. The affected table has a pre-split of 100, so the log is quite large. I've shrunken some lines with dots.
{noformat}
2019-07-03 16:12:27,924 INFO [PEWorker-8] procedure2.ProcedureExecutor: Initialized subprocedures=[{pid=267, ppid=266, state=RUNNABLE:REOPEN_TABLE_REGIONS_GET_REGIONS; ReopenTableRegionsProcedure table=opencga_jcoll_grch38_variants}]
2019-07-03 16:12:28,059 INFO [PEWorker-2] procedure2.ProcedureExecutor: Initialized subprocedures=[{pid=268, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=fdad9893526ef840d117e6bea7c04bc5, source=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960, destination=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960}, {pid=269, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=7b8b7dc99aee4f524af41a86e10ac945, source=wn0-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131867, destination=wn0-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131867}, ...................................................................................................., {pid=368, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=60ccd4513bc298b83d062cb0172ccba9, source=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960, destination=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960}]
2019-07-03 16:12:28,096 INFO [PEWorker-5] procedure.MasterProcedureScheduler: Took xlock for pid=268, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=fdad9893526ef840d117e6bea7c04bc5, source=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960, destination=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960
2019-07-03 16:12:28,116 INFO [PEWorker-5] procedure2.ProcedureExecutor: Initialized subprocedures=[{pid=370, ppid=268, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, override=true, server=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960}]
2019-07-03 16:12:28,247 INFO [PEWorker-4] procedure.MasterProcedureScheduler: Took xlock for pid=370, ppid=268, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, override=true, server=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960
2019-07-03 16:12:28,280 INFO [PEWorker-4] assignment.RegionTransitionProcedure: Dispatch pid=370, ppid=268, state=RUNNABLE:REGION_TRANSITION_DISPATCH, locked=true; UnassignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, override=true, server=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960
2019-07-03 16:12:28,659 INFO [PEWorker-13] procedure2.ProcedureExecutor: Finished subprocedure pid=370, resume processing parent pid=268, ppid=267, state=RUNNABLE:MOVE_REGION_ASSIGN, locked=true; MoveRegionProcedure hri=fdad9893526ef840d117e6bea7c04bc5, source=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960, destination=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960
2019-07-03 16:12:28,659 INFO [PEWorker-13] procedure2.ProcedureExecutor: Finished pid=370, ppid=268, state=SUCCESS; UnassignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, override=true, server=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960 in 458msec, unfinishedSiblingCount=0
2019-07-03 16:12:28,662 INFO [PEWorker-8] procedure2.ProcedureExecutor: Initialized subprocedures=[{pid=408, ppid=268, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, target=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960}]
2019-07-03 16:12:28,687 INFO [PEWorker-8] procedure.MasterProcedureScheduler: Took xlock for pid=408, ppid=268, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, target=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960
2019-07-03 16:12:28,713 INFO [PEWorker-8] assignment.AssignProcedure: Starting pid=408, ppid=268, state=RUNNABLE:REGION_TRANSITION_QUEUE, locked=true; AssignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, target=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960; rit=OFFLINE, location=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960; forceNewPlan=false, retain=false target svr=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960
2019-07-03 16:12:28,909 INFO [PEWorker-13] assignment.RegionTransitionProcedure: Dispatch pid=408, ppid=268, state=RUNNABLE:REGION_TRANSITION_DISPATCH, locked=true; AssignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, target=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960
2019-07-03 16:12:29,435 INFO [PEWorker-13] procedure2.ProcedureExecutor: Finished subprocedure pid=408, resume processing parent pid=268, ppid=267, state=RUNNABLE, locked=true; MoveRegionProcedure hri=fdad9893526ef840d117e6bea7c04bc5, source=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960, destination=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960
2019-07-03 16:12:29,436 INFO [PEWorker-13] procedure2.ProcedureExecutor: Finished pid=408, ppid=268, state=SUCCESS; AssignProcedure table=opencga_jcoll_grch38_variants, region=fdad9893526ef840d117e6bea7c04bc5, target=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960 in 684msec, unfinishedSiblingCount=0
2019-07-03 16:12:29,494 INFO [PEWorker-14] procedure2.ProcedureExecutor: Finished pid=268, ppid=267, state=SUCCESS; MoveRegionProcedure hri=fdad9893526ef840d117e6bea7c04bc5, source=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960, destination=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960 in 1.3930sec, unfinishedSiblingCount=92
2019-07-03 16:12:36,744 INFO [PEWorker-12] procedure2.ProcedureExecutor: Finished subprocedure pid=275, resume processing parent pid=267, ppid=266, state=RUNNABLE:REOPEN_TABLE_REGIONS_CONFIRM_REOPENED; ReopenTableRegionsProcedure table=opencga_jcoll_grch38_variants
2019-07-03 16:12:36,744 INFO [PEWorker-12] procedure2.ProcedureExecutor: Finished pid=275, ppid=267, state=SUCCESS; MoveRegionProcedure hri=f552eccd01cfd00bc30bec5e19f398df, source=wn2-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131806, destination=wn2-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131806 in 8.4340sec, unfinishedSiblingCount=0
2019-07-03 16:12:36,744 INFO [PEWorker-12] procedure2.ProcedureExecutor: Finished subprocedure pid=275, resume processing parent pid=267, ppid=266, state=RUNNABLE:REOPEN_TABLE_REGIONS_CONFIRM_REOPENED; ReopenTableRegionsProcedure table=o
pencga_jcoll_grch38_variants
2019-07-03 16:12:36,744 INFO [PEWorker-12] procedure2.ProcedureExecutor: Finished pid=275, ppid=267, state=SUCCESS; MoveRegionProcedure hri=f552eccd01cfd00bc30bec5e19f398df, source=wn2-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.clouda
pp.net,16020,1562169131806, destination=wn2-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131806 in 8.4340sec, unfinishedSiblingCount=0
2019-07-03 16:12:36,791 INFO [PEWorker-5] procedure2.ProcedureExecutor: Initialized subprocedures=[{pid=571, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=fdad9893526ef840d117e6bea7c04bc5, source=wn1-opencg.5w3ff
4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960, destination=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960}, {pid=572, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProced
ure hri=7b8b7dc99aee4f524af41a86e10ac945, source=wn0-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131867, destination=wn0-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131867}, {pid=573
, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=545caf13911c04263c8f84f2c14783b7, source=wn4-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131742, destination=wn4-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131742}, {pid=574, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=6fd4397428a741d0fa67e1a2774f48d1, source=wn3-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131711, destination=wn3-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131711}, {pid=575, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=053f3ff2a77982f98bb399d60aa0942b, source=wn2-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131806, destination=wn2-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131806}, {pid=576, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=94415a23ead3e24367c12a0de1e90e28, source=wn4-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131742, destination=wn4-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131742}, {pid=577, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=eacf81f79287d01f721a352407d5a1a5, source=wn2-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131806, destination=wn2-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131806}, .................................................................................................................................., {pid=670, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=941c5d8178257b7fc6bfa76b7d760468, source=wn4-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131742, destination=wn4-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131742}, {pid=671, ppid=267, state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure hri=60ccd4513bc298b83d062cb0172ccba9, source=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960, destination=wn1-opencg.5w3ff4rocu0e1dpkokmkmgo5ib.zx.internal.cloudapp.net,16020,1562169131960}]
{noformat}
And then, the loop starts over
The ReopenTableRegionsProcedure is stuck at REOPEN_TABLE_REGIONS_CONFIRM_REOPENED, where it starts over again, so, somehow, this should be relaed with HBASE-20752
> Infinite loop when executing ReopenTableRegionsProcedure
> ---------------------------------------------------------
>
> Key: HBASE-20817
> URL: https://issues.apache.org/jira/browse/HBASE-20817
> Project: HBase
> Issue Type: Bug
> Components: Region Assignment
> Affects Versions: 2.0.0
> Reporter: Duo Zhang
> Assignee: Ankit Singhal
> Priority: Blocker
> Fix For: 3.0.0, 2.1.0, 2.0.2
>
> Attachments: HBASE-20817-v1.patch, HBASE-20817.patch
>
>
> As discussed in HBASE-20792, it seems that a region's openSeqNum could remain the same after a sucessful reopen, which causes the RTRP loop infinitely.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)