You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "David Manning (Jira)" <ji...@apache.org> on 2024/06/14 17:06:00 UTC
[jira] [Work logged] (HBASE-28663) CanaryTool continues executing and scanning after timeout
[ https://issues.apache.org/jira/browse/HBASE-28663?focusedWorklogId=923552&page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-923552 ]
David Manning logged work on HBASE-28663:
-----------------------------------------
Author: David Manning
Created on: 14/Jun/24 17:05
Start Date: 14/Jun/24 17:05
Worklog Time Spent: 24h
Issue Time Tracking
-------------------
Worklog Id: (was: 923552)
Remaining Estimate: 0h (was: 24h)
Time Spent: 24h
> CanaryTool continues executing and scanning after timeout
> ---------------------------------------------------------
>
> Key: HBASE-28663
> URL: https://issues.apache.org/jira/browse/HBASE-28663
> Project: HBase
> Issue Type: Bug
> Components: canary
> Affects Versions: 2.0.0, 3.0.0
> Reporter: David Manning
> Assignee: David Manning
> Priority: Minor
> Labels: pull-request-available
> Original Estimate: 24h
> Time Spent: 24h
> Remaining Estimate: 0h
>
> If you run the {{CanaryTool}} in region mode until it reaches the configured timeout, the logs and sink results will show that it can continue executing and scanning for 10 seconds.
> This is because the RegionTasks have already been submitted to an ExecutorService which continues execution after timeout, and the Monitor continues execution on a separate thread.
> The 10 second delay in shutdown is seen, in hbase 2.x at least, because {{runMonitor}} will close the {{Connection}} and that process ([code|https://github.com/apache/hbase/blob/e865c852c0e9a1e9b55b9d1512d379072d3e7a7b/hbase-server/src/main/java/org/apache/hadoop/hbase/tool/CanaryTool.java#L1054-L1094]) will lead to {{ConnectionImplementation#close}} ([code|https://github.com/apache/hbase/blob/e865c852c0e9a1e9b55b9d1512d379072d3e7a7b/hbase-client/src/main/java/org/apache/hadoop/hbase/client/ConnectionImplementation.java#L2272-L2300]) and inside {{shutdownPools}} we will potentially wait the full 10 seconds of {{awaitTermination}} if client operations are in progress.
> The scenario can be improved by simply interrupting the monitor thread, as we will often be in an {{invokeAll}} call in a {{sniff}} method. The {{invokeAll}} method is blocking, and interrupting the monitor in this call will interrupt the client threads and generally shutdown properly and timely. However, we can be more robust by also watching for a shutdown signal in the various tasks such as {{RegionTask}} so any remaining tasks will drain quickly and without errors.
>
> {code:java}
> 2024-06-12 02:57:14 [Time-limited test] ERROR tool.Canary(1076): The monitor is running too long (1140098) after timeout limit:1140000 will be killed itself !!
> 2024-06-12 02:57:14 [Time-limited test] INFO client.ConnectionImplementation(2039): Closing master protocol: MasterService
> 2024-06-12 02:57:14 [pool-3-thread-4] ERROR tool.Canary(353): Read from REGION1. on serverName=REGIONSERVER-1, columnFamily=0 failed
> java.lang.RuntimeException: java.util.concurrent.RejectedExecutionException: Task org.apache.hadoop.hbase.client.ResultBoundedCompletionService$QueueingFuture@54f2a9a4 rejected from java.util.concurrent.ThreadPoolExecutor@2d3d204d[Shutting down, pool size = 7, active threads = 7, queued tasks = 0, completed tasks = 180094]
> at org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithoutRetries(RpcRetryingCallerImpl.java:199)
> at org.apache.hadoop.hbase.client.ClientScanner.call(ClientScanner.java:271)
> at org.apache.hadoop.hbase.client.ClientScanner.loadCache(ClientScanner.java:440)
> at org.apache.hadoop.hbase.client.ClientScanner.nextWithSyncCache(ClientScanner.java:314)
> at org.apache.hadoop.hbase.client.ClientScanner.next(ClientScanner.java:612)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.readColumnFamily(CanaryTool.java:565)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.read(CanaryTool.java:609)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.call(CanaryTool.java:503)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.call(CanaryTool.java:471)
> [... repeats for 10 seconds and tens of thousands of regions ... ]
> 2024-06-12 02:57:16 [pool-3-thread-11] ERROR tool.Canary(353): Read from REGION10000. on serverName=REGIONSERVER-2, columnFamily=0 failed
> java.lang.RuntimeException: java.util.concurrent.RejectedExecutionException: Task org.apache.hadoop.hbase.client.ResultBoundedCompletionService$QueueingFuture@d08d21f rejected from java.util.concurrent.ThreadPoolExecutor@2d3d204d[Shutting down, pool size = 3, active threads = 3, queued tasks = 0, completed tasks = 180098]
> [...]
> 2024-06-12 02:57:24 [pool-3-thread-11] ERROR tool.Canary(353): Read from REGION42000. on serverName=REGIONSERVER-3, columnFamily=0 failed
> java.lang.RuntimeException: java.util.concurrent.RejectedExecutionException: Task org.apache.hadoop.hbase.client.ResultBoundedCompletionService$QueueingFuture@38e7a5a1 rejected from java.util.concurrent.ThreadPoolExecutor@2d3d204d[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 180101]
> 2024-06-12T02:57:24.202Z, java.io.InterruptedIOException
> at org.apache.hadoop.hbase.client.RpcRetryingCallerWithReadReplicas.throwEnrichedException(RpcRetryingCallerWithReadReplicas.java:294)
> at org.apache.hadoop.hbase.client.ScannerCallableWithReplicas.call(ScannerCallableWithReplicas.java:255)
> at org.apache.hadoop.hbase.client.ScannerCallableWithReplicas.call(ScannerCallableWithReplicas.java:53)
> at org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithoutRetries(RpcRetryingCallerImpl.java:191)
> at org.apache.hadoop.hbase.client.ClientScanner.call(ClientScanner.java:271)
> at org.apache.hadoop.hbase.client.ClientScanner.loadCache(ClientScanner.java:440)
> at org.apache.hadoop.hbase.client.ClientScanner.nextWithSyncCache(ClientScanner.java:314)
> at org.apache.hadoop.hbase.client.ClientScanner.next(ClientScanner.java:612)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.readColumnFamily(CanaryTool.java:565)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.read(CanaryTool.java:609)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.call(CanaryTool.java:503)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.call(CanaryTool.java:471)
> 2024-06-12 02:57:24 [pool-3-thread-8] WARN client.ConnectionImplementation(428): Checking master connection org.apache.hadoop.hbase.ipc.StoppedRpcClientException: Call to address=HMASTER-1 failed on local exception: org.apache.hadoop.hbase.ipc.StoppedRpcClientException at sun.reflect.GeneratedConstructorAccessor27.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at org.apache.hadoop.hbase.ipc.IPCUtil.wrapException(IPCUtil.java:206) at org.apache.hadoop.hbase.ipc.AbstractRpcClient.onCallFinished(AbstractRpcClient.java:391) at org.apache.hadoop.hbase.ipc.AbstractRpcClient.access$100(AbstractRpcClient.java:92) at org.apache.hadoop.hbase.ipc.AbstractRpcClient$3.run(AbstractRpcClient.java:425) at org.apache.hadoop.hbase.ipc.AbstractRpcClient$3.run(AbstractRpcClient.java:420) at org.apache.hadoop.hbase.ipc.Call.callComplete(Call.java:114) at org.apache.hadoop.hbase.ipc.Call.setException(Call.java:129) at org.apache.hadoop.hbase.ipc.AbstractRpcClient.callMethod(AbstractRpcClient.java:446) at org.apache.hadoop.hbase.ipc.AbstractRpcClient.callBlockingMethod(AbstractRpcClient.java:332) at org.apache.hadoop.hbase.ipc.AbstractRpcClient.access$200(AbstractRpcClient.java:92) at org.apache.hadoop.hbase.ipc.AbstractRpcClient$BlockingRpcChannelImplementation.callBlockingMethod(AbstractRpcClient.java:595) at org.apache.hadoop.hbase.shaded.protobuf.generated.MasterProtos$MasterService$BlockingStub.isMasterRunning(MasterProtos.java) at org.apache.hadoop.hbase.client.ConnectionImplementation$MasterServiceState.isMasterRunning(ConnectionImplementation.java:1235) at org.apache.hadoop.hbase.client.ConnectionImplementation.lambda$masterConnectionStateSupplier$1(ConnectionImplementation.java:421) at org.apache.hadoop.hbase.client.ConnectionImplementation.isKeepAliveMasterConnectedAndRunning(ConnectionImplementation.java:2025) at org.apache.hadoop.hbase.client.ConnectionImplementation.getKeepAliveMasterService(ConnectionImplementation.java:1441) at org.apache.hadoop.hbase.client.ConnectionImplementation.getMaster(ConnectionImplementation.java:1433) at org.apache.hadoop.hbase.client.MasterCallable.prepare(MasterCallable.java:57) at org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithRetries(RpcRetryingCallerImpl.java:101) at org.apache.hadoop.hbase.client.HBaseAdmin.executeCallable(HBaseAdmin.java:3020) at org.apache.hadoop.hbase.client.HBaseAdmin.getTableDescriptor(HBaseAdmin.java:579) at org.apache.hadoop.hbase.client.HTable.getDescriptor(HTable.java:242) at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.read(CanaryTool.java:593) at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.call(CanaryTool.java:503) at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.call(CanaryTool.java:471)
> 2024-06-12 02:57:24 [pool-3-thread-7] ERROR tool.Canary(345): Read from REGION43000. on serverName=REGIONSERVER-4 failed
> org.apache.hadoop.hbase.DoNotRetryIOException: Connection was closed while trying to get master
> at org.apache.hadoop.hbase.client.ConnectionImplementation$MasterServiceStubMaker.makeStub(ConnectionImplementation.java:1381)
> at org.apache.hadoop.hbase.client.ConnectionImplementation.getKeepAliveMasterService(ConnectionImplementation.java:1445)
> at org.apache.hadoop.hbase.client.ConnectionImplementation.getMaster(ConnectionImplementation.java:1433)
> at org.apache.hadoop.hbase.client.MasterCallable.prepare(MasterCallable.java:57)
> at org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithRetries(RpcRetryingCallerImpl.java:101)
> at org.apache.hadoop.hbase.client.HBaseAdmin.executeCallable(HBaseAdmin.java:3020)
> at org.apache.hadoop.hbase.client.HBaseAdmin.getTableDescriptor(HBaseAdmin.java:579)
> at org.apache.hadoop.hbase.client.HTable.getDescriptor(HTable.java:242)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.read(CanaryTool.java:593)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.call(CanaryTool.java:503)
> at org.apache.hadoop.hbase.tool.CanaryTool$RegionTask.call(CanaryTool.java:471){code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)