[
https://issues.apache.org/jira/browse/YARN-4227?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14962935#comment-14962935
]
Wilfred Spiegelenburg commented on YARN-4227:
---------------------------------------------
I dug through the logs and it looks similar to [YARN-3675] however the time lag
is far larger and there are multiple allocations happening in between the
removal of the node and the allocation. These allocations happen on other
nodes. I would have expected that the node removal would have been processed in
that time.
{code}
2015-09-11 23:47:52,589 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.SchedulerNode: Released
container container_e11_1438912039098_1027475_01_000012 of capacity
<memory:6144, vCores:1> on host XXXX.com:8041, which currently has 0
containers, <memory:0, vCores:0> used and <memory:221184, vCores:36> available,
release resources=true
2015-09-11 23:47:52,589 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler:
Application attempt appattempt_1438912039098_1027475_000001 released container
container_e11_1438912039098_1027475_01_000012 on node: host: XXXX.com:8041
#containers=0 available=221184 used=0 with event: KILL
2015-09-11 23:47:52,596 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler:
Removed node XXXX.com:8041 cluster capacity: <memory:17190912, vCores:2798>
2015-09-11 23:47:52,596 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler:
Null container completed...
2015-09-11 23:47:52,598 INFO
org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.RMContainerImpl:
container_e11_1438912039098_1027474_01_002591 Container Transitioned from
RUNNING to COMPLETED
2015-09-11 23:47:52,598 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FSAppAttempt:
Completed container: container_e11_1438912039098_1027474_01_002591 in state:
COMPLETED event:FINISHED
2015-09-11 23:47:52,598 INFO
org.apache.hadoop.yarn.server.resourcemanager.RMAuditLogger: USER=my_user
OPERATION=AM Released Container TARGET=SchedulerApp RESULT=SUCCESS
APPID=application_1438912039098_1027474
CONTAINERID=container_e11_1438912039098_1027474_01_002591
2015-09-11 23:47:52,598 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.SchedulerNode: Released
container container_e11_1438912039098_1027474_01_002591 of capacity
<memory:6144, vCores:1> on host YYYY.com:8041, which currently has 5
containers, <memory:24576, vCores:5> used and <memory:159744, vCores:25>
available, release resources=true
2015-09-11 23:47:52,598 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler:
Application attempt appattempt_1438912039098_1027474_000001 released container
container_e11_1438912039098_1027474_01_002591 on node: host: YYYY.com:8041
#containers=5 available=159744 used=24576 with event: FINISHED
2015-09-11 23:47:52,599 INFO
org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.RMContainerImpl:
container_e11_1438912039098_1027474_01_002648 Container Transitioned from NEW
to ALLOCATED
2015-09-11 23:47:52,599 INFO
org.apache.hadoop.yarn.server.resourcemanager.RMAuditLogger: USER=my_user
OPERATION=AM Allocated Container TARGET=SchedulerApp RESULT=SUCCESS
APPID=application_1438912039098_1027474
CONTAINERID=container_e11_1438912039098_1027474_01_002648
2015-09-11 23:47:52,600 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.SchedulerNode: Assigned
container container_e11_1438912039098_1027474_01_002648 of capacity
<memory:6144, vCores:1> on host YYYY.com:8041, which has 6 containers,
<memory:30720, vCores:6> used and <memory:153600, vCores:24> available after
allocation
2015-09-11 23:47:52,600 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler:
Null container completed...
2015-09-11 23:47:52,601 INFO
org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.RMContainerImpl:
container_e11_1438912039098_1027474_01_002649 Container Transitioned from NEW
to ALLOCATED
2015-09-11 23:47:52,601 INFO
org.apache.hadoop.yarn.server.resourcemanager.RMAuditLogger: USER=my_user
OPERATION=AM Allocated Container TARGET=SchedulerApp RESULT=SUCCESS
APPID=application_1438912039098_1027474
CONTAINERID=container_e11_1438912039098_1027474_01_002649
2015-09-11 23:47:52,601 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.SchedulerNode: Assigned
container container_e11_1438912039098_1027474_01_002649 of capacity
<memory:6144, vCores:1> on host YYYY.com:8041, which has 9 containers,
<memory:51712, vCores:9> used and <memory:169472, vCores:27> available after
allocation
2015-09-11 23:47:52,604 INFO
org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.RMContainerImpl:
container_e11_1438912039098_1027474_01_002650 Container Transitioned from NEW
to ALLOCATED
2015-09-11 23:47:52,604 INFO
org.apache.hadoop.yarn.server.resourcemanager.RMAuditLogger: USER=my_user
OPERATION=AM Allocated Container TARGET=SchedulerApp RESULT=SUCCESS
APPID=application_1438912039098_1027474
CONTAINERID=container_e11_1438912039098_1027474_01_002650
2015-09-11 23:47:52,604 INFO
org.apache.hadoop.yarn.server.resourcemanager.scheduler.SchedulerNode: Assigned
container container_e11_1438912039098_1027474_01_002650 of capacity
<memory:6144, vCores:1> on host XXXX.com:8041, which has 1 containers,
<memory:6144, vCores:1> used and <memory:215040, vCores:35> available after
allocation
{code}
Getting a list of nodes that was not updated 8ms after the removal seems to
point to an issue in node processing caused by far to coarse locking. I am thus
not so sure that we can attribute this to the same race condition (I know I am
being really careful here). The log given above from timestamp 47:52,589 to
47:52,604 is complete no lines removed.
BTW: this example might have been taken from a different application since I
have seen this a number of times over the last weeks
> FairScheduler: RM quits processing expired container from a removed node
> ------------------------------------------------------------------------
>
> Key: YARN-4227
> URL: https://issues.apache.org/jira/browse/YARN-4227
> Project: Hadoop YARN
> Issue Type: Bug
> Components: fairscheduler
> Affects Versions: 2.3.0, 2.5.0, 2.7.1
> Reporter: Wilfred Spiegelenburg
> Assignee: Wilfred Spiegelenburg
> Priority: Critical
> Attachments: YARN-4227.2.patch, YARN-4227.3.patch, YARN-4227.4.patch,
> YARN-4227.patch
>
>
> Under some circumstances the node is removed before an expired container
> event is processed causing the RM to exit:
> {code}
> 2015-10-04 21:14:01,063 INFO
> org.apache.hadoop.yarn.util.AbstractLivelinessMonitor:
> Expired:container_1436927988321_1307950_01_000012 Timed out after 600 secs
> 2015-10-04 21:14:01,063 INFO
> org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.RMContainerImpl:
> container_1436927988321_1307950_01_000012 Container Transitioned from
> ACQUIRED to EXPIRED
> 2015-10-04 21:14:01,063 INFO
> org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FSSchedulerApp:
> Completed container: container_1436927988321_1307950_01_000012 in state:
> EXPIRED event:EXPIRE
> 2015-10-04 21:14:01,063 INFO
> org.apache.hadoop.yarn.server.resourcemanager.RMAuditLogger: USER=system_op
> OPERATION=AM Released Container TARGET=SchedulerApp RESULT=SUCCESS
> APPID=application_1436927988321_1307950
> CONTAINERID=container_1436927988321_1307950_01_000012
> 2015-10-04 21:14:01,063 FATAL
> org.apache.hadoop.yarn.server.resourcemanager.ResourceManager: Error in
> handling event type CONTAINER_EXPIRED to the scheduler
> java.lang.NullPointerException
> at
> org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler.completedContainer(FairScheduler.java:849)
> at
> org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler.handle(FairScheduler.java:1273)
> at
> org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.FairScheduler.handle(FairScheduler.java:122)
> at
> org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$SchedulerEventDispatcher$EventProcessor.run(ResourceManager.java:585)
> at java.lang.Thread.run(Thread.java:745)
> 2015-10-04 21:14:01,063 INFO
> org.apache.hadoop.yarn.server.resourcemanager.ResourceManager: Exiting, bbye..
> {code}
> The stack trace is from 2.3.0 but the same issue has been observed in 2.5.0
> and 2.6.0 by different customers.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
