[
https://issues.apache.org/jira/browse/HBASE-29041?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Nirdosh Kumar Yadav updated HBASE-29041:
----------------------------------------
Description:
In an HBase cluster, we encountered a scenario where the RegionServer crash
procedure (SCP) took for more than 3 hours to complete. The incident was
triggered by temporary network unavailability in the HBase cluster. Upon
debugging, we found that the SCP was stuck due to the child SplitWALProcedure,
which was waiting for the completion of the SplitWALRemote procedure by the
RegionServer worker.
While executing, the SplitWALRemote procedure encountered an unknown exception.
The logs show an error message: "hdfs.DataStreamer - No ack received,"
indicating an issue with the RegionServer's connection to the DataNode. After
this error, the thread either became stuck or terminated, as no related logs
were available.
During this period, inconsistent regions were reported. All procedures were
restarted and completed successfully after the Active HMaster service was
bounced.
Related logs:
[HMASTER-4]
2024-12-05 14:55:11,264 INFO [PEWorker-41] procedure2.ProcedureExecutor -
Initialized subprocedures=[
{pid=6003288, ppid=6002575, state=RUNNABLE;
SplitWALRemoteProcedureregionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028}
]
[RS-15]
2024-12-05 14:55:11,461 DEBUG
[iority.RWQ.Fifo.read.handler=83,queue=2,port=60020] regionserver.RSRpcServices
- Executing remote procedure
classorg.apache.hadoop.hbase.regionserver.SplitWALCallable, pid=6003288
[RS-15]
2024-12-05 14:55:54,689 ERROR [split-log-closeStream-pool-0] hdfs.DataStreamer
- No ack received, took 25002ms (threshold=25000ms). File being written:
/hbase/data/default/tsdb/c997c5f8dd36481dcd3ebb9b79a35b51/recovered.edits/0000000000539451088-regionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680.temp,
block: BP-1745262640-10.60.130.13-1712173738392:blk_1330710217_257120451,
Write pipeline datanodes:
[DatanodeInfoWithStorage[10.60.52.107:50010,DS-f2b7ba1a-68b5-433a-9fe8-99315a172098,SSD],
DatanodeInfoWithStorage[10.60.75.52:50010,DS-93a433be-972f-4457-92ae-dd07288e41b5,SSD]].
[HMASTER-1]
2024-12-05 18:11:42,036 DEBUG [master/hmaster-1:60000:becomeActiveMaster]
store.ProcedureTree -Procedure Procedure(pid=6003288, ppid=6002575,
class=org.apache.hadoop.hbase.master.procedure.SplitWALRemoteProcedure) stack
ids=[3592]
[HMASTER-1]
2024-12-05 18:11:42,214 DEBUG [master/hmaster-1:60000:becomeActiveMaster]
procedure2.ProcedureExecutor - Loading pid=6003288, ppid=6002575,
state=RUNNABLE; SplitWALRemoteProcedure
regionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028
[RS-15]
2024-12-05 18:11:42,769 DEBUG
[iority.RWQ.Fifo.read.handler=79,queue=7,port=60020] regionserver.RSRpcServices
- Executing remote procedure
classorg.apache.hadoop.hbase.regionserver.SplitWALCallable, pid=6003288
[RS-15]
2024-12-05 18:11:48,247 DEBUG
[_REPLAY_OPS-regionserver/regionserver-15:60020-192]
regionserver.RemoteProcedureResultReporter - Successfully complete execution of
pid=6003288
[HMASTER-1]
2024-12-05 18:11:48,304 INFO [PEWorker-2] procedure2.ProcedureExecutor -
Finished pid=6002575, ppid=6000775, state=SUCCESS;
SplitWALProcedureregionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028
in 3 hrs, 16 mins, 52.806 sec
was:
In an HBase cluster, we encountered a scenario where the RegionServer crash
procedure (SCP) was delayed for more than 3 hours. The incident was triggered
by temporary network unavailability in the HBase cluster. Upon debugging, we
found that the SCP was stuck due to the child SplitWALProcedure, which was
waiting for the completion of the SplitWALRemote procedure by the RegionServer
worker.
While executing, the SplitWALRemote procedure encountered an unknown exception.
The logs show an error message: "hdfs.DataStreamer - No ack received,"
indicating an issue with the RegionServer's connection to the DataNode. After
this error, the thread either became stuck or terminated, as no related logs
were available.
During this period, inconsistent regions were reported. All procedures were
restarted and completed successfully after the Active HMaster service was
bounced.
Related logs:
[HMASTER-4]
2024-12-05 14:55:11,264 INFO [PEWorker-41] procedure2.ProcedureExecutor -
Initialized subprocedures=[\\{pid=6003288, ppid=6002575, state=RUNNABLE;
SplitWALRemoteProcedureregionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028}]
[RS-15]
2024-12-05 14:55:11,461 DEBUG
[iority.RWQ.Fifo.read.handler=83,queue=2,port=60020] regionserver.RSRpcServices
- Executing remote procedure
classorg.apache.hadoop.hbase.regionserver.SplitWALCallable, pid=6003288
[RS-15]
2024-12-05 14:55:54,689 ERROR [split-log-closeStream-pool-0] hdfs.DataStreamer
- No ack received, took 25002ms (threshold=25000ms). File being written:
/hbase/data/default/tsdb/c997c5f8dd36481dcd3ebb9b79a35b51/recovered.edits/0000000000539451088-regionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680.temp,
block: BP-1745262640-10.60.130.13-1712173738392:blk_1330710217_257120451,
Write pipeline datanodes:
[DatanodeInfoWithStorage[10.60.52.107:50010,DS-f2b7ba1a-68b5-433a-9fe8-99315a172098,SSD],
DatanodeInfoWithStorage[10.60.75.52:50010,DS-93a433be-972f-4457-92ae-dd07288e41b5,SSD]].
[HMASTER-1]
2024-12-05 18:11:42,036 DEBUG [master/hmaster-1:60000:becomeActiveMaster]
store.ProcedureTree -Procedure Procedure(pid=6003288, ppid=6002575,
class=org.apache.hadoop.hbase.master.procedure.SplitWALRemoteProcedure) stack
ids=[3592]
[HMASTER-1]
2024-12-05 18:11:42,214 DEBUG [master/hmaster-1:60000:becomeActiveMaster]
procedure2.ProcedureExecutor - Loading pid=6003288, ppid=6002575,
state=RUNNABLE; SplitWALRemoteProcedure
regionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028
[RS-15]
2024-12-05 18:11:42,769 DEBUG
[iority.RWQ.Fifo.read.handler=79,queue=7,port=60020] regionserver.RSRpcServices
- Executing remote procedure
classorg.apache.hadoop.hbase.regionserver.SplitWALCallable, pid=6003288
[RS-15]
2024-12-05 18:11:48,247 DEBUG
[_REPLAY_OPS-regionserver/regionserver-15:60020-192]
regionserver.RemoteProcedureResultReporter - Successfully complete execution of
pid=6003288
[HMASTER-1]
2024-12-05 18:11:48,304 INFO [PEWorker-2] procedure2.ProcedureExecutor -
Finished pid=6002575, ppid=6000775, state=SUCCESS;
SplitWALProcedureregionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028
in 3 hrs, 16 mins, 52.806 sec
> Set UncaughtException Handler for RegionServer ExecutorService
> --------------------------------------------------------------
>
> Key: HBASE-29041
> URL: https://issues.apache.org/jira/browse/HBASE-29041
> Project: HBase
> Issue Type: Bug
> Components: regionserver
> Affects Versions: 3.0.0, 2.6.1, 2.5.10
> Reporter: Nirdosh Kumar Yadav
> Priority: Minor
>
> In an HBase cluster, we encountered a scenario where the RegionServer crash
> procedure (SCP) took for more than 3 hours to complete. The incident was
> triggered by temporary network unavailability in the HBase cluster. Upon
> debugging, we found that the SCP was stuck due to the child
> SplitWALProcedure, which was waiting for the completion of the SplitWALRemote
> procedure by the RegionServer worker.
> While executing, the SplitWALRemote procedure encountered an unknown
> exception. The logs show an error message: "hdfs.DataStreamer - No ack
> received," indicating an issue with the RegionServer's connection to the
> DataNode. After this error, the thread either became stuck or terminated, as
> no related logs were available.
> During this period, inconsistent regions were reported. All procedures were
> restarted and completed successfully after the Active HMaster service was
> bounced.
> Related logs:
> [HMASTER-4]
> 2024-12-05 14:55:11,264 INFO [PEWorker-41] procedure2.ProcedureExecutor -
> Initialized subprocedures=[
> {pid=6003288, ppid=6002575, state=RUNNABLE;
> SplitWALRemoteProcedureregionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
>
> worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028}
> ]
> [RS-15]
> 2024-12-05 14:55:11,461 DEBUG
> [iority.RWQ.Fifo.read.handler=83,queue=2,port=60020]
> regionserver.RSRpcServices - Executing remote procedure
> classorg.apache.hadoop.hbase.regionserver.SplitWALCallable, pid=6003288
> [RS-15]
> 2024-12-05 14:55:54,689 ERROR [split-log-closeStream-pool-0]
> hdfs.DataStreamer - No ack received, took 25002ms (threshold=25000ms). File
> being written:
> /hbase/data/default/tsdb/c997c5f8dd36481dcd3ebb9b79a35b51/recovered.edits/0000000000539451088-regionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680.temp,
> block: BP-1745262640-10.60.130.13-1712173738392:blk_1330710217_257120451,
> Write pipeline datanodes:
> [DatanodeInfoWithStorage[10.60.52.107:50010,DS-f2b7ba1a-68b5-433a-9fe8-99315a172098,SSD],
>
> DatanodeInfoWithStorage[10.60.75.52:50010,DS-93a433be-972f-4457-92ae-dd07288e41b5,SSD]].
> [HMASTER-1]
> 2024-12-05 18:11:42,036 DEBUG [master/hmaster-1:60000:becomeActiveMaster]
> store.ProcedureTree -Procedure Procedure(pid=6003288, ppid=6002575,
> class=org.apache.hadoop.hbase.master.procedure.SplitWALRemoteProcedure) stack
> ids=[3592]
> [HMASTER-1]
> 2024-12-05 18:11:42,214 DEBUG [master/hmaster-1:60000:becomeActiveMaster]
> procedure2.ProcedureExecutor - Loading pid=6003288, ppid=6002575,
> state=RUNNABLE; SplitWALRemoteProcedure
> regionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
>
> worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028
> [RS-15]
> 2024-12-05 18:11:42,769 DEBUG
> [iority.RWQ.Fifo.read.handler=79,queue=7,port=60020]
> regionserver.RSRpcServices - Executing remote procedure
> classorg.apache.hadoop.hbase.regionserver.SplitWALCallable, pid=6003288
> [RS-15]
> 2024-12-05 18:11:48,247 DEBUG
> [_REPLAY_OPS-regionserver/regionserver-15:60020-192]
> regionserver.RemoteProcedureResultReporter - Successfully complete execution
> of pid=6003288
> [HMASTER-1]
> 2024-12-05 18:11:48,304 INFO [PEWorker-2] procedure2.ProcedureExecutor -
> Finished pid=6002575, ppid=6000775, state=SUCCESS;
> SplitWALProcedureregionserver-53.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is%2C60020%2C1730886070174.1733410178680,
>
> worker=regionserver-15.regionserver.hbase.hbase33a.hbase.monitoring.aws-esvc1-useast2.aws.sfdc.is,60020,1730878238028
> in 3 hrs, 16 mins, 52.806 sec
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
