hadoop-yarn-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Haibo Chen (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (YARN-7748) TestContainerResizing.testIncreaseContainerUnreservedWhenApplicationCompleted failed
Date Sun, 14 Jan 2018 16:16:00 GMT

    [ https://issues.apache.org/jira/browse/YARN-7748?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16325652#comment-16325652 ] 

Haibo Chen commented on YARN-7748:
----------------------------------

{code}
2018-01-14 09:45:15,849 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: org.apache.hadoop.yarn.nodelabels.CommonNodeLabelsManager entered state INITED
2018-01-14 09:45:15,865 INFO  [main] conf.Configuration (Configuration.java:getConfResourceAsInputStream(2656)) - resource-types.xml not found
2018-01-14 09:45:15,865 INFO  [main] resource.ResourceUtils (ResourceUtils.java:addResourcesFileToConf(395)) - Unable to find 'resource-types.xml'.
2018-01-14 09:45:15,865 DEBUG [main] resource.ResourceUtils (ResourceUtils.java:addMandatoryResources(127)) - Adding resource type - name = memory-mb, units = Mi, type = COUNTABLE
2018-01-14 09:45:15,866 DEBUG [main] resource.ResourceUtils (ResourceUtils.java:addMandatoryResources(137)) - Adding resource type - name = vcores, units = , type = COUNTABLE
2018-01-14 09:45:15,866 DEBUG [main] resource.ResourceUtils (ResourceUtils.java:getAllocation(177)) - Mandatory Resource 'yarn.resource-types.memory-mb.minimum-allocation' is not configured in resource-types config file. Setting allocation specified using 'yarn.scheduler.minimum-allocation-mb'
2018-01-14 09:45:15,866 DEBUG [main] resource.ResourceUtils (ResourceUtils.java:getAllocation(177)) - Mandatory Resource 'yarn.resource-types.memory-mb.maximum-allocation' is not configured in resource-types config file. Setting allocation specified using 'yarn.scheduler.maximum-allocation-mb'
2018-01-14 09:45:15,866 DEBUG [main] resource.ResourceUtils (ResourceUtils.java:getAllocation(177)) - Mandatory Resource 'yarn.resource-types.vcores.minimum-allocation' is not configured in resource-types config file. Setting allocation specified using 'yarn.scheduler.minimum-allocation-vcores'
2018-01-14 09:45:15,866 DEBUG [main] resource.ResourceUtils (ResourceUtils.java:getAllocation(177)) - Mandatory Resource 'yarn.resource-types.vcores.maximum-allocation' is not configured in resource-types config file. Setting allocation specified using 'yarn.scheduler.maximum-allocation-vcores'
2018-01-14 09:45:15,866 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: ResourceManager entered state INITED
2018-01-14 09:45:15,867 INFO  [main] conf.Configuration (Configuration.java:getConfResourceAsInputStream(2659)) - found resource core-site.xml at file:/testptch/hadoop/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-server/hadoop-yarn-server-resourcemanager/target/test-classes/core-site.xml
2018-01-14 09:45:15,875 DEBUG [main] security.JniBasedUnixGroupsMappingWithFallback (JniBasedUnixGroupsMappingWithFallback.java:<init>(45)) - Group mapping impl=org.apache.hadoop.security.JniBasedUnixGroupsMapping
2018-01-14 09:45:15,876 DEBUG [main] security.Groups (Groups.java:<init>(150)) - Group mapping impl=org.apache.hadoop.security.JniBasedUnixGroupsMappingWithFallback; cacheTimeout=300000; warningDeltaMs=5000
2018-01-14 09:45:15,876 INFO  [main] security.Groups (Groups.java:refresh(401)) - clearing userToGroupsMap cache
2018-01-14 09:45:15,878 INFO  [main] conf.Configuration (Configuration.java:getConfResourceAsInputStream(2659)) - found resource yarn-site.xml at file:/testptch/hadoop/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-server/hadoop-yarn-server-resourcemanager/target/test-classes/yarn-site.xml
2018-01-14 09:45:15,887 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.RMFatalEventType for class org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$RMFatalEventDispatcher
2018-01-14 09:45:15,887 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service Dispatcher
2018-01-14 09:45:15,887 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.AdminService
2018-01-14 09:45:15,888 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: RMActiveServices entered state INITED
2018-01-14 09:45:15,888 INFO  [main] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:<init>(75)) - NMTokenKeyRollingInterval: 86400000ms and NMTokenKeyActivationDelay: 900000ms
2018-01-14 09:45:15,889 INFO  [main] security.RMContainerTokenSecretManager (RMContainerTokenSecretManager.java:<init>(79)) - ContainerTokenKeyRollingInterval: 86400000ms and ContainerTokenKeyActivationDelay: 900000ms
2018-01-14 09:45:15,890 INFO  [main] security.AMRMTokenSecretManager (AMRMTokenSecretManager.java:<init>(94)) - AMRMTokenKeyRollingInterval: 86400000ms and AMRMTokenKeyActivationDelay: 900000 ms
2018-01-14 09:45:15,891 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.RMSecretManagerService
2018-01-14 09:45:15,891 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.ContainerAllocationExpirer
2018-01-14 09:45:15,891 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service AMLivelinessMonitor
2018-01-14 09:45:15,891 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service AMLivelinessMonitor
2018-01-14 09:45:15,891 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.rmapp.monitor.RMAppLifetimeMonitor
2018-01-14 09:45:15,891 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.nodelabels.CommonNodeLabelsManager
2018-01-14 09:45:15,892 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore entered state INITED
2018-01-14 09:45:15,892 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: Dispatcher entered state INITED
2018-01-14 09:45:15,892 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStoreEventType for class org.apache.hadoop.yarn.server.resourcemanager.recovery.RMStateStore$ForwardingEventHandler
2018-01-14 09:45:15,892 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.NodesListManagerEventType for class org.apache.hadoop.yarn.server.resourcemanager.NodesListManager
2018-01-14 09:45:15,893 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.NodesListManager
2018-01-14 09:45:15,893 INFO  [main] resourcemanager.ResourceManager (ResourceManager.java:createScheduler(437)) - Using Scheduler: org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CapacityScheduler
2018-01-14 09:45:15,893 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CapacityScheduler
2018-01-14 09:45:15,893 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.scheduler.event.SchedulerEventType for class org.apache.hadoop.yarn.server.resourcemanager.MockRM$1
2018-01-14 09:45:15,894 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppEventType for class org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$ApplicationEventDispatcher
2018-01-14 09:45:15,894 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptEventType for class org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$ApplicationAttemptEventDispatcher
2018-01-14 09:45:15,894 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.rmnode.RMNodeEventType for class org.apache.hadoop.yarn.server.resourcemanager.ResourceManager$NodeEventDispatcher
2018-01-14 09:45:15,894 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service NMLivelinessMonitor
2018-01-14 09:45:15,895 INFO  [main] security.RMContainerTokenSecretManager (RMContainerTokenSecretManager.java:rollMasterKey(107)) - Rolling master-key for container-tokens
2018-01-14 09:45:15,895 INFO  [main] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:rollMasterKey(95)) - Rolling master-key for nm-tokens
2018-01-14 09:45:15,896 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.ResourceTrackerService
2018-01-14 09:45:15,896 DEBUG [main] impl.MetricsSystemImpl (MetricsSystemImpl.java:initMode(627)) - from system property: null
2018-01-14 09:45:15,896 DEBUG [main] impl.MetricsSystemImpl (MetricsSystemImpl.java:initMode(628)) - from environment variable: null
2018-01-14 09:45:15,902 WARN  [main] impl.MetricsConfig (MetricsConfig.java:loadFirst(134)) - Cannot locate configuration: tried hadoop-metrics2-resourcemanager.properties,hadoop-metrics2.properties
2018-01-14 09:45:15,903 DEBUG [main] impl.MetricsConfig (MetricsConfig.java:getPropertyInternal(189)) - poking parent 'PropertiesConfiguration' for key: period
2018-01-14 09:45:15,903 DEBUG [main] impl.MetricsConfig (MetricsConfig.java:getPropertyInternal(189)) - poking parent 'PropertiesConfiguration' for key: periodMillis
2018-01-14 09:45:15,904 DEBUG [main] impl.MetricsConfig (MetricsConfig.java:getPropertyInternal(189)) - poking parent 'PropertiesConfiguration' for key: source.source.start_mbeans
2018-01-14 09:45:15,904 DEBUG [main] impl.MetricsConfig (MetricsConfig.java:getPropertyInternal(189)) - poking parent 'MetricsConfig' for key: source.start_mbeans
2018-01-14 09:45:15,905 DEBUG [main] impl.MetricsConfig (MetricsConfig.java:getPropertyInternal(189)) - poking parent 'PropertiesConfiguration' for key: *.source.start_mbeans
2018-01-14 09:45:15,905 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:updateAttrCache(252)) - Updating attr cache...
2018-01-14 09:45:15,905 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:updateAttrCache(266)) - Done. # tags & metrics=10
2018-01-14 09:45:15,906 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:updateInfoCache(245)) - Updating info cache...
2018-01-14 09:45:15,906 DEBUG [main] impl.MetricsSystemImpl (MBeanInfoBuilder.java:get(109)) - [javax.management.MBeanAttributeInfo[description=Metrics context, name=tag.Context, type=java.lang.String, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Number of active metrics sources, name=NumActiveSources, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Number of all registered metrics sources, name=NumAllSources, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Number of active metrics sinks, name=NumActiveSinks, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Number of all registered metrics sinks, name=NumAllSinks, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Number of ops for snapshot stats, name=SnapshotNumOps, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Average time for snapshot stats, name=SnapshotAvgTime, type=java.lang.Double, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Number of ops for publishing stats, name=PublishNumOps, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Average time for publishing stats, name=PublishAvgTime, type=java.lang.Double, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Dropped updates by all sinks, name=DroppedPubAll, type=java.lang.Long, read-only, descriptor={}]]
2018-01-14 09:45:15,906 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:updateInfoCache(247)) - Done
2018-01-14 09:45:15,907 DEBUG [main] util.MBeans (MBeans.java:register(68)) - Registered Hadoop:service=ResourceManager,name=MetricsSystem,sub=Stats
2018-01-14 09:45:15,907 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:startMBeans(223)) - MBean for source MetricsSystem,sub=Stats registered.
2018-01-14 09:45:15,908 INFO  [main] impl.MetricsSystemImpl (MetricsSystemImpl.java:startTimer(374)) - Scheduled Metric snapshot period at 10 second(s).
2018-01-14 09:45:15,908 INFO  [main] impl.MetricsSystemImpl (MetricsSystemImpl.java:start(191)) - ResourceManager metrics system started
2018-01-14 09:45:15,909 DEBUG [main] util.MBeans (MBeans.java:register(68)) - Registered Hadoop:service=ResourceManager,name=MetricsSystem,sub=Control
2018-01-14 09:45:15,909 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.util.JvmPauseMonitor
2018-01-14 09:45:15,910 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.ApplicationMasterService
2018-01-14 09:45:15,910 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.RMAppManagerEventType for class org.apache.hadoop.yarn.server.resourcemanager.RMAppManager
2018-01-14 09:45:15,910 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.ClientRMService
2018-01-14 09:45:15,918 INFO  [main] event.AsyncDispatcher (AsyncDispatcher.java:register(223)) - Registering class org.apache.hadoop.yarn.server.resourcemanager.amlauncher.AMLauncherEventType for class org.apache.hadoop.yarn.server.resourcemanager.MockRM$7
2018-01-14 09:45:15,919 DEBUG [main] service.CompositeService (CompositeService.java:addService(74)) - Adding service org.apache.hadoop.yarn.server.resourcemanager.amlauncher.ApplicationMasterLauncher
2018-01-14 09:45:15,919 WARN  [main] util.MBeans (MBeans.java:register(74)) - Failed to register MBean "Hadoop:service=ResourceManager,name=RMNMInfo": Instance already exists.
2018-01-14 09:45:15,919 INFO  [main] resourcemanager.RMNMInfo (RMNMInfo.java:<init>(63)) - Registered RMNMInfo MBean
2018-01-14 09:45:15,920 DEBUG [main] service.CompositeService (CompositeService.java:serviceInit(105)) - RMActiveServices: initing services, size=14
2018-01-14 09:45:15,920 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: org.apache.hadoop.yarn.server.resourcemanager.RMSecretManagerService entered state INITED
2018-01-14 09:45:15,920 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: org.apache.hadoop.yarn.server.resourcemanager.rmcontainer.ContainerAllocationExpirer entered state INITED
2018-01-14 09:45:15,920 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: AMLivelinessMonitor entered state INITED
2018-01-14 09:45:15,921 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: AMLivelinessMonitor entered state INITED
2018-01-14 09:45:15,921 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: org.apache.hadoop.yarn.server.resourcemanager.rmapp.monitor.RMAppLifetimeMonitor entered state INITED
2018-01-14 09:45:15,921 INFO  [main] monitor.RMAppLifetimeMonitor (RMAppLifetimeMonitor.java:serviceInit(66)) - Application lifelime monitor interval set to 3000 ms.
2018-01-14 09:45:15,921 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: org.apache.hadoop.yarn.server.resourcemanager.NodesListManager entered state INITED
2018-01-14 09:45:15,921 INFO  [main] util.HostsFileReader (HostsFileReader.java:refresh(211)) - Refreshing hosts (include/exclude) list
2018-01-14 09:45:15,922 DEBUG [main] resourcemanager.NodesListManager (NodesListManager.java:printConfiguredHosts(194)) - hostsReader: in= out=
2018-01-14 09:45:15,922 DEBUG [main] service.CompositeService (CompositeService.java:serviceInit(105)) - org.apache.hadoop.yarn.server.resourcemanager.NodesListManager: initing services, size=0
2018-01-14 09:45:15,923 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CapacityScheduler entered state INITED
2018-01-14 09:45:15,925 INFO  [main] conf.Configuration (Configuration.java:getConfResourceAsInputStream(2659)) - found resource capacity-scheduler.xml at file:/testptch/hadoop/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-server/hadoop-yarn-server-resourcemanager/target/test-classes/capacity-scheduler.xml
2018-01-14 09:45:15,934 INFO  [main] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getMinimumAllocation(1353)) - Minimum allocation = <memory:1024, vCores:1>
2018-01-14 09:45:15,934 INFO  [main] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:getMaximumAllocation(1365)) - Maximum allocation = <memory:8192, vCores:4>
2018-01-14 09:45:15,934 DEBUG [main] service.AbstractService (AbstractService.java:enterState(453)) - Service: org.apache.hadoop.yarn.server.resourcemanager.scheduler.activities.ActivitiesManager entered state INITED
2018-01-14 09:45:15,934 DEBUG [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getQueues(807)) - CSConf - getQueues called for: queuePrefix=yarn.scheduler.capacity.root.
2018-01-14 09:45:15,934 DEBUG [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getQueues(817)) - CSConf - getQueues: queuePrefix=yarn.scheduler.capacity.root., queues=default
2018-01-14 09:45:15,935 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.AMResourceLimitMB with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[AM memory limit in MB])
2018-01-14 09:45:15,935 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.AMResourceLimitVCores with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[AM CPU limit in virtual cores])
2018-01-14 09:45:15,936 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.usedAMResourceMB with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Used AM memory limit in MB])
2018-01-14 09:45:15,936 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.usedAMResourceVCores with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Used AM CPU limit in virtual cores])
2018-01-14 09:45:15,936 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeFloat org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.usedCapacity with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Percent of Capacity Used])
2018-01-14 09:45:15,936 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeFloat org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.absoluteUsedCapacity with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Percent of Absolute Capacity Used])
2018-01-14 09:45:15,937 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsSubmitted with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of apps submitted])
2018-01-14 09:45:15,937 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsRunning with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of running apps])
2018-01-14 09:45:15,937 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsPending with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of pending apps])
2018-01-14 09:45:15,943 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsCompleted with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of apps completed])
2018-01-14 09:45:15,944 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsKilled with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of apps killed])
2018-01-14 09:45:15,944 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsFailed with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of apps failed])
2018-01-14 09:45:15,944 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateNodeLocalContainersAllocated with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of allocated node-local containers])
2018-01-14 09:45:15,944 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateRackLocalContainersAllocated with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of allocated rack-local containers])
2018-01-14 09:45:15,945 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateOffSwitchContainersAllocated with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of allocated off-switch containers])
2018-01-14 09:45:15,945 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateContainersPreempted with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of preempted containers])
2018-01-14 09:45:15,945 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.activeUsers with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of active users])
2018-01-14 09:45:15,945 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.activeApplications with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of active applications])
2018-01-14 09:45:15,945 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableRate org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appAttemptFirstContainerAllocationDelay with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[App Attempt First Container Allocation Delay])
2018-01-14 09:45:15,946 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.allocatedMB with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Allocated memory in MB])
2018-01-14 09:45:15,946 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.allocatedVCores with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Allocated CPU in virtual cores])
2018-01-14 09:45:15,946 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.allocatedContainers with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of allocated containers])
2018-01-14 09:45:15,946 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateContainersAllocated with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of allocated containers])
2018-01-14 09:45:15,947 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateContainersReleased with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of released containers])
2018-01-14 09:45:15,947 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.availableMB with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Available memory in MB])
2018-01-14 09:45:15,947 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.availableVCores with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Available CPU in virtual cores])
2018-01-14 09:45:15,947 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.pendingMB with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Pending memory allocation in MB])
2018-01-14 09:45:15,948 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.pendingVCores with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Pending CPU allocation in virtual cores])
2018-01-14 09:45:15,948 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.pendingContainers with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of pending containers])
2018-01-14 09:45:15,948 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.reservedMB with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of reserved memory in MB])
2018-01-14 09:45:15,948 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.reservedVCores with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Reserved CPU in virtual cores])
2018-01-14 09:45:15,949 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.reservedContainers with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of reserved containers])
2018-01-14 09:45:15,949 DEBUG [main] impl.MetricsSystemImpl (MetricsSystemImpl.java:register(231)) - QueueMetrics,q0=root, Metrics for queue: root
2018-01-14 09:45:15,949 DEBUG [main] impl.MetricsConfig (MetricsConfig.java:getPropertyInternal(189)) - poking parent 'PropertiesConfiguration' for key: source.source.start_mbeans
2018-01-14 09:45:15,949 DEBUG [main] impl.MetricsConfig (MetricsConfig.java:getPropertyInternal(189)) - poking parent 'MetricsConfig' for key: source.start_mbeans
2018-01-14 09:45:15,950 DEBUG [main] impl.MetricsConfig (MetricsConfig.java:getPropertyInternal(189)) - poking parent 'PropertiesConfiguration' for key: *.source.start_mbeans
2018-01-14 09:45:15,950 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:updateAttrCache(252)) - Updating attr cache...
2018-01-14 09:45:15,950 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:updateAttrCache(266)) - Done. # tags & metrics=40
2018-01-14 09:45:15,950 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:updateInfoCache(245)) - Updating info cache...
2018-01-14 09:45:15,951 DEBUG [main] impl.MetricsSystemImpl (MBeanInfoBuilder.java:get(109)) - [javax.management.MBeanAttributeInfo[description=Metrics by queue, name=tag.Queue, type=java.lang.String, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Metrics context, name=tag.Context, type=java.lang.String, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Local hostname, name=tag.Hostname, type=java.lang.String, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=, name=running_0, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=, name=running_60, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=, name=running_300, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=, name=running_1440, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=AM memory limit in MB, name=AMResourceLimitMB, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=AM CPU limit in virtual cores, name=AMResourceLimitVCores, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Used AM memory limit in MB, name=UsedAMResourceMB, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Used AM CPU limit in virtual cores, name=UsedAMResourceVCores, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Percent of Capacity Used, name=UsedCapacity, type=java.lang.Float, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Percent of Absolute Capacity Used, name=AbsoluteUsedCapacity, type=java.lang.Float, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of apps submitted, name=AppsSubmitted, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of running apps, name=AppsRunning, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of pending apps, name=AppsPending, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of apps completed, name=AppsCompleted, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of apps killed, name=AppsKilled, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of apps failed, name=AppsFailed, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Aggregate # of allocated node-local containers, name=AggregateNodeLocalContainersAllocated, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Aggregate # of allocated rack-local containers, name=AggregateRackLocalContainersAllocated, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Aggregate # of allocated off-switch containers, name=AggregateOffSwitchContainersAllocated, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Aggregate # of preempted containers, name=AggregateContainersPreempted, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of active users, name=ActiveUsers, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of active applications, name=ActiveApplications, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Number of ops for app Attempt First Container Allocation Delay, name=AppAttemptFirstContainerAllocationDelayNumOps, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Average time for app Attempt First Container Allocation Delay, name=AppAttemptFirstContainerAllocationDelayAvgTime, type=java.lang.Double, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Allocated memory in MB, name=AllocatedMB, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Allocated CPU in virtual cores, name=AllocatedVCores, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of allocated containers, name=AllocatedContainers, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Aggregate # of allocated containers, name=AggregateContainersAllocated, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Aggregate # of released containers, name=AggregateContainersReleased, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Available memory in MB, name=AvailableMB, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Available CPU in virtual cores, name=AvailableVCores, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Pending memory allocation in MB, name=PendingMB, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Pending CPU allocation in virtual cores, name=PendingVCores, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of pending containers, name=PendingContainers, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of reserved memory in MB, name=ReservedMB, type=java.lang.Long, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=Reserved CPU in virtual cores, name=ReservedVCores, type=java.lang.Integer, read-only, descriptor={}], javax.management.MBeanAttributeInfo[description=# of reserved containers, name=ReservedContainers, type=java.lang.Integer, read-only, descriptor={}]]
2018-01-14 09:45:15,951 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:updateInfoCache(247)) - Done
2018-01-14 09:45:15,951 DEBUG [main] util.MBeans (MBeans.java:register(68)) - Registered Hadoop:service=ResourceManager,name=QueueMetrics,q0=root
2018-01-14 09:45:15,951 DEBUG [main] impl.MetricsSourceAdapter (MetricsSourceAdapter.java:startMBeans(223)) - MBean for source QueueMetrics,q0=root registered.
2018-01-14 09:45:15,952 DEBUG [main] impl.MetricsSystemImpl (MetricsSystemImpl.java:registerSource(269)) - Registered source QueueMetrics,q0=root
2018-01-14 09:45:15,952 DEBUG [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getNonLabeledQueueCapacity(441)) - CSConf - getCapacity: queuePrefix=yarn.scheduler.capacity.root., capacity=100.0
2018-01-14 09:45:15,953 DEBUG [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getNonLabeledQueueCapacity(441)) - CSConf - getCapacity: queuePrefix=yarn.scheduler.capacity.root., capacity=100.0
2018-01-14 09:45:15,960 DEBUG [main] capacity.AbstractCSQueue (AbstractCSQueue.java:updateConfigurableResourceRequirement(446)) - capacityConfigType is 'NONE' for queue 'root
2018-01-14 09:45:15,961 DEBUG [main] capacity.AbstractCSQueue (AbstractCSQueue.java:updateConfigurableResourceRequirement(455)) - capacityConfigType is updated as 'PERCENTAGE' for queue 'root
2018-01-14 09:45:15,961 DEBUG [main] capacity.AbstractCSQueue (AbstractCSQueue.java:updateConfigurableResourceRequirement(495)) - Updating absolute resource configuration for queue:root as minResource=<memory:0, vCores:0> and maxResource=<memory:0, vCores:0>
2018-01-14 09:45:15,961 DEBUG [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getMaximumAllocationPerQueue(877)) - max alloc mb per queue for root is -1
2018-01-14 09:45:15,961 DEBUG [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getMaximumAllocationPerQueue(879)) - max alloc vcores per queue for root is -1
2018-01-14 09:45:15,961 INFO  [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getMaximumAllocationPerQueue(884)) - max alloc mb per queue for root is undefined
2018-01-14 09:45:15,961 INFO  [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getMaximumAllocationPerQueue(888)) - max alloc vcore per queue for root is undefined
2018-01-14 09:45:15,962 INFO  [main] capacity.ParentQueue (ParentQueue.java:setupQueueConfigs(149)) - root, capacity=1.0, absoluteCapacity=1.0, maxCapacity=1.0, absoluteMaxCapacity=1.0, state=RUNNING, acls=ADMINISTER_QUEUE:*SUBMIT_APP:*, labels=*,
, reservationsContinueLooking=true, orderingPolicy=utilization, priority=0
2018-01-14 09:45:15,963 INFO  [main] capacity.ParentQueue (ParentQueue.java:<init>(112)) - Initialized parent-queue root name=root, fullname=root
2018-01-14 09:45:15,963 DEBUG [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getQueues(807)) - CSConf - getQueues called for: queuePrefix=yarn.scheduler.capacity.root.default.
2018-01-14 09:45:15,963 DEBUG [main] capacity.CapacitySchedulerConfiguration (CapacitySchedulerConfiguration.java:getQueues(817)) - CSConf - getQueues: queuePrefix=yarn.scheduler.capacity.root.default., queues=
2018-01-14 09:45:15,963 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.AMResourceLimitMB with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[AM memory limit in MB])
2018-01-14 09:45:15,964 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.AMResourceLimitVCores with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[AM CPU limit in virtual cores])
2018-01-14 09:45:15,964 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.usedAMResourceMB with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Used AM memory limit in MB])
2018-01-14 09:45:15,964 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.usedAMResourceVCores with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Used AM CPU limit in virtual cores])
2018-01-14 09:45:15,964 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeFloat org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.usedCapacity with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Percent of Capacity Used])
2018-01-14 09:45:15,965 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeFloat org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.CSQueueMetrics.absoluteUsedCapacity with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Percent of Absolute Capacity Used])
2018-01-14 09:45:15,965 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsSubmitted with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of apps submitted])
2018-01-14 09:45:15,965 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsRunning with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of running apps])
2018-01-14 09:45:15,965 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsPending with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of pending apps])
2018-01-14 09:45:15,965 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsCompleted with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of apps completed])
2018-01-14 09:45:15,966 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsKilled with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of apps killed])
2018-01-14 09:45:15,966 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appsFailed with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of apps failed])
2018-01-14 09:45:15,966 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateNodeLocalContainersAllocated with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of allocated node-local containers])
2018-01-14 09:45:15,966 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateRackLocalContainersAllocated with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of allocated rack-local containers])
2018-01-14 09:45:15,966 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateOffSwitchContainersAllocated with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of allocated off-switch containers])
2018-01-14 09:45:15,967 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableCounterLong org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.aggregateContainersPreempted with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[Aggregate # of preempted containers])
2018-01-14 09:45:15,967 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.activeUsers with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of active users])
2018-01-14 09:45:15,967 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableGaugeInt org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.activeApplications with annotation @org.apache.hadoop.metrics2.annotation.Metric(sampleName=Ops, always=false, about=, type=DEFAULT, valueName=Time, value=[# of active applications])
2018-01-14 09:45:15,967 DEBUG [main] lib.MutableMetricsFactory (MutableMetricsFactory.java:newForField(43)) - field org.apache.hadoop.metrics2.lib.MutableRate org.apache.hadoop.yarn.server.resourcemanager.scheduler.QueueMetrics.appAttemptFirstContainerAllocation
...[truncated 90343 chars]...
cher event handler] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:showRequests(636)) - showRequests: application=application_1515923115995_0001 headRoom=<memory:15360, vCores:15> currentConsumption=1024
2018-01-14 09:45:16,156 DEBUG [AsyncDispatcher event handler] placement.LocalityAppPlacementAllocator (LocalityAppPlacementAllocator.java:showRequests(408)) - 	Request={AllocationRequestId: -1, Priority: 1, Capability: <memory:2048, vCores:1>, # Containers: 1, Location: *, Relax Locality: true, Execution Type Request: {Execution Type: GUARANTEED, Enforce Execution Type: false}, Node Label Expression: , Resource Profile: null}
2018-01-14 09:45:16,156 DEBUG [AsyncDispatcher event handler] capacity.ParentQueue (ParentQueue.java:assignContainersToChildQueues(787)) - Assigned to queue: root.default stats: default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:1024, vCores:1>, usedCapacity=0.0625, absoluteUsedCapacity=0.0625, numApps=1, numContainers=1, effectiveMinResource=<memory:16384, vCores:16> , effectiveMaxResource=<memory:16384, vCores:16> --> <memory:2048, vCores:1>, OFF_SWITCH
2018-01-14 09:45:16,156 INFO  [AsyncDispatcher event handler] capacity.ParentQueue (ParentQueue.java:assignContainers(669)) - assignedContainer queue=root usedCapacity=0.0625 absoluteUsedCapacity=0.0625 used=<memory:1024, vCores:1> cluster=<memory:16384, vCores:16>
2018-01-14 09:45:16,156 DEBUG [AsyncDispatcher event handler] capacity.ParentQueue (ParentQueue.java:assignContainers(675)) - ParentQ=root assignedSoFarInThisIteration=<memory:2048, vCores:1> usedCapacity=0.0625 absoluteUsedCapacity=0.0625
2018-01-14 09:45:16,156 DEBUG [AsyncDispatcher event handler] capacity.CapacityScheduler (CapacityScheduler.java:tryCommit(2598)) - Try to commit allocation proposal=New org.apache.hadoop.yarn.server.resourcemanager.scheduler.common.ResourceCommitRequest:
	 ALLOCATED=[(Application=appattempt_1515923115995_0001_000001; Node=h1:1234; Resource=<memory:2048, vCores:1>)]
2018-01-14 09:45:16,156 DEBUG [AsyncDispatcher event handler] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,156 DEBUG [AsyncDispatcher event handler] capacity.LeafQueue (LeafQueue.java:computeUserLimitAndSetHeadroom(1445)) - Headroom calculation for user user:  userLimit=<memory:16384, vCores:1> queueMaxAvailRes=<memory:16384, vCores:1> consumed=<memory:1024, vCores:1> partition=
2018-01-14 09:45:16,157 DEBUG [AsyncDispatcher event handler] scheduler.AppSchedulingInfo (AppSchedulingInfo.java:updateMetricsForAllocatedContainer(585)) - allocate: applicationId=application_1515923115995_0001 container=container_1515923115995_0001_01_000002 host=h1:1234 user=user resource=<memory:2048, vCores:1> type=OFF_SWITCH
2018-01-14 09:45:16,157 DEBUG [AsyncDispatcher event handler] capacity.UsersManager (UsersManager.java:updateNonActiveUsersResourceUsage(988)) - User 'user' has become non-active.Hence move user to non-active list.Active users size = 0Non-active users size = 1Total Resource usage for active users=<memory:0, vCores:0>.Total Resource usage for non-active users=<memory:1024, vCores:1>
2018-01-14 09:45:16,157 DEBUG [AsyncDispatcher event handler] capacity.UsersManager (UsersManager.java:deactivateApplication(883)) - User user removed from activeUsers, currently: 0
2018-01-14 09:45:16,157 DEBUG [AsyncDispatcher event handler] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(556)) - Processing container_1515923115995_0001_01_000002 of type START
2018-01-14 09:45:16,157 INFO  [AsyncDispatcher event handler] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(570)) - container_1515923115995_0001_01_000002 Container Transitioned from NEW to ALLOCATED
2018-01-14 09:45:16,157 DEBUG [AsyncDispatcher event handler] scheduler.SchedulerNode (SchedulerNode.java:allocateContainer(208)) - Assigned container container_1515923115995_0001_01_000002 of capacity <memory:2048, vCores:1> and type GUARANTEED on host host: h1:1234 #guaranteed containers=2 #opportunistic containers=0 available=<memory:5120, vCores:6> used by guaranteed containers=<memory:3072, vCores:2> used by opportunistic containers=<memory:0, vCores:0>
2018-01-14 09:45:16,158 INFO  [AsyncDispatcher event handler] fica.FiCaSchedulerNode (FiCaSchedulerNode.java:allocateContainer(169)) - Assigned container container_1515923115995_0001_01_000002 of capacity <memory:2048, vCores:1> on host h1:1234, which has 2 guaranteed containers using <memory:3072, vCores:2>, 0 opportunistic containers using <memory:0, vCores:0>
2018-01-14 09:45:16,158 DEBUG [AsyncDispatcher event handler] fica.FiCaSchedulerApp (FiCaSchedulerApp.java:apply(556)) - allocate: applicationAttemptId=appattempt_1515923115995_0001_000001 container=container_1515923115995_0001_01_000002 host=h1 type=OFF_SWITCH
2018-01-14 09:45:16,158 INFO  [AsyncDispatcher event handler] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(200)) - USER=user	OPERATION=AM Allocated Container	TARGET=SchedulerApp	RESULT=SUCCESS	APPID=application_1515923115995_0001	CONTAINERID=container_1515923115995_0001_01_000002	RESOURCE=<memory:2048, vCores:1>
2018-01-14 09:45:16,158 DEBUG [AsyncDispatcher event handler] capacity.UsersManager (UsersManager.java:updateResourceUsagePerUser(1071)) - User resource is updated.Total Resource usage for active users=<memory:0, vCores:0>.Total Resource usage for non-active users=<memory:3072, vCores:2>
2018-01-14 09:45:16,158 DEBUG [AsyncDispatcher event handler] capacity.UsersManager (UsersManager.java:computeUserLimit(779)) - User limit computation for user,  in queue: default,  userLimitPercent=100,  userLimitFactor=1.0,  required=<memory:1024, vCores:1>,  consumed=<memory:3072, vCores:1>,  user-limit-resource=<memory:16384, vCores:1>,  queueCapacity=<memory:16384, vCores:16>,  qconsumed=<memory:3072, vCores:2>,  currentCapacity=<memory:16384, vCores:16>,  activeUsers=0.0,  clusterCapacity=<memory:16384, vCores:16>,  resourceByLabel=<memory:16384, vCores:16>,  usageratio=0.1875,  Partition=,  resourceUsed=<memory:1024, vCores:1>,  maxUserLimit=<memory:16384, vCores:16>,  userWeight=1.0
2018-01-14 09:45:16,158 DEBUG [AsyncDispatcher event handler] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,159 DEBUG [AsyncDispatcher event handler] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,159 DEBUG [AsyncDispatcher event handler] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,159 DEBUG [AsyncDispatcher event handler] capacity.LeafQueue (LeafQueue.java:allocateResource(1712)) - default user=user used=<memory:3072, vCores:2> numContainers=2 headroom = <memory:13312, vCores:1> user-resources=<memory:3072, vCores:2>
2018-01-14 09:45:16,159 INFO  [AsyncDispatcher event handler] capacity.ParentQueue (ParentQueue.java:apply(1320)) - assignedContainer queue=root usedCapacity=0.1875 absoluteUsedCapacity=0.1875 used=<memory:3072, vCores:2> cluster=<memory:16384, vCores:16>
2018-01-14 09:45:16,159 INFO  [AsyncDispatcher event handler] capacity.CapacityScheduler (CapacityScheduler.java:tryCommit(2609)) - Allocation proposal accepted
2018-01-14 09:45:16,159 DEBUG [AsyncDispatcher event handler] capacity.CapacityScheduler (CapacityScheduler.java:allocateContainersToNode(1308)) - Assigned maximum number of off-switch containers: 1, assignments so far: resource:<memory:2048, vCores:1>; type:OFF_SWITCH; excessReservation:null; applicationid:null; skipped:NONE; fulfilled reservation:false; allocations(count/resource):1/<memory:2048, vCores:1>; reservations(count/resource):0/<memory:0, vCores:0>
2018-01-14 09:45:16,159 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptEvent.EventType: CONTAINER_ALLOCATED
2018-01-14 09:45:16,159 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(903)) - Processing event for appattempt_1515923115995_0001_000001 of type CONTAINER_ALLOCATED
2018-01-14 09:45:16,160 INFO  [main] resourcemanager.MockRM (MockRM.java:waitForState(478)) - Waiting for container container_1515923115995_0001_01_000002 to be ALLOCATED, container is null right now.
2018-01-14 09:45:16,170 INFO  [main] resourcemanager.MockRM (MockRM.java:waitForState(499)) - Container State is : ALLOCATED
2018-01-14 09:45:16,170 DEBUG [main] security.UserGroupInformation (UserGroupInformation.java:logPrivilegedAction(1992)) - PrivilegedAction as:appattempt_1515923115995_0001_000001 (auth:SIMPLE) from:org.apache.hadoop.yarn.server.resourcemanager.MockAM.doAllocateAs(MockAM.java:290)
2018-01-14 09:45:16,171 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.event.RMAppAttemptStatusupdateEvent.EventType: STATUS_UPDATE
2018-01-14 09:45:16,171 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(903)) - Processing event for appattempt_1515923115995_0001_000001 of type STATUS_UPDATE
2018-01-14 09:45:16,171 DEBUG [main] security.BaseContainerTokenSecretManager (BaseContainerTokenSecretManager.java:createPassword(89)) - Creating password for container_1515923115995_0001_01_000002 for user container_1515923115995_0001_01_000002 (auth:SIMPLE) to be run on NM h1:1234
2018-01-14 09:45:16,172 DEBUG [main] security.ContainerTokenIdentifier (ContainerTokenIdentifier.java:write(266)) - Writing ContainerTokenIdentifier to RPC layer: containerId { app_attempt_id { application_id { id: 1 cluster_timestamp: 1515923115995 } attemptId: 1 } id: 2 } nmHostAddr: "h1:1234" appSubmitter: "user" resource { memory: 2048 virtual_cores: 1 resource_value_map { key: "memory-mb" value: 2048 units: "Mi" type: COUNTABLE } resource_value_map { key: "vcores" value: 1 units: "" type: COUNTABLE } } expiryTimeStamp: 1515923716171 masterKeyId: 1575419537 rmIdentifier: 1515923115995 priority { priority: 1 } creationTime: 1515923116155 nodeLabelExpression: "" containerType: TASK executionType: GUARANTEED version: 0 allocation_request_id: -1
2018-01-14 09:45:16,173 DEBUG [main] security.ContainerTokenIdentifier (ContainerTokenIdentifier.java:write(266)) - Writing ContainerTokenIdentifier to RPC layer: containerId { app_attempt_id { application_id { id: 1 cluster_timestamp: 1515923115995 } attemptId: 1 } id: 2 } nmHostAddr: "h1:1234" appSubmitter: "user" resource { memory: 2048 virtual_cores: 1 resource_value_map { key: "memory-mb" value: 2048 units: "Mi" type: COUNTABLE } resource_value_map { key: "vcores" value: 1 units: "" type: COUNTABLE } } expiryTimeStamp: 1515923716171 masterKeyId: 1575419537 rmIdentifier: 1515923115995 priority { priority: 1 } creationTime: 1515923116155 nodeLabelExpression: "" containerType: TASK executionType: GUARANTEED version: 0 allocation_request_id: -1
2018-01-14 09:45:16,173 INFO  [main] security.NMTokenSecretManagerInRM (NMTokenSecretManagerInRM.java:createAndGetNMToken(200)) - Sending NMToken for nodeId : h1:1234 for container : container_1515923115995_0001_01_000002
2018-01-14 09:45:16,173 DEBUG [main] security.BaseNMTokenSecretManager (BaseNMTokenSecretManager.java:createPassword(74)) - creating password for appattempt_1515923115995_0001_000001 for user user to run on NM h1:1234
2018-01-14 09:45:16,174 DEBUG [main] security.NMTokenIdentifier (NMTokenIdentifier.java:write(96)) - Writing NMTokenIdentifier to RPC layer: appAttemptId { application_id { id: 1 cluster_timestamp: 1515923115995 } attemptId: 1 } nodeId { host: "h1" port: 1234 } appSubmitter: "user" keyId: -1458844128
2018-01-14 09:45:16,174 DEBUG [main] security.NMTokenIdentifier (NMTokenIdentifier.java:write(96)) - Writing NMTokenIdentifier to RPC layer: appAttemptId { application_id { id: 1 cluster_timestamp: 1515923115995 } attemptId: 1 } nodeId { host: "h1" port: 1234 } appSubmitter: "user" keyId: -1458844128
2018-01-14 09:45:16,174 DEBUG [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(556)) - Processing container_1515923115995_0001_01_000002 of type ACQUIRED
2018-01-14 09:45:16,175 INFO  [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(570)) - container_1515923115995_0001_01_000002 Container Transitioned from ALLOCATED to ACQUIRED
2018-01-14 09:45:16,175 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppRunningOnNodeEvent.EventType: APP_RUNNING_ON_NODE
2018-01-14 09:45:16,175 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,175 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(882)) - Processing event for application_1515923115995_0001 of type APP_RUNNING_ON_NODE
2018-01-14 09:45:16,176 DEBUG [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(556)) - Processing container_1515923115995_0001_01_000002 of type LAUNCHED
2018-01-14 09:45:16,176 INFO  [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(570)) - container_1515923115995_0001_01_000002 Container Transitioned from ACQUIRED to RUNNING
2018-01-14 09:45:16,176 DEBUG [main] security.UserGroupInformation (UserGroupInformation.java:logPrivilegedAction(1992)) - PrivilegedAction as:appattempt_1515923115995_0001_000001 (auth:SIMPLE) from:org.apache.hadoop.yarn.server.resourcemanager.MockAM.doAllocateAs(MockAM.java:290)
2018-01-14 09:45:16,177 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.event.RMAppAttemptStatusupdateEvent.EventType: STATUS_UPDATE
2018-01-14 09:45:16,177 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(903)) - Processing event for appattempt_1515923115995_0001_000001 of type STATUS_UPDATE
2018-01-14 09:45:16,177 INFO  [main] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:handleContainerUpdates(1170)) - Resource increase requests : [UpdateReq{containerId=container_1515923115995_0001_01_000002, containerVersion=0, targetExecType=null, targetCapability=<memory:8192, vCores:1>, updateType=INCREASE_RESOURCE, }]
2018-01-14 09:45:16,177 DEBUG [main] capacity.UsersManager (UsersManager.java:updateActiveUsersResourceUsage(948)) - User 'user' has become active. Hence move user to active list.Active users size = 1Non-active users size = 0Total Resource usage for active users=<memory:3072, vCores:2>.Total Resource usage for non-active users=<memory:0, vCores:0>
2018-01-14 09:45:16,178 DEBUG [main] capacity.UsersManager (UsersManager.java:activateApplication(852)) - User user added to activeUsers, currently: 1
2018-01-14 09:45:16,178 DEBUG [main] capacity.UsersManager (UsersManager.java:computeUserLimit(779)) - User limit computation for user,  in queue: default,  userLimitPercent=100,  userLimitFactor=1.0,  required=<memory:1024, vCores:1>,  consumed=<memory:3072, vCores:1>,  user-limit-resource=<memory:16384, vCores:1>,  queueCapacity=<memory:16384, vCores:16>,  qconsumed=<memory:3072, vCores:2>,  currentCapacity=<memory:16384, vCores:16>,  activeUsers=1.0,  clusterCapacity=<memory:16384, vCores:16>,  resourceByLabel=<memory:16384, vCores:16>,  usageratio=0.1875,  Partition=,  resourceUsed=<memory:4096, vCores:3>,  maxUserLimit=<memory:16384, vCores:16>,  userWeight=1.0
2018-01-14 09:45:16,178 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,178 DEBUG [main] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:nodeUpdate(1099)) - nodeUpdate: h1:1234 cluster capacity: <memory:16384, vCores:16>
2018-01-14 09:45:16,179 DEBUG [main] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:nodeUpdate(1132)) - Node being looked for scheduling h1:1234 availableResource: <memory:5120, vCores:6>
2018-01-14 09:45:16,180 DEBUG [main] capacity.CapacityScheduler (CapacityScheduler.java:allocateContainerOnSingleNode(1411)) - Trying to schedule on node: h1, available: <memory:5120, vCores:6>
2018-01-14 09:45:16,180 DEBUG [main] capacity.ParentQueue (ParentQueue.java:assignContainers(586)) - Trying to assign containers to child-queue of root
2018-01-14 09:45:16,180 DEBUG [main] capacity.AbstractCSQueue (AbstractCSQueue.java:canAssignToThisQueue(904)) - Check assign to queue: root nodePartition: , usedResources: <memory:3072, vCores:2>, clusterResources: <memory:16384, vCores:16>, currentUsedCapacity: 0.1875, max-capacity: 1.0
2018-01-14 09:45:16,181 DEBUG [main] capacity.ParentQueue (ParentQueue.java:printChildQueues(833)) - printChildQueues - queue: root child-queues: root.defaultusedCapacity=(0.1875),  label=(*)
2018-01-14 09:45:16,181 DEBUG [main] capacity.ParentQueue (ParentQueue.java:assignContainersToChildQueues(775)) - Trying to assign to queue: root.default stats: default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:3072, vCores:2>, usedCapacity=0.1875, absoluteUsedCapacity=0.1875, numApps=1, numContainers=2, effectiveMinResource=<memory:16384, vCores:16> , effectiveMaxResource=<memory:16384, vCores:16>
2018-01-14 09:45:16,181 DEBUG [main] capacity.LeafQueue (LeafQueue.java:assignContainers(1040)) - assignContainers: partition= #applications=1
2018-01-14 09:45:16,181 DEBUG [main] capacity.AbstractCSQueue (AbstractCSQueue.java:canAssignToThisQueue(904)) - Check assign to queue: default nodePartition: , usedResources: <memory:3072, vCores:2>, clusterResources: <memory:16384, vCores:16>, currentUsedCapacity: 0.1875, max-capacity: 1.0
2018-01-14 09:45:16,181 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,182 DEBUG [main] capacity.LeafQueue (LeafQueue.java:computeUserLimitAndSetHeadroom(1445)) - Headroom calculation for user user:  userLimit=<memory:16384, vCores:1> queueMaxAvailRes=<memory:16384, vCores:1> consumed=<memory:3072, vCores:2> partition=
2018-01-14 09:45:16,182 DEBUG [main] fica.FiCaSchedulerApp (FiCaSchedulerApp.java:assignContainers(863)) - pre-assignContainers for application application_1515923115995_0001
2018-01-14 09:45:16,182 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,182 DEBUG [main] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:showRequests(636)) - showRequests: application=application_1515923115995_0001 headRoom=<memory:13312, vCores:14> currentConsumption=3072
2018-01-14 09:45:16,182 DEBUG [main] placement.LocalityAppPlacementAllocator (LocalityAppPlacementAllocator.java:showRequests(408)) - 	Request={AllocationRequestId: -1, Priority: 1, Capability: <memory:6144, vCores:0>, # Containers: 1, Location: /default-rack, Relax Locality: false, Execution Type Request: {Execution Type: GUARANTEED, Enforce Execution Type: true}, Node Label Expression: , Resource Profile: null}
2018-01-14 09:45:16,182 DEBUG [main] placement.LocalityAppPlacementAllocator (LocalityAppPlacementAllocator.java:showRequests(408)) - 	Request={AllocationRequestId: -1, Priority: 1, Capability: <memory:6144, vCores:0>, # Containers: 1, Location: h1, Relax Locality: false, Execution Type Request: {Execution Type: GUARANTEED, Enforce Execution Type: true}, Node Label Expression: , Resource Profile: null}
2018-01-14 09:45:16,182 DEBUG [main] placement.LocalityAppPlacementAllocator (LocalityAppPlacementAllocator.java:showRequests(408)) - 	Request={AllocationRequestId: -1, Priority: 1, Capability: <memory:6144, vCores:0>, # Containers: 1, Location: *, Relax Locality: false, Execution Type Request: {Execution Type: GUARANTEED, Enforce Execution Type: true}, Node Label Expression: , Resource Profile: null}
2018-01-14 09:45:16,183 DEBUG [main] allocator.RegularContainerAllocator (RegularContainerAllocator.java:assignContainer(497)) - assignContainers: node=h1 application=application_1515923115995_0001 priority=1 pendingAsk=<per-allocation-resource=<memory:6144, vCores:0>, isGuaranteedEnforced=true,repeat=1> type=NODE_LOCAL
2018-01-14 09:45:16,183 DEBUG [main] allocator.RegularContainerAllocator (RegularContainerAllocator.java:doAllocation(757)) - Resetting scheduling opportunities
2018-01-14 09:45:16,183 INFO  [main] allocator.AbstractContainerAllocator (AbstractContainerAllocator.java:getCSAssignmentFromAllocateResult(97)) - Reserved container  application=application_1515923115995_0001 resource=<memory:6144, vCores:0> queue=org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.allocator.RegularContainerAllocator@1fa59bc3 cluster=<memory:16384, vCores:16>
2018-01-14 09:45:16,183 DEBUG [main] capacity.LeafQueue (LeafQueue.java:assignContainers(1148)) - post-assignContainers for application application_1515923115995_0001
2018-01-14 09:45:16,183 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,184 DEBUG [main] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:showRequests(636)) - showRequests: application=application_1515923115995_0001 headRoom=<memory:13312, vCores:14> currentConsumption=3072
2018-01-14 09:45:16,184 DEBUG [main] placement.LocalityAppPlacementAllocator (LocalityAppPlacementAllocator.java:showRequests(408)) - 	Request={AllocationRequestId: -1, Priority: 1, Capability: <memory:6144, vCores:0>, # Containers: 1, Location: /default-rack, Relax Locality: false, Execution Type Request: {Execution Type: GUARANTEED, Enforce Execution Type: true}, Node Label Expression: , Resource Profile: null}
2018-01-14 09:45:16,184 DEBUG [main] placement.LocalityAppPlacementAllocator (LocalityAppPlacementAllocator.java:showRequests(408)) - 	Request={AllocationRequestId: -1, Priority: 1, Capability: <memory:6144, vCores:0>, # Containers: 1, Location: h1, Relax Locality: false, Execution Type Request: {Execution Type: GUARANTEED, Enforce Execution Type: true}, Node Label Expression: , Resource Profile: null}
2018-01-14 09:45:16,184 DEBUG [main] placement.LocalityAppPlacementAllocator (LocalityAppPlacementAllocator.java:showRequests(408)) - 	Request={AllocationRequestId: -1, Priority: 1, Capability: <memory:6144, vCores:0>, # Containers: 1, Location: *, Relax Locality: false, Execution Type Request: {Execution Type: GUARANTEED, Enforce Execution Type: true}, Node Label Expression: , Resource Profile: null}
2018-01-14 09:45:16,193 DEBUG [main] capacity.ParentQueue (ParentQueue.java:assignContainersToChildQueues(787)) - Assigned to queue: root.default stats: default: capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:3072, vCores:2>, usedCapacity=0.1875, absoluteUsedCapacity=0.1875, numApps=1, numContainers=2, effectiveMinResource=<memory:16384, vCores:16> , effectiveMaxResource=<memory:16384, vCores:16> --> <memory:6144, vCores:0>, NODE_LOCAL
2018-01-14 09:45:16,196 INFO  [main] capacity.ParentQueue (ParentQueue.java:assignContainers(669)) - assignedContainer queue=root usedCapacity=0.1875 absoluteUsedCapacity=0.1875 used=<memory:3072, vCores:2> cluster=<memory:16384, vCores:16>
2018-01-14 09:45:16,196 DEBUG [main] capacity.ParentQueue (ParentQueue.java:assignContainers(675)) - ParentQ=root assignedSoFarInThisIteration=<memory:6144, vCores:0> usedCapacity=0.1875 absoluteUsedCapacity=0.1875
2018-01-14 09:45:16,197 DEBUG [main] capacity.CapacityScheduler (CapacityScheduler.java:tryCommit(2598)) - Try to commit allocation proposal=New org.apache.hadoop.yarn.server.resourcemanager.scheduler.common.ResourceCommitRequest:
	 RESERVED=[(Application=appattempt_1515923115995_0001_000001; Node=h1:1234; Resource=<memory:6144, vCores:0>)]
2018-01-14 09:45:16,197 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,197 DEBUG [main] capacity.LeafQueue (LeafQueue.java:computeUserLimitAndSetHeadroom(1445)) - Headroom calculation for user user:  userLimit=<memory:16384, vCores:1> queueMaxAvailRes=<memory:16384, vCores:1> consumed=<memory:3072, vCores:2> partition=
2018-01-14 09:45:16,198 DEBUG [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(556)) - Processing container_1515923115995_0001_01_000003 of type RESERVED
2018-01-14 09:45:16,198 INFO  [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(570)) - container_1515923115995_0001_01_000003 Container Transitioned from NEW to RESERVED
2018-01-14 09:45:16,199 DEBUG [main] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:commonReserve(540)) - Application attempt appattempt_1515923115995_0001_000001 reserved container container_1515923115995_0001_01_000003 on node host: h1:1234 #guaranteed containers=2 #opportunistic containers=0 available=<memory:5120, vCores:6> used by guaranteed containers=<memory:3072, vCores:2> used by opportunistic containers=<memory:0, vCores:0>. This attempt currently has 1 reserved containers at priority 1; currentReservation <memory:6144, vCores:0>
2018-01-14 09:45:16,199 DEBUG [main] fica.FiCaSchedulerNode (FiCaSchedulerNode.java:reserveResource(92)) - Reserved container container_1515923115995_0001_01_000003 on node host: h1:1234 #guaranteed containers=2 #opportunistic containers=0 available=<memory:5120, vCores:6> used by guaranteed containers=<memory:3072, vCores:2> used by opportunistic containers=<memory:0, vCores:0> for application attempt appattempt_1515923115995_0001_000001
2018-01-14 09:45:16,200 DEBUG [main] capacity.UsersManager (UsersManager.java:updateResourceUsagePerUser(1071)) - User resource is updated.Total Resource usage for active users=<memory:9216, vCores:2>.Total Resource usage for non-active users=<memory:0, vCores:0>
2018-01-14 09:45:16,200 DEBUG [main] capacity.UsersManager (UsersManager.java:computeUserLimit(779)) - User limit computation for user,  in queue: default,  userLimitPercent=100,  userLimitFactor=1.0,  required=<memory:1024, vCores:1>,  consumed=<memory:9216, vCores:1>,  user-limit-resource=<memory:16384, vCores:1>,  queueCapacity=<memory:16384, vCores:16>,  qconsumed=<memory:9216, vCores:2>,  currentCapacity=<memory:16384, vCores:16>,  activeUsers=1.0,  clusterCapacity=<memory:16384, vCores:16>,  resourceByLabel=<memory:16384, vCores:16>,  usageratio=0.5625,  Partition=,  resourceUsed=<memory:10240, vCores:3>,  maxUserLimit=<memory:16384, vCores:16>,  userWeight=1.0
2018-01-14 09:45:16,200 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,201 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,201 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,201 DEBUG [main] capacity.LeafQueue (LeafQueue.java:allocateResource(1712)) - default user=user used=<memory:9216, vCores:2> numContainers=3 headroom = <memory:7168, vCores:1> user-resources=<memory:9216, vCores:2>
2018-01-14 09:45:16,202 INFO  [main] capacity.ParentQueue (ParentQueue.java:apply(1320)) - assignedContainer queue=root usedCapacity=0.5625 absoluteUsedCapacity=0.5625 used=<memory:9216, vCores:2> cluster=<memory:16384, vCores:16>
2018-01-14 09:45:16,202 INFO  [main] capacity.CapacityScheduler (CapacityScheduler.java:tryCommit(2609)) - Allocation proposal accepted
2018-01-14 09:45:16,203 INFO  [main] capacity.CapacityScheduler (CapacityScheduler.java:doneApplicationAttempt(953)) - Application Attempt appattempt_1515923115995_0001_000001 is done. finalState=KILLED
2018-01-14 09:45:16,205 DEBUG [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(556)) - Processing container_1515923115995_0001_01_000001 of type KILL
2018-01-14 09:45:16,205 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmnode.RMNodeCleanContainerEvent.EventType: CLEANUP_CONTAINER
2018-01-14 09:45:16,206 DEBUG [AsyncDispatcher event handler] rmnode.RMNodeImpl (RMNodeImpl.java:handle(675)) - Processing h1:1234 of type CLEANUP_CONTAINER
2018-01-14 09:45:16,205 INFO  [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(570)) - container_1515923115995_0001_01_000001 Container Transitioned from ACQUIRED to KILLED
2018-01-14 09:45:16,206 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.event.RMAppAttemptContainerFinishedEvent.EventType: CONTAINER_FINISHED
2018-01-14 09:45:16,207 INFO  [main] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(200)) - USER=user	OPERATION=AM Released Container	TARGET=SchedulerApp	RESULT=SUCCESS	APPID=application_1515923115995_0001	CONTAINERID=container_1515923115995_0001_01_000001	RESOURCE=<memory:1024, vCores:1>
2018-01-14 09:45:16,207 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(903)) - Processing event for appattempt_1515923115995_0001_000001 of type CONTAINER_FINISHED
2018-01-14 09:45:16,207 DEBUG [main] scheduler.SchedulerNode (SchedulerNode.java:releaseContainer(369)) - Released GUARANTEED container container_1515923115995_0001_01_000001 of capacity <memory:1024, vCores:1> on node (host: h1:1234 #guaranteed containers=1 #opportunistic containers=0 available=<memory:6144, vCores:7> used by guaranteed containers=<memory:2048, vCores:1> used by opportunistic containers=<memory:0, vCores:0>), release resources=true
2018-01-14 09:45:16,213 INFO  [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:rememberTargetTransitionsAndStoreState(1372)) - Updating application attempt appattempt_1515923115995_0001_000001 with final state: FAILED, and exit status: -100
2018-01-14 09:45:16,213 DEBUG [main] capacity.UsersManager (UsersManager.java:updateResourceUsagePerUser(1071)) - User resource is updated.Total Resource usage for active users=<memory:8192, vCores:1>.Total Resource usage for non-active users=<memory:0, vCores:0>
2018-01-14 09:45:16,214 DEBUG [main] capacity.UsersManager (UsersManager.java:computeUserLimit(779)) - User limit computation for user,  in queue: default,  userLimitPercent=100,  userLimitFactor=1.0,  required=<memory:1024, vCores:1>,  consumed=<memory:8192, vCores:1>,  user-limit-resource=<memory:16384, vCores:1>,  queueCapacity=<memory:16384, vCores:16>,  qconsumed=<memory:8192, vCores:1>,  currentCapacity=<memory:16384, vCores:16>,  activeUsers=1.0,  clusterCapacity=<memory:16384, vCores:16>,  resourceByLabel=<memory:16384, vCores:16>,  usageratio=0.5,  Partition=,  resourceUsed=<memory:9216, vCores:2>,  maxUserLimit=<memory:16384, vCores:16>,  userWeight=1.0
2018-01-14 09:45:16,214 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,214 DEBUG [main] capacity.LeafQueue (LeafQueue.java:releaseResource(1752)) - default used=<memory:8192, vCores:1> numContainers=2 user=user user-resources=<memory:8192, vCores:1>
2018-01-14 09:45:16,214 DEBUG [AsyncDispatcher event handler] recovery.RMStateStore (RMStateStore.java:handleStoreEvent(1105)) - Processing event of type UPDATE_APP_ATTEMPT
2018-01-14 09:45:16,214 DEBUG [main] capacity.ParentQueue (ParentQueue.java:internalReleaseResource(846)) - completedContainer root: numChildQueue= 1, capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:8192, vCores:1>usedCapacity=0.5, numApps=1, numContainers=2, cluster=<memory:16384, vCores:16>
2018-01-14 09:45:16,215 DEBUG [AsyncDispatcher event handler] recovery.RMStateStore (RMStateStore.java:transition(356)) - Updating info for attempt: appattempt_1515923115995_0001_000001
2018-01-14 09:45:16,215 DEBUG [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(556)) - Processing container_1515923115995_0001_01_000002 of type KILL
2018-01-14 09:45:16,215 INFO  [main] rmcontainer.RMContainerImpl (RMContainerImpl.java:handle(570)) - container_1515923115995_0001_01_000002 Container Transitioned from RUNNING to KILLED
2018-01-14 09:45:16,215 INFO  [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(920)) - appattempt_1515923115995_0001_000001 State change from RUNNING to FINAL_SAVING on event = CONTAINER_FINISHED
2018-01-14 09:45:16,215 INFO  [main] resourcemanager.RMAuditLogger (RMAuditLogger.java:logSuccess(200)) - USER=user	OPERATION=AM Released Container	TARGET=SchedulerApp	RESULT=SUCCESS	APPID=application_1515923115995_0001	CONTAINERID=container_1515923115995_0001_01_000002	RESOURCE=<memory:2048, vCores:1>
2018-01-14 09:45:16,215 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmnode.RMNodeFinishedContainersPulledByAMEvent.EventType: FINISHED_CONTAINERS_PULLED_BY_AM
2018-01-14 09:45:16,216 DEBUG [main] scheduler.SchedulerNode (SchedulerNode.java:releaseContainer(369)) - Released GUARANTEED container container_1515923115995_0001_01_000002 of capacity <memory:2048, vCores:1> on node (host: h1:1234 #guaranteed containers=0 #opportunistic containers=0 available=<memory:8192, vCores:8> used by guaranteed containers=<memory:0, vCores:0> used by opportunistic containers=<memory:0, vCores:0>), release resources=true
2018-01-14 09:45:16,216 DEBUG [AsyncDispatcher event handler] rmnode.RMNodeImpl (RMNodeImpl.java:handle(675)) - Processing h1:1234 of type FINISHED_CONTAINERS_PULLED_BY_AM
2018-01-14 09:45:16,216 DEBUG [main] capacity.UsersManager (UsersManager.java:updateResourceUsagePerUser(1071)) - User resource is updated.Total Resource usage for active users=<memory:6144, vCores:0>.Total Resource usage for non-active users=<memory:0, vCores:0>
2018-01-14 09:45:16,216 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptEvent.EventType: ATTEMPT_UPDATE_SAVED
2018-01-14 09:45:16,223 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(903)) - Processing event for appattempt_1515923115995_0001_000001 of type ATTEMPT_UPDATE_SAVED
2018-01-14 09:45:16,216 DEBUG [main] capacity.UsersManager (UsersManager.java:computeUserLimit(779)) - User limit computation for user,  in queue: default,  userLimitPercent=100,  userLimitFactor=1.0,  required=<memory:1024, vCores:1>,  consumed=<memory:6144, vCores:1>,  user-limit-resource=<memory:16384, vCores:1>,  queueCapacity=<memory:16384, vCores:16>,  qconsumed=<memory:6144, vCores:0>,  currentCapacity=<memory:16384, vCores:16>,  activeUsers=1.0,  clusterCapacity=<memory:16384, vCores:16>,  resourceByLabel=<memory:16384, vCores:16>,  usageratio=0.375,  Partition=,  resourceUsed=<memory:7168, vCores:1>,  maxUserLimit=<memory:16384, vCores:16>,  userWeight=1.0
2018-01-14 09:45:16,223 INFO  [AsyncDispatcher event handler] resourcemanager.ApplicationMasterService (ApplicationMasterService.java:unregisterAttempt(451)) - Unregistering app attempt : appattempt_1515923115995_0001_000001
2018-01-14 09:45:16,223 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,223 DEBUG [main] capacity.LeafQueue (LeafQueue.java:releaseResource(1752)) - default used=<memory:6144, vCores:0> numContainers=1 user=user user-resources=<memory:6144, vCores:0>
2018-01-14 09:45:16,224 INFO  [AsyncDispatcher event handler] security.AMRMTokenSecretManager (AMRMTokenSecretManager.java:applicationMasterFinished(124)) - Application finished, removing password for appattempt_1515923115995_0001_000001
2018-01-14 09:45:16,224 DEBUG [main] capacity.ParentQueue (ParentQueue.java:internalReleaseResource(846)) - completedContainer root: numChildQueue= 1, capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:6144, vCores:0>usedCapacity=0.375, numApps=1, numContainers=1, cluster=<memory:16384, vCores:16>
2018-01-14 09:45:16,224 INFO  [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(920)) - appattempt_1515923115995_0001_000001 State change from FINAL_SAVING to FAILED on event = ATTEMPT_UPDATE_SAVED
2018-01-14 09:45:16,224 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmnode.RMNodeCleanContainerEvent.EventType: CLEANUP_CONTAINER
2018-01-14 09:45:16,224 INFO  [main] fica.FiCaSchedulerApp (FiCaSchedulerApp.java:internalUnreserve(629)) - Application application_1515923115995_0001 unreserved  on node host: h1:1234 #guaranteed containers=0 #opportunistic containers=0 available=<memory:8192, vCores:8> used by guaranteed containers=<memory:0, vCores:0> used by opportunistic containers=<memory:0, vCores:0>, currently has 0 at priority 1; currentReservation <memory:0, vCores:0> on node-label=
2018-01-14 09:45:16,224 DEBUG [AsyncDispatcher event handler] rmnode.RMNodeImpl (RMNodeImpl.java:handle(675)) - Processing h1:1234 of type CLEANUP_CONTAINER
2018-01-14 09:45:16,225 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.event.RMAppAttemptContainerFinishedEvent.EventType: CONTAINER_FINISHED
2018-01-14 09:45:16,225 DEBUG [main] capacity.UsersManager (UsersManager.java:updateResourceUsagePerUser(1071)) - User resource is updated.Total Resource usage for active users=<memory:0, vCores:0>.Total Resource usage for non-active users=<memory:0, vCores:0>
2018-01-14 09:45:16,225 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(903)) - Processing event for appattempt_1515923115995_0001_000001 of type CONTAINER_FINISHED
2018-01-14 09:45:16,225 DEBUG [main] capacity.UsersManager (UsersManager.java:computeUserLimit(779)) - User limit computation for user,  in queue: default,  userLimitPercent=100,  userLimitFactor=1.0,  required=<memory:1024, vCores:1>,  consumed=<memory:0, vCores:0>,  user-limit-resource=<memory:16384, vCores:1>,  queueCapacity=<memory:16384, vCores:16>,  qconsumed=<memory:0, vCores:0>,  currentCapacity=<memory:16384, vCores:16>,  activeUsers=1.0,  clusterCapacity=<memory:16384, vCores:16>,  resourceByLabel=<memory:16384, vCores:16>,  usageratio=0.0,  Partition=,  resourceUsed=<memory:1024, vCores:1>,  maxUserLimit=<memory:16384, vCores:16>,  userWeight=1.0
2018-01-14 09:45:16,225 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.RMAppFailedAttemptEvent.EventType: ATTEMPT_FAILED
2018-01-14 09:45:16,226 DEBUG [main] capacity.UsersManager (UsersManager.java:getComputedResourceLimitForActiveUsers(523)) - userLimit is fetched. userLimit=<memory:16384, vCores:1>, userSpecificUserLimit=<memory:16384, vCores:1>, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY, partition=
2018-01-14 09:45:16,226 DEBUG [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(882)) - Processing event for application_1515923115995_0001 of type ATTEMPT_FAILED
2018-01-14 09:45:16,226 DEBUG [main] capacity.LeafQueue (LeafQueue.java:releaseResource(1752)) - default used=<memory:0, vCores:0> numContainers=0 user=user user-resources=<memory:0, vCores:0>
2018-01-14 09:45:16,227 INFO  [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:transition(1496)) - The number of failed attempts is 0. The max attempts is 2
2018-01-14 09:45:16,227 DEBUG [main] capacity.ParentQueue (ParentQueue.java:internalReleaseResource(846)) - completedContainer root: numChildQueue= 1, capacity=1.0, absoluteCapacity=1.0, usedResources=<memory:0, vCores:0>usedCapacity=0.0, numApps=1, numContainers=0, cluster=<memory:16384, vCores:16>
2018-01-14 09:45:16,227 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:<init>(537)) - yarn.app.attempt.diagnostics.limit.kc : 64
2018-01-14 09:45:16,227 INFO  [AsyncDispatcher event handler] rmapp.RMAppImpl (RMAppImpl.java:handle(899)) - application_1515923115995_0001 State change from RUNNING to ACCEPTED on event = ATTEMPT_FAILED
2018-01-14 09:45:16,227 INFO  [main] scheduler.AppSchedulingInfo (AppSchedulingInfo.java:clearRequests(151)) - Application application_1515923115995_0001 requests cleared
2018-01-14 09:45:16,227 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.scheduler.event.AppAttemptRemovedSchedulerEvent.EventType: APP_ATTEMPT_REMOVED
2018-01-14 09:45:16,228 INFO  [main] capacity.LeafQueue (LeafQueue.java:removeApplicationAttempt(973)) - Application removed - appId: application_1515923115995_0001 user: user queue: default #user-pending-applications: 0 #user-active-applications: 0 #queue-pending-applications: 0 #queue-active-applications: 0
2018-01-14 09:45:16,229 INFO  [AsyncDispatcher event handler] capacity.CapacityScheduler (CapacityScheduler.java:doneApplicationAttempt(953)) - Application Attempt appattempt_1515923115995_0001_000001 is done. finalState=FAILED
2018-01-14 09:45:16,229 INFO  [AsyncDispatcher event handler] scheduler.AppSchedulingInfo (AppSchedulingInfo.java:clearRequests(151)) - Application application_1515923115995_0001 requests cleared
2018-01-14 09:45:16,229 INFO  [AsyncDispatcher event handler] capacity.LeafQueue (LeafQueue.java:removeApplicationAttempt(973)) - Application removed - appId: application_1515923115995_0001 user: user queue: default #user-pending-applications: -1 #user-active-applications: 0 #queue-pending-applications: 0 #queue-active-applications: 0
2018-01-14 09:45:16,229 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.amlauncher.AMLauncherEvent.EventType: CLEANUP
2018-01-14 09:45:16,229 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppStartAttemptEvent.EventType: START
2018-01-14 09:45:16,229 DEBUG [main] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:nodeUpdate(1099)) - nodeUpdate: h1:1234 cluster capacity: <memory:16384, vCores:16>
2018-01-14 09:45:16,229 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(903)) - Processing event for appattempt_1515923115995_0001_000002 of type START
2018-01-14 09:45:16,230 DEBUG [main] scheduler.AbstractYarnScheduler (AbstractYarnScheduler.java:nodeUpdate(1132)) - Node being looked for scheduling h1:1234 availableResource: <memory:8192, vCores:8>
2018-01-14 09:45:16,230 INFO  [AsyncDispatcher event handler] resourcemanager.ApplicationMasterService (ApplicationMasterService.java:registerAppAttempt(434)) - Registering app attempt : appattempt_1515923115995_0001_000002
2018-01-14 09:45:16,230 DEBUG [main] capacity.CapacityScheduler (CapacityScheduler.java:allocateContainerOnSingleNode(1411)) - Trying to schedule on node: h1, available: <memory:8192, vCores:8>
2018-01-14 09:45:16,230 INFO  [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(920)) - appattempt_1515923115995_0001_000002 State change from NEW to SUBMITTED on event = START
2018-01-14 09:45:16,230 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.scheduler.event.AppAttemptAddedSchedulerEvent.EventType: APP_ATTEMPT_ADDED
2018-01-14 09:45:16,230 DEBUG [main] capacity.ParentQueue (ParentQueue.java:assignContainers(564)) - Skip this queue=root, because it doesn't need more resource, schedulingMode=RESPECT_PARTITION_EXCLUSIVITY node-partition=
2018-01-14 09:45:16,231 DEBUG [AsyncDispatcher event handler] capacity.LeafQueue (LeafQueue.java:activateApplications(803)) - application application_1515923115995_0001 AMResource <memory:1024, vCores:1> maxAMResourcePerQueuePercent 0.1 amLimit <memory:2048, vCores:1> lastClusterResource <memory:16384, vCores:16> amIfStarted <memory:1024, vCores:1> AM node-partition name 
2018-01-14 09:45:16,232 INFO  [AsyncDispatcher event handler] capacity.LeafQueue (LeafQueue.java:activateApplications(881)) - Application application_1515923115995_0001 from user: user activated in queue: default
2018-01-14 09:45:16,232 INFO  [AsyncDispatcher event handler] capacity.LeafQueue (LeafQueue.java:addApplicationAttempt(911)) - Application added - appId: application_1515923115995_0001 user: user, leaf-queue: default #user-pending-applications: -1 #user-active-applications: 1 #queue-pending-applications: 0 #queue-active-applications: 1
2018-01-14 09:45:16,232 INFO  [AsyncDispatcher event handler] capacity.CapacityScheduler (CapacityScheduler.java:addApplicationAttempt(904)) - Added Application Attempt appattempt_1515923115995_0001_000002 to scheduler from user user in queue default
2018-01-14 09:45:16,232 DEBUG [AsyncDispatcher event handler] event.AsyncDispatcher (AsyncDispatcher.java:dispatch(188)) - Dispatching the event org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptEvent.EventType: ATTEMPT_ADDED
2018-01-14 09:45:16,232 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(903)) - Processing event for appattempt_1515923115995_0001_000002 of type ATTEMPT_ADDED
2018-01-14 09:45:16,232 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:transition(1105)) - Setting node count for blacklist to 2
2018-01-14 09:45:16,232 DEBUG [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:transition(1112)) - Using blacklist for AM: additions([]) and removals([])
2018-01-14 09:45:16,232 DEBUG [AsyncDispatcher event handler] capacity.CapacityScheduler (CapacityScheduler.java:allocate(1053)) - allocate: pre-update appattempt_1515923115995_0001_000002 ask size =1
2018-01-14 09:45:16,233 DEBUG [AsyncDispatcher event handler] capacity.CapacityScheduler (CapacityScheduler.java:allocate(1065)) - allocate: post-update
2018-01-14 09:45:16,233 DEBUG [AsyncDispatcher event handler] scheduler.SchedulerApplicationAttempt (SchedulerApplicationAttempt.java:showRequests(636)) - showRequests: application=application_1515923115995_0001 headRoom=<memory:0, vCores:0> currentConsumption=0
2018-01-14 09:45:16,233 DEBUG [AsyncDispatcher event handler] placement.LocalityAppPlacementAllocator (LocalityAppPlacementAllocator.java:showRequests(408)) - 	Request={AllocationRequestId: -1, Priority: 0, Capability: <memory:1024, vCores:1>, # Containers: 1, Location: *, Relax Locality: true, Execution Type Request: {Execution Type: GUARANTEED, Enforce Execution Type: true}, Node Label Expression: , Resource Profile: null}
2018-01-14 09:45:16,233 INFO  [AsyncDispatcher event handler] attempt.RMAppAttemptImpl (RMAppAttemptImpl.java:handle(920)) - appattempt_1515923115995_0001_000002 State change from SUBMITTED to SCHEDULED on event = ATTEMPT_ADDED
{code}

> TestContainerResizing.testIncreaseContainerUnreservedWhenApplicationCompleted failed
> ------------------------------------------------------------------------------------
>
>                 Key: YARN-7748
>                 URL: https://issues.apache.org/jira/browse/YARN-7748
>             Project: Hadoop YARN
>          Issue Type: Bug
>          Components: capacityscheduler
>    Affects Versions: 3.0.0
>            Reporter: Haibo Chen
>
> TestContainerResizing.testIncreaseContainerUnreservedWhenApplicationCompleted
> Failing for the past 1 build (Since Failed#19244 )
> Took 0.4 sec.
> *Error Message*
> expected null, but was:<org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.UsersManager$User@6193932a>
> *Stacktrace*
> {code}
> java.lang.AssertionError: expected null, but was:<org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.UsersManager$User@6193932a>
> 	at org.junit.Assert.fail(Assert.java:88)
> 	at org.junit.Assert.failNotNull(Assert.java:664)
> 	at org.junit.Assert.assertNull(Assert.java:646)
> 	at org.junit.Assert.assertNull(Assert.java:656)
> 	at org.apache.hadoop.yarn.server.resourcemanager.scheduler.capacity.TestContainerResizing.testIncreaseContainerUnreservedWhenApplicationCompleted(TestContainerResizing.java:826)
> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 	at java.lang.reflect.Method.invoke(Method.java:498)
> 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> 	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> 	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:369)
> 	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:275)
> 	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:239)
> 	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:160)
> 	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:373)
> 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:334)
> 	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:119)
> 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:407)
> {code}



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

---------------------------------------------------------------------
To unsubscribe, e-mail: yarn-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: yarn-issues-help@hadoop.apache.org


Mime
View raw message