the port: 1983 is application master's port or not ? i am not sure about that  ... View more

Log Type: syslog Log Upload Time: Wed Apr 28 03:31:04 +0800 2021 Log Length: 132219 2021-04-28 03:27:36,319 INFO [main] org.apache.hadoop.mapreduce.v2.app.MRAppMaster: Created MRAppMaster for application appattempt_1618548626214_128739_000001 2021-04-28 03:27:36,530 INFO [main] org.apache.hadoop.mapreduce.v2.app.MRAppMaster: Executing with tokens: 2021-04-28 03:27:36,530 INFO [main] org.apache.hadoop.mapreduce.v2.app.MRAppMaster: Kind: YARN_AM_RM_TOKEN, Service: , Ident: (org.apache.hadoop.yarn.security.AMRMTokenIdentifier@5b218417) 2021-04-28 03:27:36,706 INFO [main] org.apache.hadoop.mapreduce.v2.app.MRAppMaster: OutputCommitter set in config org.apache.hadoop.hive.ql.io.HiveFileFormatUtils$NullOutputCommitter 2021-04-28 03:27:36,708 INFO [main] org.apache.hadoop.mapreduce.v2.app.MRAppMaster: OutputCommitter is org.apache.hadoop.hive.ql.io.HiveFileFormatUtils$NullOutputCommitter 2021-04-28 03:27:37,232 WARN [main] org.apache.hadoop.util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable 2021-04-28 03:27:37,378 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.jobhistory.EventType for class org.apache.hadoop.mapreduce.jobhistory.JobHistoryEventHandler 2021-04-28 03:27:37,379 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.v2.app.job.event.JobEventType for class org.apache.hadoop.mapreduce.v2.app.MRAppMaster$JobEventDispatcher 2021-04-28 03:27:37,380 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.v2.app.job.event.TaskEventType for class org.apache.hadoop.mapreduce.v2.app.MRAppMaster$TaskEventDispatcher 2021-04-28 03:27:37,381 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.v2.app.job.event.TaskAttemptEventType for class org.apache.hadoop.mapreduce.v2.app.MRAppMaster$TaskAttemptEventDispatcher 2021-04-28 03:27:37,381 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.v2.app.commit.CommitterEventType for class org.apache.hadoop.mapreduce.v2.app.commit.CommitterEventHandler 2021-04-28 03:27:37,385 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.v2.app.speculate.Speculator$EventType for class org.apache.hadoop.mapreduce.v2.app.MRAppMaster$SpeculatorEventDispatcher 2021-04-28 03:27:37,386 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.v2.app.rm.ContainerAllocator$EventType for class org.apache.hadoop.mapreduce.v2.app.MRAppMaster$ContainerAllocatorRouter 2021-04-28 03:27:37,386 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.v2.app.launcher.ContainerLauncher$EventType for class org.apache.hadoop.mapreduce.v2.app.MRAppMaster$ContainerLauncherRouter 2021-04-28 03:27:37,430 INFO [main] org.apache.hadoop.mapreduce.v2.jobhistory.JobHistoryUtils: Default file system [hdfs://nameservice1:8020] 2021-04-28 03:27:37,449 INFO [main] org.apache.hadoop.mapreduce.v2.jobhistory.JobHistoryUtils: Default file system [hdfs://nameservice1:8020] 2021-04-28 03:27:37,469 INFO [main] org.apache.hadoop.mapreduce.v2.jobhistory.JobHistoryUtils: Default file system [hdfs://nameservice1:8020] 2021-04-28 03:27:37,481 INFO [main] org.apache.hadoop.mapreduce.jobhistory.JobHistoryEventHandler: Emitting job history data to the timeline server is not enabled 2021-04-28 03:27:37,513 INFO [main] org.apache.hadoop.yarn.event.AsyncDispatcher: Registering class org.apache.hadoop.mapreduce.v2.app.job.event.JobFinishEvent$Type for class org.apache.hadoop.mapreduce.v2.app.MRAppMaster$JobFinishEventHandler 2021-04-28 03:27:37,673 INFO [main] org.apache.hadoop.metrics2.impl.MetricsConfig: loaded properties from hadoop-metrics2.properties 2021-04-28 03:27:37,724 INFO [main] org.apache.hadoop.metrics2.impl.MetricsSystemImpl: Scheduled snapshot period at 10 second(s). 2021-04-28 03:27:37,725 INFO [main] org.apache.hadoop.metrics2.impl.MetricsSystemImpl: MRAppMaster metrics system started 2021-04-28 03:27:37,735 INFO [main] org.apache.hadoop.mapreduce.v2.app.job.impl.JobImpl: Adding job token for job_1618548626214_128739 to jobTokenSecretManager 2021-04-28 03:27:37,855 INFO [main] org.apache.hadoop.mapreduce.v2.app.job.impl.JobImpl: Not uberizing job_1618548626214_128739 because: not enabled; too much RAM; 2021-04-28 03:27:37,877 INFO [main] org.apache.hadoop.mapreduce.v2.app.job.impl.JobImpl: Input size for job job_1618548626214_128739 = 23256534. Number of splits = 7 2021-04-28 03:27:37,877 INFO [main] org.apache.hadoop.mapreduce.v2.app.job.impl.JobImpl: Number of reduces for job job_1618548626214_128739 = 0 2021-04-28 03:27:37,877 INFO [main] org.apache.hadoop.mapreduce.v2.app.job.impl.JobImpl: job_1618548626214_128739Job Transitioned from NEW to INITED 2021-04-28 03:27:37,878 INFO [main] org.apache.hadoop.mapreduce.v2.app.MRAppMaster: MRAppMaster launching normal, non-uberized, multi-container job job_1618548626214_128739. 2021-04-28 03:27:37,905 INFO [main] org.apache.hadoop.ipc.CallQueueManager: Using callQueue: class java.util.concurrent.LinkedBlockingQueue queueCapacity: 100 2021-04-28 03:27:37,914 INFO [Socket Reader #1 for port 9115] org.apache.hadoop.ipc.Server: Starting Socket Reader #1 for port 9115 2021-04-28 03:27:37,951 INFO [main] org.apache.hadoop.yarn.factories.impl.pb.RpcServerFactoryPBImpl: Adding protocol org.apache.hadoop.mapreduce.v2.api.MRClientProtocolPB to the server 2021-04-28 03:27:37,952 INFO [IPC Server Responder] org.apache.hadoop.ipc.Server: IPC Server Responder: starting 2021-04-28 03:27:37,952 INFO [IPC Server listener on 9115] org.apache.hadoop.ipc.Server: IPC Server listener on 9115: starting 2021-04-28 03:27:37,953 INFO [main] org.apache.hadoop.mapreduce.v2.app.client.MRClientService: Instantiated MRClientService at dataware-14/10.39.58.19:9115 2021-04-28 03:27:38,009 INFO [main] org.mortbay.log: Logging to org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog 2021-04-28 03:27:38,015 INFO [main] org.apache.hadoop.security.authentication.server.AuthenticationFilter: Unable to initialize FileSignerSecretProvider, falling back to use random secrets. 2021-04-28 03:27:38,019 INFO [main] org.apache.hadoop.http.HttpRequestLog: Http request log for http.requests.mapreduce is not defined 2021-04-28 03:27:38,027 INFO [main] org.apache.hadoop.http.HttpServer2: Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter) 2021-04-28 03:27:38,072 INFO [main] org.apache.hadoop.http.HttpServer2: Added filter AM_PROXY_FILTER (class=org.apache.hadoop.yarn.server.webproxy.amfilter.AmIpFilter) to context mapreduce 2021-04-28 03:27:38,074 INFO [main] org.apache.hadoop.http.HttpServer2: Added filter AM_PROXY_FILTER (class=org.apache.hadoop.yarn.server.webproxy.amfilter.AmIpFilter) to context static 2021-04-28 03:27:38,077 INFO [main] org.apache.hadoop.http.HttpServer2: adding path spec: /mapreduce/* 2021-04-28 03:27:38,077 INFO [main] org.apache.hadoop.http.HttpServer2: adding path spec: /ws/* 2021-04-28 03:27:38,086 INFO [main] org.apache.hadoop.http.HttpServer2: Jetty bound to port 41305 2021-04-28 03:27:38,086 INFO [main] org.mortbay.log: jetty-6.1.26.cloudera.4 2021-04-28 03:27:38,120 INFO [main] org.mortbay.log: Extract jar:file:/opt/cloudera/parcels/CDH-5.13.3-1.cdh5.13.3.p0.2/jars/hadoop-yarn-common-2.6.0-cdh5.13.3.jar!/webapps/mapreduce to /tmp/Jetty_0_0_0_0_41305_mapreduce____2p8bem/webapp 2021-04-28 03:27:38,436 INFO [main] org.mortbay.log: Started HttpServer2$SelectChannelConnectorWithSafeStartup@0.0.0.0:41305 2021-04-28 03:27:38,437 INFO [main] org.apache.hadoop.yarn.webapp.WebApps: Web app /mapreduce started at 41305 2021-04-28 03:27:38,742 INFO [main] org.apache.hadoop.yarn.webapp.WebApps: Registered webapp guice modules 2021-04-28 03:27:38,745 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.speculate.DefaultSpeculator: JOB_CREATE job_1618548626214_128739 2021-04-28 03:27:38,748 INFO [main] org.apache.hadoop.ipc.CallQueueManager: Using callQueue: class java.util.concurrent.LinkedBlockingQueue queueCapacity: 3000 2021-04-28 03:27:38,749 INFO [Socket Reader #1 for port 1983] org.apache.hadoop.ipc.Server: Starting Socket Reader #1 for port 1983 2021-04-28 03:27:38,753 INFO [IPC Server Responder] org.apache.hadoop.ipc.Server: IPC Server Responder: starting 2021-04-28 03:27:38,753 INFO [IPC Server listener on 1983] org.apache.hadoop.ipc.Server: IPC Server listener on 1983: starting 2021-04-28 03:27:38,775 INFO [main] org.apache.hadoop.mapreduce.v2.app.rm.RMContainerRequestor: nodeBlacklistingEnabled:true 2021-04-28 03:27:38,775 INFO [main] org.apache.hadoop.mapreduce.v2.app.rm.RMContainerRequestor: maxTaskFailuresPerNode is 3 2021-04-28 03:27:38,775 INFO [main] org.apache.hadoop.mapreduce.v2.app.rm.RMContainerRequestor: blacklistDisablePercent is 33 2021-04-28 03:27:38,848 INFO [main] org.apache.hadoop.yarn.client.ConfiguredRMFailoverProxyProvider: Failing over to rm237 2021-04-28 03:27:38,877 INFO [main] org.apache.hadoop.mapreduce.v2.app.rm.RMContainerAllocator: maxContainerCapability: <memory:24576, vCores:14> 2021-04-28 03:27:38,877 INFO [main] org.apache.hadoop.mapreduce.v2.app.rm.RMContainerAllocator: queue: root.etl_core 2021-04-28 03:27:38,881 INFO [main] org.apache.hadoop.mapreduce.v2.app.launcher.ContainerLauncherImpl: Upper limit on the thread pool size is 500 2021-04-28 03:27:38,881 INFO [main] org.apache.hadoop.mapreduce.v2.app.launcher.ContainerLauncherImpl: The thread pool initial size is 10 2021-04-28 03:27:38,889 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.JobImpl: job_1618548626214_128739Job Transitioned from INITED to SETUP 2021-04-28 03:27:38,893 INFO [CommitterEvent Processor #0] org.apache.hadoop.mapreduce.v2.app.commit.CommitterEventHandler: Processing the event EventType: JOB_SETUP 2021-04-28 03:27:38,895 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.JobImpl: job_1618548626214_128739Job Transitioned from SETUP to RUNNING 2021-04-28 03:27:38,970 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskImpl: task_1618548626214_128739_m_000000 Task Transitioned from NEW to SCHEDULED 2021-04-28 03:27:38,988 INFO [eventHandlingThread] org.apache.hadoop.mapreduce.jobhistory.JobHistoryEventHandler: Event Writer setup for JobId: job_1618548626214_128739, File: hdfs://nameservice1:8020/user/hive/.staging/job_1618548626214_128739/job_1618548626214_128739_1.jhist 2021-04-28 03:27:38,994 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskImpl: task_1618548626214_128739_m_000001 Task Transitioned from NEW to SCHEDULED 2021-04-28 03:27:39,013 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskImpl: task_1618548626214_128739_m_000002 Task Transitioned from NEW to SCHEDULED 2021-04-28 03:27:39,032 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskImpl: task_1618548626214_128739_m_000003 Task Transitioned from NEW to SCHEDULED 2021-04-28 03:27:39,049 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskImpl: task_1618548626214_128739_m_000004 Task Transitioned from NEW to SCHEDULED 2021-04-28 03:27:39,077 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskImpl: task_1618548626214_128739_m_000005 Task Transitioned from NEW to SCHEDULED 2021-04-28 03:27:39,095 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskImpl: task_1618548626214_128739_m_000006 Task Transitioned from NEW to SCHEDULED 2021-04-28 03:27:39,097 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskAttemptImpl: attempt_1618548626214_128739_m_000000_0 TaskAttempt Transitioned from NEW to UNASSIGNED 2021-04-28 03:27:39,097 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskAttemptImpl: attempt_1618548626214_128739_m_000001_0 TaskAttempt Transitioned from NEW to UNASSIGNED 2021-04-28 03:27:39,098 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskAttemptImpl: attempt_1618548626214_128739_m_000002_0 TaskAttempt Transitioned from NEW to UNASSIGNED 2021-04-28 03:27:39,098 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskAttemptImpl: attempt_1618548626214_128739_m_000003_0 TaskAttempt Transitioned from NEW to UNASSIGNED 2021-04-28 03:27:39,098 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskAttemptImpl: attempt_1618548626214_128739_m_000004_0 TaskAttempt Transitioned from NEW to UNASSIGNED 2021-04-28 03:27:39,098 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskAttemptImpl: attempt_1618548626214_128739_m_000005_0 TaskAttempt Transitioned from NEW to UNASSIGNED 2021-04-28 03:27:39,098 INFO [AsyncDispatcher event handler] org.apache.hadoop.mapreduce.v2.app.job.impl.TaskAttemptImpl: attempt_1618548626214_128739_m_000006_0 TaskAttempt Transitioned from NEW to UNASSIGNED 2021-04-28 03:27:39,099 INFO [Thread-53] org.apache.hadoop.mapreduce.v2.app.rm.RMContainerAllocator: mapResourceRequest:<memory:6144, vCores:1>   please help me check the port:1983, everytime when the job failed, retry connection port is 1983, after several times then job failed since connection timeout. Already tried 2 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS) 2021-04-28 03:27:59,247 INFO [main] org.apache.hadoop.ipc.Client: Retrying connect to server: dataware-14/10.39.58.19:1983. Already tried 3 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS) 2021-04-28 03:28:03,247 INFO [main] org.apache.hadoop.ipc.Client: Retrying connect to server: dataware-14/10.39.58.19:1983. Already tried 4 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS) 2021-04-28 03:28:07,248 INFO [main] org.apache.hadoop.ipc.Client: Retrying connect to server: dataware-14/10.39.58.19:1983. Already tried 5 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS) 2021-04-28 03:28:11,249 INFO [main] org.apache.hadoop.ipc.Client: Retrying connect to server: dataware-14/10.39.58.19:1983. Already tried 6 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS) 2021-04-28 03:28:15,250 INFO [main] org.apache.hadoop.ipc.Client: Retrying connect to server: dataware-14/10.39.58.19:1983. Already tried 7 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS) 2021-04-28 03:28:19,251 INFO [main] org.apache.hadoop.ipc.Client: Retrying connect to server: dataware-14/10.39.58.19:1983. Already tried 8 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS) 2021-04-28 03:28:23,253 INFO [main] org.apache.hadoop.ipc.Client: Retrying connect to server: dataware-14/10.39.58.19:1983. Already tried 9 time(s); retry policy is RetryUpToMaximumCountWithFixedSleep(maxRetries=10, sleepTime=1000 MILLISECONDS) 2021-04-28 03:28:26,258 WARN [main] org.apache.hadoop.mapred.YarnChild: Exception running child : java.net.ConnectException: Call From dataware-17/10.39.58.15 to dataware-14:1983 failed on connection exception: java.net.ConnectException: Connection timed out; For more details see: http://wiki.apache.org/hadoop/ConnectionRefused at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:791) at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:731) at org.apache.hadoop.ipc.Client.call(Client.java:1508) at org.apache.hadoop.ipc.Client.call(Client.java:1441) at org.apache.hadoop.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:246) at com.sun.proxy.$Proxy9.getTask(Unknown Source) at org.apache.hadoop.mapred.YarnChild.main(YarnChild.java:132) Caused by: java.net.ConnectException: Connection timed out at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) at org.apache.hadoop.net.SocketIOWithTimeout.connect(SocketIOWithTimeout.java:206) at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:530) at org.apache.hadoop.net.NetUtils.connect(NetUtils.java:494) at org.apache.hadoop.ipc.Client$Connection.setupConnection(Client.java:648) at org.apache.hadoop.ipc.Client$Connection.setupIOstreams(Client.java:744) at org.apache.hadoop.ipc.Client$Connection.access$3000(Client.java:396) at org.apache.hadoop.ipc.Client.getConnection(Client.java:1557) at org.apache.hadoop.ipc.Client.call(Client.java:1480) ... 4 more     ... View more

you are right, the connection is between two Nodemanager,  and i assume dataware-3 :1079 is app master, another one is a task.  that's why i said the connection timeout is from task to appmaster. since this kind error just happend randomly, and 1 time per hour, so it's really hard for me to find out root cause.    ... View more

after monitor agent status more than ten days, I think this issue has been resolved by your solution. it seems this issue caused by impala logs, since I just have changed the impala log level to WARN, then it haven't happened again. thanks. ... View more

after change Impala log level to WARN, the agent connectivity  issue happened frequency has been reduced. but still two servers happened, after stop agent and delete impala log, these the issue on these two servers hasn't happened again.   I will continue monitor the agent issue, and feedback to you.     ... View more

basically these node machines just install DataNode, impala, node manager, no others.    I have changed impala log to WARN level, if this issue still happened  then I will change other DataNode and node manager log level. hope can find out root cause .   anything good and bad news will feed back to you , thanks. ... View more

OS version is : CentOS 7.4 , it doesn't have swap space, is this a matter ? the below log I am not sure it has connection to swap, if Cloudera manager require swap, I can try to add swap space.    [04/Dec/2019 01:16:49 +0000] 28842 MonitorDaemon-Reporter throttling_logger WARNING Failed to get swap memory usage for process 13345: list index out of range   ... View more

04/Dec/2019 01:14:54 +0000] 28842 MainThread agent WARNING Long HB processing time: 12.050262928 [04/Dec/2019 01:15:03 +0000] 28842 MainThread agent WARNING Long HB processing time: 6.31600308418 [04/Dec/2019 01:15:18 +0000] 28842 MainThread agent WARNING Long HB processing time: 5.97873497009 [04/Dec/2019 01:15:34 +0000] 28842 MainThread agent WARNING Long HB processing time: 7.34343314171 [04/Dec/2019 01:15:54 +0000] 28842 MainThread agent WARNING Long HB processing time: 12.1208558083 [04/Dec/2019 01:16:14 +0000] 28842 MainThread agent WARNING Long HB processing time: 16.9043488503 [04/Dec/2019 01:16:26 +0000] 28842 MainThread agent WARNING Long HB processing time: 12.2732441425 [04/Dec/2019 01:16:47 +0000] 28842 MainThread agent WARNING Long HB processing time: 18.1826350689 [04/Dec/2019 01:16:47 +0000] 28842 MainThread agent WARNING Delayed HB: 3s since last [04/Dec/2019 01:16:49 +0000] 28842 MonitorDaemon-Reporter throttling_logger WARNING Failed to get swap memory usage for process 13345: list index out of range [04/Dec/2019 01:18:02 +0000] 28842 MainThread agent WARNING Long HB processing time: 15.3277680874 [04/Dec/2019 01:18:27 +0000] 28842 MainThread agent WARNING Long HB processing time: 9.59771895409 [04/Dec/2019 01:18:47 +0000] 28842 MainThread agent WARNING Long HB processing time: 14.4301588535 [04/Dec/2019 01:18:53 +0000] 28842 MainThread agent WARNING Long HB processing time: 5.77177095413 [04/Dec/2019 01:19:17 +0000] 28842 MainThread agent WARNING Long HB processing time: 14.8392968178 [04/Dec/2019 01:19:33 +0000] 28842 MainThread agent WARNING Long HB processing time: 15.5372338295 [04/Dec/2019 01:20:50 +0000] 28842 MainThread agent WARNING Long HB processing time: 46.7583889961 [04/Dec/2019 01:20:50 +0000] 28842 MainThread agent WARNING Delayed HB: 31s since last [04/Dec/2019 01:22:24 +0000] 28842 MainThread heartbeat_tracker INFO HB stats (seconds): num:31 LIFE_MIN:0.00 min:0.02 mean:0.28 max:2.14 LIFE_MAX:4.53 [04/Dec/2019 01:22:25 +0000] 28842 MainThread throttling_logger INFO (12 skipped) Identified java component java8 with full version java version "1.8.0_181" Java(TM) SE Runtime Environment (build 1.8.0_181-b13) Java HotSpot(TM) 64-Bit Server VM (build 25.181-b13, mixed mode) for requested version 8. [04/Dec/2019 01:22:26 +0000] 28842 MainThread agent WARNING Long HB processing time: 95.7612428665 [04/Dec/2019 01:22:26 +0000] 28842 MainThread agent WARNING Delayed HB: 80s since last [04/Dec/2019 01:22:32 +0000] 28842 MainThread agent WARNING Long HB processing time: 6.20306706429 [04/Dec/2019 01:24:18 +0000] 28842 MainThread agent WARNING Long HB processing time: 97.3476579189 [04/Dec/2019 01:24:18 +0000] 28842 MainThread agent WARNING Delayed HB: 82s since last [04/Dec/2019 01:25:32 +0000] 28842 MainThread agent WARNING Long HB processing time: 73.8358900547 [04/Dec/2019 01:25:32 +0000] 28842 MainThread agent WARNING Delayed HB: 58s since last [04/Dec/2019 01:26:21 +0000] 28842 MainThread agent WARNING Long HB processing time: 48.3692760468 [04/Dec/2019 01:26:21 +0000] 28842 MainThread agent WARNING Delayed HB: 33s since last [04/Dec/2019 01:28:50 +0000] 28842 MainThread agent WARNING Long HB processing time: 149.57425499 [04/Dec/2019 01:28:50 +0000] 28842 MainThread agent WARNING Delayed HB: 134s since last [04/Dec/2019 01:30:42 +0000] 28842 MainThread agent WARNING Long HB processing time: 111.463696957 [04/Dec/2019 01:30:42 +0000] 28842 MainThread agent WARNING Delayed HB: 96s since last [04/Dec/2019 01:30:47 +0000] 28842 MainThread agent WARNING Long HB processing time: 5.08097100258 [04/Dec/2019 01:32:58 +0000] 28842 MainThread heartbeat_tracker INFO HB stats (seconds): num:8 LIFE_MIN:0.00 min:0.11 mean:0.71 max:1.96 LIFE_MAX:4.53 [04/Dec/2019 01:33:00 +0000] 28842 MainThread agent WARNING Long HB processing time: 122.480878115 [04/Dec/2019 01:33:00 +0000] 28842 MainThread agent WARNING Delayed HB: 107s since last [04/Dec/2019 01:34:10 +0000] 28842 MainThread agent WARNING Long HB processing time: 69.9775719643 [04/Dec/2019 01:34:10 +0000] 28842 MainThread agent WARNING Delayed HB: 55s since last [04/Dec/2019 01:35:45 +0000] 28842 MainThread agent WARNING Long HB processing time: 95.0239050388 [04/Dec/2019 01:35:45 +0000] 28842 MainThread agent WARNING Delayed HB: 80s since last [04/Dec/2019 01:37:42 +0000] 28842 MainThread agent WARNING Long HB processing time: 117.279044151 [04/Dec/2019 01:37:42 +0000] 28842 MainThread agent WARNING Delayed HB: 102s since last [04/Dec/2019 01:40:33 +0000] 28842 MainThread agent WARNING Long HB processing time: 170.700104952 [04/Dec/2019 01:40:33 +0000] 28842 MainThread agent WARNING Delayed HB: 155s since last [04/Dec/2019 01:40:43 +0000] 28842 MainThread agent WARNING Long HB processing time: 10.2622208595 [04/Dec/2019 01:41:17 +0000] 28842 MainThread agent WARNING Long HB processing time: 28.4504780769 [04/Dec/2019 01:41:17 +0000] 28842 MainThread agent WARNING Delayed HB: 13s since last [04/Dec/2019 01:43:17 +0000] 28842 MainThread heartbeat_tracker INFO HB stats (seconds): num:7 LIFE_MIN:0.00 min:0.02 mean:0.94 max:1.48 LIFE_MAX:4.53 [04/Dec/2019 01:43:18 +0000] 28842 MainThread agent WARNING Long HB processing time: 121.649900913 [04/Dec/2019 01:43:18 +0000] 28842 MainThread agent WARNING Delayed HB: 106s since last [04/Dec/2019 01:44:11 +0000] 28842 MainThread agent WARNING Long HB processing time: 52.2356939316 [04/Dec/2019 01:44:11 +0000] 28842 MainThread agent WARNING Delayed HB: 37s since last [04/Dec/2019 01:44:28 +0000] 28842 MainThread agent WARNING Long HB processing time: 17.3855171204 [04/Dec/2019 01:47:23 +0000] 28842 MainThread agent WARNING Long HB processing time: 175.126209021 [04/Dec/2019 01:47:24 +0000] 28842 MainThread agent WARNING Delayed HB: 160s since last [04/Dec/2019 01:48:27 +0000] 28842 MainThread agent WARNING Long HB processing time: 63.2303080559 [04/Dec/2019 01:48:27 +0000] 28842 MainThread agent WARNING Delayed HB: 48s since last [04/Dec/2019 01:49:00 +0000] 28842 MonitorDaemon-Reporter throttling_logger ERROR (22 skipped) Role_extractor for STATESTORE is not initialized correctly. None [04/Dec/2019 01:49:12 +0000] 28842 MainThread agent WARNING Long HB processing time: 45.4053838253 [04/Dec/2019 01:49:13 +0000] 28842 MainThread agent WARNING Delayed HB: 31s since last [04/Dec/2019 01:51:19 +0000] 28842 MainThread agent WARNING Long HB processing time: 125.514182091 [04/Dec/2019 01:51:19 +0000] 28842 MainThread agent WARNING Delayed HB: 110s since last [04/Dec/2019 01:52:38 +0000] 28842 MainThread agent WARNING Long HB processing time: 78.3114128113 [04/Dec/2019 01:52:38 +0000] 28842 MainThread agent WARNING Delayed HB: 63s since last [04/Dec/2019 01:52:45 +0000] 28842 MainThread agent WARNING Long HB processing time: 6.34388899803 [04/Dec/2019 01:53:03 +0000] 28842 MainThread agent WARNING Long HB processing time: 9.70307207108 [04/Dec/2019 01:53:30 +0000] 28842 MainThread heartbeat_tracker INFO HB stats (seconds): num:10 LIFE_MIN:0.00 min:0.06 mean:0.58 max:1.79 LIFE_MAX:4.53 [04/Dec/2019 01:53:30 +0000] 28842 MainThread throttling_logger INFO (8 skipped) Identified java component java8 with full version java version "1.8.0_181" Java(TM) SE Runtime Environment (build 1.8.0_181-b13) Java HotSpot(TM) 64-Bit Server VM (build 25.181-b13, mixed mode) for requested version 8. [04/Dec/2019 01:53:30 +0000] 28842 MainThread agent WARNING Long HB processing time: 21.8870470524 [04/Dec/2019 01:53:30 +0000] 28842 MainThread agent WARNING Delayed HB: 6s since last [04/Dec/2019 01:53:46 +0000] 28842 MainThread agent WARNING Long HB processing time: 16.0326740742 [04/Dec/2019 01:54:08 +0000] 28842 MainThread agent WARNING Long HB processing time: 22.1611609459 [04/Dec/2019 01:54:08 +0000] 28842 MainThread agent WARNING Delayed HB: 7s since last [04/Dec/2019 01:54:14 +0000] 28842 MainThread agent WARNING Long HB processing time: 6.01884293556 [04/Dec/2019 01:54:34 +0000] 28842 MainThread agent WARNING Long HB processing time: 10.3302299976 [04/Dec/2019 01:54:45 +0000] 28842 MainThread agent WARNING Long HB processing time: 6.26238012314 [04/Dec/2019 01:54:59 +0000] 28842 MainThread agent WARNING Long HB processing time: 5.61235713959 [04/Dec/2019 01:55:48 +0000] 28842 MainThread agent WARNING Long HB processing time: 39.5674409866 [04/Dec/2019 01:55:48 +0000] 28842 MainThread agent WARNING Delayed HB: 24s since last [04/Dec/2019 01:56:04 +0000] 28842 MainThread agent WARNING Long HB processing time: 15.7047331333 [04/Dec/2019 01:56:45 +0000] 28842 MainThread agent WARNING Long HB processing time: 26.3552570343 [04/Dec/2019 01:56:45 +0000] 28842 MainThread agent WARNING Delayed HB: 11s since last [04/Dec/2019 01:58:15 +0000] 28842 MainThread agent WARNING Long HB processing time: 44.8799829483 [04/Dec/2019 01:58:15 +0000] 28842 MainThread agent WARNING Delayed HB: 29s since last [04/Dec/2019 01:59:02 +0000] 28842 MainThread agent WARNING Long HB processing time: 47.1872057915 [04/Dec/2019 01:59:02 +0000] 28842 MainThread agent WARNING Delayed HB: 32s since last [04/Dec/2019 01:59:17 +0000] 28842 MainThread agent WARNING Long HB processing time: 14.3799068928 [04/Dec/2019 02:00:27 +0000] 28842 MainThread agent WARNING Long HB processing time: 54.5242679119 [04/Dec/2019 02:00:27 +0000] 28842 MainThread agent WARNING Delayed HB: 39s since last [04/Dec/2019 02:01:07 +0000] 28842 MonitorDaemon-Reporter throttling_logger INFO (10 skipped) Descendants user CPU lower than expected for process 7167: 42154365.0, 42134965.36 [04/Dec/2019 02:02:45 +0000] 28842 MainThread agent WARNING Long HB processing time: 137.669925213 [04/Dec/2019 02:02:45 +0000] 28842 MainThread agent WARNING Delayed HB: 122s since last [04/Dec/2019 02:04:41 +0000] 28842 MainThread heartbeat_tracker INFO HB stats (seconds): num:20 LIFE_MIN:0.00 min:0.02 mean:0.52 max:2.48 LIFE_MAX:4.53 [04/Dec/2019 02:04:42 +0000] 28842 MainThread agent WARNING Long HB processing time: 117.50967598 [04/Dec/2019 02:04:42 +0000] 28842 MainThread agent WARNING Delayed HB: 102s since last [04/Dec/2019 02:07:01 +0000] 28842 MainThread agent WARNING Long HB processing time: 138.424443007 [04/Dec/2019 02:07:01 +0000] 28842 MainThread agent WARNING Delayed HB: 123s since last [04/Dec/2019 02:09:43 +0000] 28842 MainThread agent WARNING Long HB processing time: 162.216438055 [04/Dec/2019 02:09:44 +0000] 28842 MainThread agent WARNING Delayed HB: 147s since last [04/Dec/2019 02:11:34 +0000] 28842 MainThread agent WARNING Long HB processing time: 109.956519842 [04/Dec/2019 02:11:34 +0000] 28842 MainThread agent WARNING Delayed HB: 95s since last [04/Dec/2019 02:12:10 +0000] 28842 MainThread agent WARNING Long HB processing time: 36.4911990166 [04/Dec/2019 02:12:11 +0000] 28842 MainThread agent WARNING Delayed HB: 21s since last [04/Dec/2019 02:12:17 +0000] 28842 MainThread agent WARNING Long HB processing time: 6.5263209343 [04/Dec/2019 02:13:37 +0000] 28842 MainThread agent WARNING Long HB processing time: 71.4897689819 [04/Dec/2019 02:13:37 +0000] 28842 MainThread agent WARNING Delayed HB: 56s since last [04/Dec/2019 02:15:11 +0000] 28842 MainThread heartbeat_tracker INFO HB stats (seconds): num:7 LIFE_MIN:0.00 min:0.20 mean:1.26 max:1.96 LIFE_MAX:4.53 [04/Dec/2019 02:15:13 +0000] 28842 MainThread agent WARNING Long HB processing time: 95.5481140614 [04/Dec/2019 02:15:13 +0000] 28842 MainThread agent WARNING Delayed HB: 80s since last [04/Dec/2019 02:17:41 +0000] 28842 MainThread agent WARNING Long HB processing time: 147.541055918 [04/Dec/2019 02:17:41 +0000] 28842 MainThread agent WARNING Delayed HB: 132s since last [04/Dec/2019 02:17:52 +0000] 28842 MainThread agent WARNING Long HB processing time: 11.1138081551 [04/Dec/2019 02:18:09 +0000] 28842 MainThread agent WARNING Long HB processing time: 13.3887140751 [04/Dec/2019 02:21:01 +0000] 28842 MainThread agent WARNING Long HB processing time: 170.292068958 [04/Dec/2019 02:21:01 +0000] 28842 MainThread agent WARNING Delayed HB: 155s since last [04/Dec/2019 02:21:11 +0000] 28842 MainThread agent WARNING Long HB processing time: 9.28128290176 [04/Dec/2019 02:26:27 +0000] 28842 MainThread agent ERROR Heartbeating to 10.203.3.97:7182 failed. Traceback (most recent call last): File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/cmf/agent.py", line 1396, in _send_heartbeat response = self.requestor.request('heartbeat', heartbeat_data) File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/avro/ipc.py", line 141, in request return self.issue_request(call_request, message_name, request_datum) File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/avro/ipc.py", line 254, in issue_request call_response = self.transceiver.transceive(call_request) File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/avro/ipc.py", line 483, in transceive result = self.read_framed_message() File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/avro/ipc.py", line 487, in read_framed_message response = self.conn.getresponse() File "/usr/lib64/python2.7/httplib.py", line 1113, in getresponse response.begin() File "/usr/lib64/python2.7/httplib.py", line 444, in begin version, status, reason = self._read_status() File "/usr/lib64/python2.7/httplib.py", line 408, in _read_status raise BadStatusLine(line) BadStatusLine: '' [04/Dec/2019 02:26:27 +0000] 28842 MainThread heartbeat_tracker INFO HB stats (seconds): num:6 LIFE_MIN:0.00 min:0.02 mean:0.62 max:1.55 LIFE_MAX:4.53 [04/Dec/2019 02:26:27 +0000] 28842 MainThread agent WARNING Long HB processing time: 310.67294383 [04/Dec/2019 02:26:28 +0000] 28842 MainThread agent WARNING Delayed HB: 295s since last [04/Dec/2019 02:30:28 +0000] 28842 MainThread throttling_logger INFO (10 skipped) Identified java component java8 with full version java version "1.8.0_181" Java(TM) SE Runtime Environment (build 1.8.0_181-b13) Java HotSpot(TM) 64-Bit Server VM (build 25.181-b13, mixed mode) for requested version 8. [04/Dec/2019 02:30:29 +0000] 28842 MainThread agent WARNING Long HB processing time: 241.416838169 [04/Dec/2019 02:30:29 +0000] 28842 MainThread agent WARNING Delayed HB: 226s since last [04/Dec/2019 02:37:11 +0000] 28842 MainThread agent ERROR Heartbeating to 10.203.3.97:7182 failed. Traceback (most recent call last): File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/cmf/agent.py", line 1396, in _send_heartbeat response = self.requestor.request('heartbeat', heartbeat_data) File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/avro/ipc.py", line 141, in request return self.issue_request(call_request, message_name, request_datum) File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/avro/ipc.py", line 254, in issue_request call_response = self.transceiver.transceive(call_request) File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/avro/ipc.py", line 483, in transceive result = self.read_framed_message() File "/opt/cloudera/cm-agent/lib/python2.7/site-packages/avro/ipc.py", line 487, in read_framed_message response = self.conn.getresponse() File "/usr/lib64/python2.7/httplib.py", line 1113, in getresponse response.begin() File "/usr/lib64/python2.7/httplib.py", line 444, in begin version, status, reason = self._read_status() File "/usr/lib64/python2.7/httplib.py", line 408, in _read_status raise BadStatusLine(line) BadStatusLine: '' [04/Dec/2019 02:37:11 +0000] 28842 MainThread heartbeat_tracker INFO HB stats (seconds): num:2 LIFE_MIN:0.00 min:0.44 mean:0.48 max:0.53 LIFE_MAX:4.53 [04/Dec/2019 02:37:11 +0000] 28842 MainThread agent WARNING Long HB processing time: 402.084249973 [04/Dec/2019 02:37:11 +0000] 28842 MainThread agent WARNING Delayed HB: 387s since last   could you get useful information from the above logs ?     I can see the logs show me heartbeat failed, but I don't know why ? could you give me some advises?    thank you very much . ... View more

Hi,   after set the parameter "-max_cached_file_handles=0 " as your workaround shows me, I got another issue, it's agent heartbeat timeout. the ticket URL as below: <a href="https://community.cloudera.com/t5/Support-Questions/Cloudera-Manager-agent-bad-healthy/m-p/283865#M210854" target="_blank">https://community.cloudera.com/t5/Support-Questions/Cloudera-Manager-agent-bad-healthy/m-p/283865#M210854</a>    My CDH env has been online more than half year, agent heartbeat timeout has never been happened, but after comparing the date of setting  the impala parameter and agent  heartbeat issue date , it seems there are connection, but I am not sure .       what I mean is the agent heartbeat timeout issue happened after I set the impala parameter "-max_cached_file_handles=0 ".   is that impossible ? ... View more