[ https://issues.apache.org/jira/browse/YARN-3790?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14580965#comment-14580965 ]
zhihai xu commented on YARN-3790: --------------------------------- [~rohithsharma], thanks for updating the title. The containers are recovered. {{rootMetrics}}'s used resource is also updated, But {{rootMetrics}}'s available resource is not updated. The following logs in the failed test proved it: {code} 2015-06-09 22:55:42,964 INFO [ResourceManager Event Processor] fair.FairScheduler (FairScheduler.java:addNode(855)) - Added node 127.0.0.1:1234 cluster capacity: <memory:8192, vCores:8> 2015-06-09 22:55:42,964 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1433915736884_0001 of type NODE_UPDATE 2015-06-09 22:55:42,964 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:processNodeUpdate(820)) - Received node update event:NODE_USABLE for node:127.0.0.1:1234 with state:RUNNING 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemand(287)) - The updated demand for root.default is <memory:0, vCores:0>; the max is <memory:2147483647, vCores:2147483647> 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemand(289)) - The updated fairshare for root.default is <memory:0, vCores:0> 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSParentQueue (FSParentQueue.java:updateDemand(163)) - Counting resource from root.default <memory:0, vCores:0>; Total resource consumption for root now <memory:0, vCores:0> 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemandForApp(298)) - Counting resource from application_1433915736884_0001 <memory:0, vCores:0>; Total resource consumption for root.zxu now <memory:0, vCores:0> 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemand(287)) - The updated demand for root.zxu is <memory:0, vCores:0>; the max is <memory:2147483647, vCores:2147483647> 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemand(289)) - The updated fairshare for root.zxu is <memory:0, vCores:0> 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSParentQueue (FSParentQueue.java:updateDemand(163)) - Counting resource from root.zxu <memory:0, vCores:0>; Total resource consumption for root now <memory:0, vCores:0> 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSParentQueue (FSParentQueue.java:updateDemand(177)) - The updated demand for root is <memory:0, vCores:0>; the max is <memory:2147483647, vCores:2147483647> 2015-06-09 22:55:42,964 DEBUG [FairSchedulerUpdateThread] fair.FSQueue (FSQueue.java:setFairShare(196)) - The updated fairShare for root is <memory:8192, vCores:8> 2015-06-09 22:55:42,965 INFO [ResourceManager Event Processor] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:recoverContainersOnNode(349)) - Recovering container container_id { app_attempt_id { application_id { id: 1 cluster_timestamp: 1433915736884 } attemptId: 1 } id: 1 } container_state: C_RUNNING resource { memory: 1024 virtual_cores: 1 } priority { priority: 0 } diagnostics: "recover container" container_exit_status: 0 creation_time: 0 nodeLabelExpression: "" 2015-06-09 22:55:42,965 DEBUG [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(382)) - Processing container_1433915736884_0001_01_000001 of type RECOVER 2015-06-09 22:55:42,965 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppRunningOnNodeEvent.EventType: APP_RUNNING_ON_NODE 2015-06-09 22:55:42,965 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(394)) - container_1433915736884_0001_01_000001 Container Transitioned from NEW to RUNNING 2015-06-09 22:55:42,965 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1433915736884_0001 of type APP_RUNNING_ON_NODE 2015-06-09 22:55:42,965 INFO [ResourceManager Event Processor] scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(154)) - Assigned container container_1433915736884_0001_01_000001 of capacity <memory:1024, vCores:1> on host 127.0.0.1:1234, which has 1 containers, <memory:1024, vCores:1> used and <memory:7168, vCores:7> available after allocation 2015-06-09 22:55:42,966 INFO [ResourceManager Event Processor] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:recoverContainer(651)) - SchedulerAttempt appattempt_1433915736884_0001_000001 is recovering container container_1433915736884_0001_01_000001 2015-06-09 22:55:42,966 INFO [ResourceManager Event Processor] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:recoverContainersOnNode(349)) - Recovering container container_id { app_attempt_id { application_id { id: 1 cluster_timestamp: 1433915736884 } attemptId: 1 } id: 2 } container_state: C_RUNNING resource { memory: 1024 virtual_cores: 1 } priority { priority: 0 } diagnostics: "recover container" container_exit_status: 0 creation_time: 0 nodeLabelExpression: "" 2015-06-09 22:55:42,966 DEBUG [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(382)) - Processing container_1433915736884_0001_01_000002 of type RECOVER 2015-06-09 22:55:42,966 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppRunningOnNodeEvent.EventType: APP_RUNNING_ON_NODE 2015-06-09 22:55:42,966 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(394)) - container_1433915736884_0001_01_000002 Container Transitioned from NEW to RUNNING 2015-06-09 22:55:42,967 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1433915736884_0001 of type APP_RUNNING_ON_NODE 2015-06-09 22:55:42,967 INFO [ResourceManager Event Processor] scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(154)) - Assigned container container_1433915736884_0001_01_000002 of capacity <memory:1024, vCores:1> on host 127.0.0.1:1234, which has 2 containers, <memory:2048, vCores:2> used and <memory:6144, vCores:6> available after allocation 2015-06-09 22:55:42,967 INFO [ResourceManager Event Processor] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:recoverContainer(651)) - SchedulerAttempt appattempt_1433915736884_0001_000001 is recovering container container_1433915736884_0001_01_000002 2015-06-09 22:55:42,967 INFO [ResourceManager Event Processor] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:recoverContainersOnNode(349)) - Recovering container container_id { app_attempt_id { application_id { id: 1 cluster_timestamp: 1433915736884 } attemptId: 1 } id: 3 } container_state: C_COMPLETE resource { memory: 1024 virtual_cores: 1 } priority { priority: 0 } diagnostics: "recover container" container_exit_status: 0 creation_time: 0 nodeLabelExpression: "" 2015-06-09 22:55:42,967 DEBUG [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(382)) - Processing container_1433915736884_0001_01_000003 of type RECOVER 2015-06-09 22:55:42,967 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.event.RMAppAttemptContainerFinishedEvent.EventType: CONTAINER_FINISHED 2015-06-09 22:55:42,967 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(394)) - container_1433915736884_0001_01_000003 Container Transitioned from NEW to COMPLETED 2015-06-09 22:55:42,967 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(781)) - Processing event for appattempt_1433915736884_0001_000001 of type CONTAINER_FINISHED Container State is : RUNNING Container State is : RUNNING Received completed containers [ContainerStatus: [ContainerId: container_1433915736884_0001_01_000003, State: COMPLETE, Diagnostics: recover container, ExitStatus: 0, ]] 2015-06-09 22:55:43,266 DEBUG [Thread-645] fair.FSAppAttempt (FSAppAttempt.java:getHeadroom(200)) - Headroom calculation for application_1433915736884_0001:Min((queueFairShare=<memory:8192, vCores:8> - queueUsage=<memory:2048, vCores:2>), maxAvailableResource=<memory:6144, vCores:6>Headroom=<memory:6144, vCores:6> {code} The Headroom calculation log show queueUsage=<memory:2048, vCores:2>, the code which update {{rootMetrics}}'s used resource is at {{AppSchedulingInfo#recoverContainer}} {code} metrics.allocateResources(user, 1, rmContainer.getAllocatedResource(), false); {code} And we can find the {{update}}/{{updateDemand}} is called by UpdateThread before {{recoverContainersOnNode}}. The following is the log from the succeeded test. {code} 2015-06-09 23:40:53,432 INFO [ResourceManager Event Processor] fair.FairScheduler (FairScheduler.java:addNode(855)) - Added node 127.0.0.1:1234 cluster capacity: <memory:8192, vCores:8> 2015-06-09 23:40:53,432 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1433918447351_0001 of type NODE_UPDATE 2015-06-09 23:40:53,432 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:processNodeUpdate(820)) - Received node update event:NODE_USABLE for node:127.0.0.1:1234 with state:RUNNING 2015-06-09 23:40:53,432 INFO [ResourceManager Event Processor] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:recoverContainersOnNode(349)) - Recovering container container_id { app_attempt_id { application_id { id: 1 cluster_timestamp: 1433918447351 } attemptId: 1 } id: 1 } container_state: C_RUNNING resource { memory: 1024 virtual_cores: 1 } priority { priority: 0 } diagnostics: "recover container" container_exit_status: 0 creation_time: 0 nodeLabelExpression: "" 2015-06-09 23:40:53,433 DEBUG [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(382)) - Processing container_1433918447351_0001_01_000001 of type RECOVER 2015-06-09 23:40:53,433 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(394)) - container_1433918447351_0001_01_000001 Container Transitioned from NEW to RUNNING 2015-06-09 23:40:53,433 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppRunningOnNodeEvent.EventType: APP_RUNNING_ON_NODE 2015-06-09 23:40:53,433 INFO [ResourceManager Event Processor] scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(154)) - Assigned container container_1433918447351_0001_01_000001 of capacity <memory:1024, vCores:1> on host 127.0.0.1:1234, which has 1 containers, <memory:1024, vCores:1> used and <memory:7168, vCores:7> available after allocation 2015-06-09 23:40:53,433 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1433918447351_0001 of type APP_RUNNING_ON_NODE 2015-06-09 23:40:53,434 INFO [ResourceManager Event Processor] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:recoverContainer(651)) - SchedulerAttempt appattempt_1433918447351_0001_000001 is recovering container container_1433918447351_0001_01_000001 2015-06-09 23:40:53,435 INFO [ResourceManager Event Processor] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:recoverContainersOnNode(349)) - Recovering container container_id { app_attempt_id { application_id { id: 1 cluster_timestamp: 1433918447351 } attemptId: 1 } id: 2 } container_state: C_RUNNING resource { memory: 1024 virtual_cores: 1 } priority { priority: 0 } diagnostics: "recover container" container_exit_status: 0 creation_time: 0 nodeLabelExpression: "" 2015-06-09 23:40:53,435 DEBUG [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(382)) - Processing container_1433918447351_0001_01_000002 of type RECOVER 2015-06-09 23:40:53,435 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(394)) - container_1433918447351_0001_01_000002 Container Transitioned from NEW to RUNNING 2015-06-09 23:40:53,435 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppRunningOnNodeEvent.EventType: APP_RUNNING_ON_NODE 2015-06-09 23:40:53,435 INFO [ResourceManager Event Processor] scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(154)) - Assigned container container_1433918447351_0001_01_000002 of capacity <memory:1024, vCores:1> on host 127.0.0.1:1234, which has 2 containers, <memory:2048, vCores:2> used and <memory:6144, vCores:6> available after allocation 2015-06-09 23:40:53,435 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(756)) - Processing event for application_1433918447351_0001 of type APP_RUNNING_ON_NODE 2015-06-09 23:40:53,435 INFO [ResourceManager Event Processor] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:recoverContainer(651)) - SchedulerAttempt appattempt_1433918447351_0001_000001 is recovering container container_1433918447351_0001_01_000002 2015-06-09 23:40:53,436 INFO [ResourceManager Event Processor] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:recoverContainersOnNode(349)) - Recovering container container_id { app_attempt_id { application_id { id: 1 cluster_timestamp: 1433918447351 } attemptId: 1 } id: 3 } container_state: C_COMPLETE resource { memory: 1024 virtual_cores: 1 } priority { priority: 0 } diagnostics: "recover container" container_exit_status: 0 creation_time: 0 nodeLabelExpression: "" 2015-06-09 23:40:53,436 DEBUG [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(382)) - Processing container_1433918447351_0001_01_000003 of type RECOVER 2015-06-09 23:40:53,436 INFO [ResourceManager Event Processor] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(394)) - container_1433918447351_0001_01_000003 Container Transitioned from NEW to COMPLETED 2015-06-09 23:40:53,436 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(167)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.event.RMAppAttemptContainerFinishedEvent.EventType: CONTAINER_FINISHED 2015-06-09 23:40:53,436 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(781)) - Processing event for appattempt_1433918447351_0001_000001 of type CONTAINER_FINISHED 2015-06-09 23:40:53,436 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemand(287)) - The updated demand for root.default is <memory:0, vCores:0>; the max is <memory:2147483647, vCores:2147483647> 2015-06-09 23:40:53,436 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemand(289)) - The updated fairshare for root.default is <memory:0, vCores:0> 2015-06-09 23:40:53,436 DEBUG [FairSchedulerUpdateThread] fair.FSParentQueue (FSParentQueue.java:updateDemand(163)) - Counting resource from root.default <memory:0, vCores:0>; Total resource consumption for root now <memory:0, vCores:0> 2015-06-09 23:40:53,437 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemandForApp(298)) - Counting resource from application_1433918447351_0001 <memory:2048, vCores:2>; Total resource consumption for root.zxu now <memory:0, vCores:0> 2015-06-09 23:40:53,437 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemand(287)) - The updated demand for root.zxu is <memory:2048, vCores:2>; the max is <memory:2147483647, vCores:2147483647> 2015-06-09 23:40:53,437 DEBUG [FairSchedulerUpdateThread] fair.FSLeafQueue (FSLeafQueue.java:updateDemand(289)) - The updated fairshare for root.zxu is <memory:0, vCores:0> 2015-06-09 23:40:53,437 DEBUG [FairSchedulerUpdateThread] fair.FSParentQueue (FSParentQueue.java:updateDemand(163)) - Counting resource from root.zxu <memory:2048, vCores:2>; Total resource consumption for root now <memory:0, vCores:0> 2015-06-09 23:40:53,437 DEBUG [FairSchedulerUpdateThread] fair.FSParentQueue (FSParentQueue.java:updateDemand(177)) - The updated demand for root is <memory:2048, vCores:2>; the max is <memory:2147483647, vCores:2147483647> 2015-06-09 23:40:53,437 DEBUG [FairSchedulerUpdateThread] fair.FSQueue (FSQueue.java:setFairShare(196)) - The updated fairShare for root is <memory:8192, vCores:8> Container State is : RUNNING Container State is : RUNNING Received completed containers [ContainerStatus: [ContainerId: container_1433918447351_0001_01_000003, State: COMPLETE, Diagnostics: recover container, ExitStatus: 0, ]] 2015-06-09 23:40:53,632 INFO [Thread-643] resourcemanager.TestWorkPreservingRMRestart (TestWorkPreservingRMRestart.java:testSchedulerRecovery(240)) - testSchedulerRecovery end 2015-06-09 23:40:53,733 DEBUG [Thread-643] fair.FSAppAttempt (FSAppAttempt.java:getHeadroom(200)) - Headroom calculation for application_1433918447351_0001:Min((queueFairShare=<memory:8192, vCores:8> - queueUsage=<memory:2048, vCores:2>), maxAvailableResource=<memory:6144, vCores:6>Headroom=<memory:6144, vCores:6> {code} And we can find the {{update}}/{{updateDemand}} is called by UpdateThread after {{recoverContainersOnNode}}. The test passed, because {{update}} set {{rootMetrics}}'s available resource correctly after {{recoverContainersOnNode}} updated {{rootMetrics}}'s used resource. > TestWorkPreservingRMRestart#testSchedulerRecovery fails intermittently in > trunk for FS scheduler > ------------------------------------------------------------------------------------------------ > > Key: YARN-3790 > URL: https://issues.apache.org/jira/browse/YARN-3790 > Project: Hadoop YARN > Issue Type: Bug > Components: test > Reporter: Rohith > Assignee: zhihai xu > > Failure trace is as follows > {noformat} > Tests run: 28, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 284.078 sec > <<< FAILURE! - in > org.apache.hadoop.yarn.server.resourcemanager.TestWorkPreservingRMRestart > testSchedulerRecovery[1](org.apache.hadoop.yarn.server.resourcemanager.TestWorkPreservingRMRestart) > Time elapsed: 6.502 sec <<< FAILURE! > java.lang.AssertionError: expected:<6144> but was:<8192> > at org.junit.Assert.fail(Assert.java:88) > at org.junit.Assert.failNotEquals(Assert.java:743) > at org.junit.Assert.assertEquals(Assert.java:118) > at org.junit.Assert.assertEquals(Assert.java:555) > at org.junit.Assert.assertEquals(Assert.java:542) > at > org.apache.hadoop.yarn.server.resourcemanager.TestWorkPreservingRMRestart.assertMetrics(TestWorkPreservingRMRestart.java:853) > at > org.apache.hadoop.yarn.server.resourcemanager.TestWorkPreservingRMRestart.checkFSQueue(TestWorkPreservingRMRestart.java:342) > at > org.apache.hadoop.yarn.server.resourcemanager.TestWorkPreservingRMRestart.testSchedulerRecovery(TestWorkPreservingRMRestart.java:241) > {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)