You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Nick Dimiduk (Jira)" <ji...@apache.org> on 2023/03/13 12:50:00 UTC
[jira] [Commented] (HBASE-27707) Region replica replication sometimes orphans WAL queue entries during recovery
[ https://issues.apache.org/jira/browse/HBASE-27707?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17699616#comment-17699616 ]
Nick Dimiduk commented on HBASE-27707:
--------------------------------------
Here are some notes from tracing pids through the logs.
{noformat}
Procedures And Locks screen shows,
181951 181104 WAITING nonroot org.apache.hadoop.hbase.master.replication.ClaimReplicationQueuesProcedure
182060 181951 RUNNABLE org.apache.hadoop.hbase.master.replication.ClaimReplicationQueueRemoteProcedure
2023-03-09T18:35:13,865 DEBUG [RegionServerTracker-0] procedure2.ProcedureExecutor: Stored pid=181104, state=RUNNABLE:SERVER_CRASH_START; ServerCrashProcedure datanode-39.example.com,16020,1677724535336, splitWal=true, meta=false
2023-03-09T18:35:13,865 INFO [RegionServerTracker-0] assignment.AssignmentManager: Scheduled ServerCrashProcedure pid=181104 for datanode-39.example.com,16020,1677724535336 (carryingMeta=false) datanode-39.example.com,16020,1677724535336/CRASHED/regionCount=299/lock=java.util.concurrent.locks.ReentrantReadWriteLock@2900bd9f[Write locks = 1, Read locks = 0], oldState=ONLINE.
2023-03-09T18:35:13,866 INFO [PEWorker-8] procedure.ServerCrashProcedure: Start pid=181104, state=RUNNABLE:SERVER_CRASH_START, locked=true; ServerCrashProcedure datanode-39.example.com,16020,1677724535336, splitWal=true, meta=false
2023-03-09T18:35:13,867 INFO [PEWorker-8] procedure.ServerCrashProcedure: datanode-39.example.com,16020,1677724535336 had 299 regions
2023-03-09T18:35:13,868 INFO [PEWorker-8] procedure.ServerCrashProcedure: Splitting WALs pid=181104, state=RUNNABLE:SERVER_CRASH_SPLIT_LOGS, locked=true; ServerCrashProcedure datanode-39.example.com,16020,1677724535336, splitWal=true, meta=false, isMeta: false
2023-03-09T18:35:13,871 DEBUG [PEWorker-8] master.MasterWalManager: Renamed region directory: hdfs://hadoop:8020/hbase/WALs/datanode-39.example.com,16020,1677724535336-splitting
2023-03-09T18:35:13,874 INFO [PEWorker-8] master.SplitWALManager: datanode-39.example.com,16020,1677724535336 WAL count=124, meta=false
... 124 events matching Initialized AND SplitWALRemoteProcedure AND datanode-39.example.com
... 44 events matching Finished AND SplitWALRemoteProcedure AND datanode-39.example.com
tracing one of the lost pids:
2023-03-09T18:35:13,884 INFO [PEWorker-4] procedure2.ProcedureExecutor: Initialized subprocedures=[{pid=181234, ppid=181118, state=RUNNABLE; SplitWALRemoteProcedure datanode-39.example.com.1678383484540, worker=datanode-42.example.com,16020,1677724534736}]
2023-03-09T18:35:14,071 INFO [RS_LOG_REPLAY_OPS-regionserver/datanode-42:16020-0] wal.WALSplitter: Splitting hdfs://hadoop:8020/hbase/WALs/datanode-39.example.com,16020,1677724535336-splitting/datanode-39.example.com.1678383484540, size=256.2 M (268665707bytes)
2023-03-09T18:35:17,092 INFO [RS_LOG_REPLAY_OPS-regionserver/datanode-42:16020-0] wal.WALSplitter: Processed 3459 edits across 16 Regions in 3014 ms; skipped=3018; WAL=hdfs://hadoop:8020/hbase/WALs/datanode-39.example.com,16020,1677724535336-splitting/datanode-39.example.com.1678383484540, size=256.2 M, length=268665707, corrupted=false, cancelled=false
2023-03-09T18:35:17,093 DEBUG [RS_LOG_REPLAY_OPS-regionserver/datanode-42:16020-0] regionserver.SplitLogWorker: Done splitting WAL hdfs://hadoop:8020/hbase/WALs/datanode-39.example.com,16020,1677724535336-splitting/datanode-39.example.com.1678383484540
2023-03-09T18:35:17,093 DEBUG [RS_LOG_REPLAY_OPS-regionserver/datanode-42:16020-0] regionserver.RemoteProcedureResultReporter: Successfully complete execution of pid=181234
... no log of an associated "Remote procedure done, pid={}" or Remote procedure failed, pid={}"
... the master seems to not receive the RPC but RS thinks it sent and acknowledged?
... pbuf response is an empty object, exceptions checked, and no indication that procedureResultReporter thread died
what happened to all of these? they all completed successfully
=> 80x RemoteProcedureResultReporter: Successfully complete execution of pid=...
SCP decides to move on...
2023-03-09T18:35:35,798 INFO [PEWorker-14] master.SplitLogManager: hdfs://hadoop:8020/hbase/WALs/datanode-39.example.com,16020,1677724535336-splitting dir is empty, no logs to split.
2023-03-09T18:35:35,798 DEBUG [PEWorker-14] procedure.ServerCrashProcedure: Check if datanode-39.example.com,16020,1677724535336 WAL splitting is done? wals=0, meta=false
2023-03-09T18:35:35,802 INFO [PEWorker-14] procedure.ServerCrashProcedure: Remove WAL directory for datanode-39.example.com,16020,1677724535336 failed, ignore...File hdfs://hadoop:8020/hbase/WALs/datanode-39.example.com,16020,1677724535336-splitting does not exist.
now trying to reclaim the queues -- these repeat about every 45 seconds
2023-03-09T18:36:18,297 DEBUG [PEWorker-2] replication.ClaimReplicationQueuesProcedure: There are 1 replication queues need to be claimed for datanode-39.example.com,16020,1677724535336
2023-03-09T18:36:51,744 DEBUG [PEWorker-8] replication.ClaimReplicationQueuesProcedure: There are 1 replication queues need to be claimed for datanode-39.example.com,16020,1677724535336
2023-03-09T18:37:40,368 DEBUG [PEWorker-15] replication.ClaimReplicationQueuesProcedure: There are 1 replication queues need to be claimed for datanode-39.example.com,16020,1677724535336
...
Tracking pid=182060 to the RS side of a ClaimReplicationQueueRemoteProcedure, over on datanode-40
2023-03-09T18:52:20,205 DEBUG [RpcServer.priority.RWQ.Fifo.read.handler=12,queue=5,port=16020] regionserver.RSRpcServices: Executing remote procedure class org.apache.hadoop.hbase.replication.regionserver.ClaimReplicationQueueCallable, pid=182060
2023-03-09T18:53:18,042 INFO [RS_CLAIM_REPLICATION_QUEUE-regionserver/datanode-40:16020-0] regionserver.ReplicationSourceManager: Not transferring queue since the replication peer region_replica_replication for queue region_replica_replication does not exist
then nothing.
back on master,
2023-03-09T18:55:30,132 ERROR [ProcedureDispatcherTimeoutThread] procedure2.RemoteProcedureDispatcher: DelayQueue for RemoteProcedureDispatcher is not empty when timed waiting elapsed. If this is repeated consistently, it means no element is getting expired from the queue and it might freeze the system. Queue: [containedObject=datanode-74.example.com,16020,1677724548782, timeout=1678388130201, delay=69, operations=[pid=182103, ppid=181951, state=RUNNABLE; org.apache.hadoop.hbase.master.replication.ClaimReplicationQueueRemoteProcedure]]
{noformat}
> Region replica replication sometimes orphans WAL queue entries during recovery
> ------------------------------------------------------------------------------
>
> Key: HBASE-27707
> URL: https://issues.apache.org/jira/browse/HBASE-27707
> Project: HBase
> Issue Type: Bug
> Components: read replicas, Replication
> Affects Versions: 2.5.0
> Reporter: Nick Dimiduk
> Priority: Major
>
> Running with timeline-consistent read replicas and {{hbase.region.replica.replication.enabled=true}}, we're seeing some region servers have WAL queue entires that never clear. This appears to correlate with SCP and recovery of replication queues. The result is WALs that build up, consuming dangerous amounts of space on HDFS. Remediation requires disabling and removing the {{region_replica_replication}} peer, which forces an impacted region server to abort with the message "Failed to operate on replication queue". We then delete the zk entry, which unlocks the WAL and the cleaner chore can sweep them.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)