[ 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-unsubscr...@hadoop.apache.org For additional commands, e-mail: yarn-issues-h...@hadoop.apache.org