Class cascading.function.FunctionPlatformTest

2016-05-17 22:35:07,254 INFO  platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-17 22:35:07,276 INFO  platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.function.FunctionPlatformTest, with platform: hadoop2-tez
2016-05-17 22:35:07,301 INFO  tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-05-17 22:35:07,692 WARN  util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2016-05-17 22:35:08,065 INFO  platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides: 
2016-05-17 22:35:08,117 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 1, with capacity: 2
2016-05-17 22:35:08,117 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 202, total: 223, max: 672
2016-05-17 22:35:08,118 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(111)) - total mem is 33% of max mem, to better utilize unused memory consider increasing the cache size
2016-05-17 22:35:08,118 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 3, with capacity: 2
2016-05-17 22:35:08,118 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 202, total: 223, max: 672
2016-05-17 22:35:08,119 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(111)) - total mem is 33% of max mem, to better utilize unused memory consider increasing the cache size
2016-05-17 22:35:08,353 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-17 22:35:08,355 INFO  planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-17 22:35:08,479 INFO  property.AppProps (AppProps.java:getAppID(177)) - using app.id: 9191BB695B76452D8D44DD7703529ED4
2016-05-17 22:35:08,647 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.063
2016-05-17 22:35:08,659 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.076
2016-05-17 22:35:08,661 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-17 22:35:08,662 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-17 22:35:08,663 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-17 22:35:08,812 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt
2016-05-17 22:35:08,815 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter
2016-05-17 22:35:09,037 INFO  util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-17 22:35:09,039 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] starting
2016-05-17 22:35:09,039 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter]  source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-05-17 22:35:09,040 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter]  sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"]
2016-05-17 22:35:09,040 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter]  parallel execution of steps is enabled: false
2016-05-17 22:35:09,040 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter]  executing total steps: 1
2016-05-17 22:35:09,040 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter]  allocating management threads: 1
2016-05-17 22:35:09,041 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] starting step: (1/1) ...tFieldFormatter/formatter
2016-05-17 22:35:09,041 WARN  flow.Flow (BaseFlow.java:logWarn(1516)) - [formatter] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-05-17 22:35:09,071 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] tez session mode enabled: true
2016-05-17 22:35:09,258 INFO  client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-05-17 22:35:09,267 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-05-17 22:35:09,267 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-05-17 22:35:09,329 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC/.tez/application_1463524509266_0001 doesn't exist and is created
2016-05-17 22:35:09,407 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-05-17 22:35:09,407 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 22:35:09,408 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC/.tez/application_1463524509266_0001
2016-05-17 22:35:09,438 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1463524509266_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-05-17 22:35:09,477 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-05-17 22:35:09,492 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-05-17 22:35:09,508 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-17 22:35:09,508 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-17 22:35:09,508 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 22:35:09,518 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-05-17 22:35:09,522 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-05-17 22:35:09,527 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC/.tez/application_1463524509266_0001/localmode-log-dir
2016-05-17 22:35:09,527 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC/.tez/application_1463524509266_0001/localmode-log-dir/history.txt.appattempt_1463524509266_0001_000000, maxErrors=10
2016-05-17 22:35:09,527 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-05-17 22:35:09,529 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463524509266_0001_000000, appSubmitTime=1463524509424, launchTime=1463524509437
2016-05-17 22:35:09,536 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-05-17 22:35:09,537 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-17 22:35:09,542 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-05-17 22:35:09,543 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-05-17 22:35:09,601 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:56826
2016-05-17 22:35:09,609 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-17 22:35:09,609 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-17 22:35:09,609 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 22:35:09,643 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-05-17 22:35:09,709 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-17 22:35:09,710 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-17 22:35:09,710 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 22:35:09,716 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-05-17 22:35:09,717 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463524509266_0001_000000, startTime=1463524509715
2016-05-17 22:35:09,717 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-05-17 22:35:09,810 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-17 22:35:09,829 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-05-17 22:35:09,829 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1463524509266_0001, dagName=[A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC] formatter/(1/1) ...tFieldFormatter/formatter
2016-05-17 22:35:10,061 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC] formatter/(1/1) ...tFieldFormatter/formatter
2016-05-17 22:35:10,171 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1463524509266_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC/.tez/application_1463524509266_0001/localmode-log-dir/dag_1463524509266_0001_1.dot
2016-05-17 22:35:10,175 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC/.tez/application_1463524509266_0001/localmode-log-dir/dag_1463524509266_0001_1-tez-dag.pb.txt
2016-05-17 22:35:10,303 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463524509266_0001_1
2016-05-17 22:35:10,303 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:10,303 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC] formatter/(1/1) ...tFieldFormatter/formatter
2016-05-17 22:35:10 Running Dag: dag_1463524509266_0001_1
2016-05-17 22:35:10,335 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-05-17 22:35:10,337 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463524509266_0001_1, submitTime=1463524510062
2016-05-17 22:35:10,369 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex E4BD5B40C2CE448C8B23F9582DA129BD
2016-05-17 22:35:10,371 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-17 22:35:10,373 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-05-17 22:35:10,373 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463524509266_0001_1, initTime=1463524510338
2016-05-17 22:35:10,374 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524509266_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-17 22:35:10,377 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-05-17 22:35:10,377 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:DAG_STARTED]: dagID=dag_1463524509266_0001_1, startTime=1463524510376
2016-05-17 22:35:10,378 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-05-17 22:35:10,379 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524509266_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-17 22:35:10,380 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: E4BD5B40C2CE448C8B23F9582DA129BD : {722B11C8C81A4B16A2B059BC0BCBEF54={InputName=722B11C8C81A4B16A2B059BC0BCBEF54}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-17 22:35:10,381 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 722B11C8C81A4B16A2B059BC0BCBEF54, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-17 22:35:10,381 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,388 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,388 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,389 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1463524509266_0001, dagName=[A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC] formatter/(1/1) ...tFieldFormatter/formatter
2016-05-17 22:35:10,390 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]. Starting root input initializers: 1
2016-05-17 22:35:10,404 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 722B11C8C81A4B16A2B059BC0BCBEF54 on vertex vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,412 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-17 22:35:10,425 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-05-17 22:35:10,426 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter] submitted tez dag to app master: application_1463524509266_0001, with dag id: dag_1463524509266_0001_1
2016-05-17 22:35:10,428 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 722B11C8C81A4B16A2B059BC0BCBEF54 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-05-17 22:35:10,429 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-05-17 22:35:10,430 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-05-17 22:35:10,479 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 522
2016-05-17 22:35:10,481 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 722B11C8C81A4B16A2B059BC0BCBEF54 on vertex vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,483 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 22:35:10,483 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {722B11C8C81A4B16A2B059BC0BCBEF54=forAllWorkUnits=true, update=[1]}
2016-05-17 22:35:10,497 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] parallelism set to 1
2016-05-17 22:35:10,497 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 22:35:10,507 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463524509266_0001_1_00, eventCount=1
2016-05-17 22:35:10,510 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,510 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=CE1C30B536E4494EA8EE833BDA55EAE6, vertexId=vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-17 22:35:10,514 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=CE1C30B536E4494EA8EE833BDA55EAE6, vertexId=vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,533 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=CE1C30B536E4494EA8EE833BDA55EAE6, vertexName=E4BD5B40C2CE448C8B23F9582DA129BD, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-17 22:35:10,542 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=CE1C30B536E4494EA8EE833BDA55EAE6, vertexId=vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,545 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 22:35:10,545 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:VERTEX_INITIALIZED]: vertexName=E4BD5B40C2CE448C8B23F9582DA129BD, vertexId=vertex_1463524509266_0001_1_00, initRequestedTime=1463524510379, initedTime=1463524510544, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-05-17 22:35:10,545 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] with distanceFromRoot: 0
2016-05-17 22:35:10,546 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-05-17 22:35:10,548 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in E4BD5B40C2CE448C8B23F9582DA129BD
2016-05-17 22:35:10,548 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,550 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 22:35:10,550 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463524509266_0001_1_00, startRequestedTime=1463524510546, startedTime=1463524510546
2016-05-17 22:35:10,550 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] transitioned from INITED to RUNNING due to event V_START
2016-05-17 22:35:10,572 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 22:35:10,572 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:TASK_STARTED]: vertexName=E4BD5B40C2CE448C8B23F9582DA129BD, taskId=task_1463524509266_0001_1_00_000000, scheduledTime=1463524510571, launchTime=1463524510571
2016-05-17 22:35:10,572 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524509266_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 22:35:10,574 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,576 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC] formatter/(1/1) ...tFieldFormatter/formatter, VertexName: E4BD5B40C2CE448C8B23F9582DA129BD, VertexParallelism: 1, TaskAttemptID:attempt_1463524509266_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=722B11C8C81A4B16A2B059BC0BCBEF54, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=CE1C30B536E4494EA8EE833BDA55EAE6, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 22:35:10,579 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524509266_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 22:35:10,579 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 22:35:10,619 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-05-17 22:35:10,622 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-05-17 22:35:10,622 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-05-17 22:35:10,627 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463524509266_0001_00_000001
2016-05-17 22:35:10,627 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524509266_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 22:35:10,636 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1463524509266_0001_00_000001
2016-05-17 22:35:10,636 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-05-17 22:35:10,641 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524509266_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 22:35:10,643 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 22:35:10,643 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463524509266_0001_00_000001, launchTime=1463524510642
2016-05-17 22:35:10,646 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463524509266_0001_00_000001
2016-05-17 22:35:10,649 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463524509266_0001_1_00_000000_0] to container: [container_1463524509266_0001_00_000001]
2016-05-17 22:35:10,650 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524509266_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 22:35:10,651 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463524509266_0001_00_000001 given task: attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,651 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463524509266_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,653 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463524509266_0001_1_00_000000_0] started. Is using containerId: [container_1463524509266_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-17 22:35:10 Starting to run new task attempt: attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,653 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,653 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:10,655 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 22:35:10,655 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 22:35:10,656 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 22:35:10,656 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 22:35:10,656 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=E4BD5B40C2CE448C8B23F9582DA129BD, taskAttemptId=attempt_1463524509266_0001_1_00_000000_0, startTime=1463524510651, containerId=container_1463524509266_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463524509266_0001_00_000001/teamcity, completedLogs=
2016-05-17 22:35:10,657 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524509266_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 22:35:10,658 INFO  counters.Limits (Limits.java:ensureInitialized(59)) - Counter limits initialized with parameters:  GROUP_NAME_MAX=128, MAX_GROUPS=500, COUNTER_NAME_MAX=64, MAX_COUNTERS=1200
2016-05-17 22:35:10,658 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 22:35:10,661 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524509266_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 22:35:10,681 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-05-17 22:35:10,681 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC] formatter/(1/1) ...tFieldFormatter/formatter, VertexName: E4BD5B40C2CE448C8B23F9582DA129BD, VertexParallelism: 1, TaskAttemptID:attempt_1463524509266_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=722B11C8C81A4B16A2B059BC0BCBEF54, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=CE1C30B536E4494EA8EE833BDA55EAE6, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 22:35:10,683 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 22:35:10,687 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,687 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 22:35:10,688 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:10,693 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463524509266_0001_1_00_000000_0 sent events: (0-1)
2016-05-17 22:35:10,694 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=722B11C8C81A4B16A2B059BC0BCBEF54, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-05-17 22:35:10,696 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 22:35:10,697 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:10,697 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 722B11C8C81A4B16A2B059BC0BCBEF54
2016-05-17 22:35:10,699 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=CE1C30B536E4494EA8EE833BDA55EAE6, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-05-17 22:35:10,703 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 722B11C8C81A4B16A2B059BC0BCBEF54
2016-05-17 22:35:10,703 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 22:35:10,704 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: CE1C30B536E4494EA8EE833BDA55EAE6
2016-05-17 22:35:10,704 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-05-17 22:35:10,704 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: CE1C30B536E4494EA8EE833BDA55EAE6
2016-05-17 22:35:10,723 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-05-17 22:35:10,724 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 722B11C8C81A4B16A2B059BC0BCBEF54
2016-05-17 22:35:10,724 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 722B11C8C81A4B16A2B059BC0BCBEF54
2016-05-17 22:35:10,737 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 22:35:10,756 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-05-17 22:35:10,756 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: CE1C30B536E4494EA8EE833BDA55EAE6
2016-05-17 22:35:10,756 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: E4BD5B40C2CE448C8B23F9582DA129BD, ordinal: 0
2016-05-17 22:35:10,757 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E4BD5B40C2CE448C8B23F9582DA129BD, mem on start (mb), free: 160, total: 223, max: 672
2016-05-17 22:35:10,758 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:10,758 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 22:35:10,758 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 22:35:10,759 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 22:35:10,760 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 22:35:10,766 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-05-17 22:35:10,767 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 22:35:10,767 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-05-17 22:35:10,767 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 22:35:10,767 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 22:35:10,768 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 2, TotalRequested: 0, TotalRequestedScaled: 0.0, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.00
2016-05-17 22:35:10,768 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 722B11C8C81A4B16A2B059BC0BCBEF54, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-05-17 22:35:10,768 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, CE1C30B536E4494EA8EE833BDA55EAE6, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-05-17 22:35:10,768 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 22:35:10,770 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 722B11C8C81A4B16A2B059BC0BCBEF54 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 22:35:10,770 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 722B11C8C81A4B16A2B059BC0BCBEF54
2016-05-17 22:35:10,770 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 22:35:10,770 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 722B11C8C81A4B16A2B059BC0BCBEF54
2016-05-17 22:35:10,770 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 22:35:10,771 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 22:35:10,772 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 22:35:10,774 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,775 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-05-17 22:35:10,783 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@634a36cd
2016-05-17 22:35:10,792 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@634a36cd
2016-05-17 22:35:10,794 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-05-17 22:35:10,794 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-05-17 22:35:10,813 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-05-17 22:35:10,824 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt"] streamed: true, id: 722B11C8C81A4B16A2B059BC0BCBEF54
2016-05-17 22:35:10,824 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"], id: CE1C30B536E4494EA8EE833BDA55EAE6
2016-05-17 22:35:10,825 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter"]
2016-05-17 22:35:10,829 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-05-17 22:35:10,829 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 22:35:10,832 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: E4BD5B40C2CE448C8B23F9582DA129BD, all 1 inputs ready in: 00:00:00.002
2016-05-17 22:35:10,844 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-05-17 22:35:10,844 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-05-17 22:35:10,845 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,846 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1463524509266_0001_1_00_000000_0 given a go for committing the task output.
2016-05-17 22:35:10,847 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,847 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E4BD5B40C2CE448C8B23F9582DA129BD, mem on close (mb), free: 154, total: 223, max: 672
2016-05-17 22:35:10 Completed running task attempt: attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,853 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463524509266_0001_1_00_000000_0, fatalErrorOccurred=false
2016-05-17 22:35:10,857 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 21 [[File System Counters FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=1088, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5][cascading.flow.SliceCounters Process_Begin_Time=1463524510832, Process_Duration=14, Process_End_Time=1463524510846, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=5, Tuples_Written=5]]
2016-05-17 22:35:10,858 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 22:35:10,860 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-05-17 22:35:10,861 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:10,861 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463524509266_0001_00_000001
2016-05-17 22:35:10,863 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=E4BD5B40C2CE448C8B23F9582DA129BD, taskAttemptId=attempt_1463524509266_0001_1_00_000000_0, startTime=1463524510651, finishTime=1463524510854, timeTaken=203, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=1088, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463524510832, Process_Duration=14, Process_End_Time=1463524510846, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-17 22:35:10,864 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524509266_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 22:35:10,864 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 22:35:10,866 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10,868 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 22:35:10,872 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:TASK_FINISHED]: vertexName=E4BD5B40C2CE448C8B23F9582DA129BD, taskId=task_1463524509266_0001_1_00_000000, startTime=1463524510651, finishTime=1463524510867, timeTaken=216, status=SUCCEEDED, successfulAttemptID=attempt_1463524509266_0001_1_00_000000_0, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=1088, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463524510832, Process_Duration=14, Process_End_Time=1463524510846, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-17 22:35:10,875 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524509266_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 22:35:10,876 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524509266_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 22:35:10,876 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] : 1
2016-05-17 22:35:10,877 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,911 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 22:35:10,920 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:VERTEX_FINISHED]: vertexName=E4BD5B40C2CE448C8B23F9582DA129BD, vertexId=vertex_1463524509266_0001_1_00, initRequestedTime=1463524510379, initedTime=1463524510544, startRequestedTime=1463524510546, startedTime=1463524510546, finishTime=1463524510877, timeTaken=331, status=SUCCEEDED, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=1088, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463524510832, Process_Duration=14, Process_End_Time=1463524510846, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5, vertexStats=firstTaskStartTime=1463524510651, firstTasksToStart=[ task_1463524509266_0001_1_00_000000 ], lastTaskFinishTime=1463524510854, lastTasksToFinish=[ task_1463524509266_0001_1_00_000000 ], minTaskDuration=203, maxTaskDuration=203, avgTaskDuration=203.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463524509266_0001_1_00_000000 ], longestDurationTasks=[ task_1463524509266_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 22:35:10,921 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 22:35:10,924 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 22:35:10,924 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463524509266_0001_00_000001, stoppedTime=1463524510924, exitStatus=0
2016-05-17 22:35:10,925 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524509266_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 22:35:10,925 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-05-17 22:35:10,926 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1463524509266_0001_1
2016-05-17 22:35:10,928 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463524509266_0001_1
2016-05-17 22:35:10,928 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: CE1C30B536E4494EA8EE833BDA55EAE6 for vertex: vertex_1463524509266_0001_1_00 [E4BD5B40C2CE448C8B23F9582DA129BD]
2016-05-17 22:35:10,935 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463524509266_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-17 22:35:10,936 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463524509266_0001_00_000001: 74 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 22:35:10,936 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463524509266_0001_00_000001, Exiting
2016-05-17 22:35:10,936 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463524509266_0001_00_000001
2016-05-17 22:35:10,936 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463524509266_0001_00_000001
2016-05-17 22:35:10,939 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463524509266_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 22:35:10,939 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463524509266_0001_00_000001 completed successfully
2016-05-17 22:35:10,947 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1463524509266_0001_1, queueSize=0
2016-05-17 22:35:10,947 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-05-17 22:35:10,949 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524509266_0001_1][Event:DAG_FINISHED]: dagId=dag_1463524509266_0001_1, startTime=1463524510376, finishTime=1463524510941, timeTaken=565, status=SUCCEEDED, diagnostics=, counters=Counters: 24, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=1088, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=233832448, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463524510832, Process_Duration=14, Process_End_Time=1463524510846, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-17 22:35:10,955 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1463524509266_0001_1 finished with state: SUCCEEDED
2016-05-17 22:35:10,955 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524509266_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-05-17 22:35:10,955 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1463524509266_0001_00_000001
2016-05-17 22:35:10,956 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524509266_0001_00_000001 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-05-17 22:35:10 Completed Dag: dag_1463524509266_0001_1
2016-05-17 22:35:10,957 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1463524509266_0001_1, dagState=SUCCEEDED
2016-05-17 22:35:10,957 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463524509266_0001_1_post
2016-05-17 22:35:10,959 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:10,959 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-05-17 22:35:10,966 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...tFieldFormatter/formatter, applicationId=application_1463524509266_0001
2016-05-17 22:35:10,971 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-05-17 22:35:10,971 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-05-17 22:35:10,971 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-05-17 22:35:10,971 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-05-17 22:35:10,971 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-05-17 22:35:10,972 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-05-17 22:35:10,975 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-05-17 22:35:10,975 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-05-17 22:35:10,975 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-05-17 22:35:10,976 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-05-17 22:35:10,976 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-05-17 22:35:10,976 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-17 22:35:10,977 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-17 22:35:10,981 INFO  app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A7A0AEE5458F40A9914CB2C1EE6B67B8/F765503E60944EDAB7E9E52F95FCC4CC/.tez/application_1463524509266_0001
2016-05-17 22:35:10,983 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testFieldFormatter/formatter/_temporary
2016-05-17 22:35:10,983 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [formatter]  completed in: 00:01.942
2016-05-17 22:35:11,083 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/functionplatform/testFieldFormatter/formatter
2016-05-17 22:35:11,087 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 1, with capacity: 2
2016-05-17 22:35:11,087 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 240, total: 281, max: 672
2016-05-17 22:35:11,088 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(111)) - total mem is 41% of max mem, to better utilize unused memory consider increasing the cache size
2016-05-17 22:35:11,088 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(105)) - flushed keys num times: 3, with capacity: 2
2016-05-17 22:35:11,089 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(106)) - mem on flush (mb), free: 240, total: 281, max: 672
2016-05-17 22:35:11,089 INFO  cache.LRUHashMapCache (LRUHashMapCache.java:removeEldestEntry(111)) - total mem is 41% of max mem, to better utilize unused memory consider increasing the cache size
2016-05-17 22:35:11,133 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-17 22:35:11,134 INFO  planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-17 22:35:11,210 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.038
2016-05-17 22:35:11,237 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.065
2016-05-17 22:35:11,239 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-17 22:35:11,239 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-17 22:35:11,239 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-17 22:35:11,260 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.200.txt
2016-05-17 22:35:11,293 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert
2016-05-17 22:35:11,396 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] starting
2016-05-17 22:35:11,397 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache]  source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.200.txt"]
2016-05-17 22:35:11,397 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache]  sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"]
2016-05-17 22:35:11,400 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache]  parallel execution of steps is enabled: false
2016-05-17 22:35:11,400 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache]  executing total steps: 1
2016-05-17 22:35:11,401 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache]  allocating management threads: 1
2016-05-17 22:35:11,401 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] starting step: (1/1) ...latform/testInsert/insert
2016-05-17 22:35:11,402 WARN  flow.Flow (BaseFlow.java:logWarn(1516)) - [apache] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-05-17 22:35:11,420 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] tez session mode enabled: true
2016-05-17 22:35:11,426 INFO  client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-05-17 22:35:11,426 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-05-17 22:35:11,426 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-05-17 22:35:11,438 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8/.tez/application_1463524511426_0001 doesn't exist and is created
2016-05-17 22:35:11,460 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-05-17 22:35:11,460 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 22:35:11,461 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8/.tez/application_1463524511426_0001
2016-05-17 22:35:11,466 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1463524511426_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-05-17 22:35:11,486 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-05-17 22:35:11,489 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-05-17 22:35:11,492 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-05-17 22:35:11,492 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-05-17 22:35:11,492 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8/.tez/application_1463524511426_0001/localmode-log-dir
2016-05-17 22:35:11,493 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8/.tez/application_1463524511426_0001/localmode-log-dir/history.txt.appattempt_1463524511426_0001_000000, maxErrors=10
2016-05-17 22:35:11,494 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-05-17 22:35:11,494 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463524511426_0001_000000, appSubmitTime=1463524511465, launchTime=1463524511466
2016-05-17 22:35:11,501 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-05-17 22:35:11,503 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-17 22:35:11,506 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-05-17 22:35:11,506 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-05-17 22:35:11,508 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:35180
2016-05-17 22:35:11,511 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-05-17 22:35:11,514 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-05-17 22:35:11,514 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463524511426_0001_000000, startTime=1463524511514
2016-05-17 22:35:11,514 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-05-17 22:35:11,561 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-17 22:35:11,561 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-05-17 22:35:11,561 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1463524511426_0001, dagName=[A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8] apache/(1/1) ...latform/testInsert/insert
2016-05-17 22:35:11,594 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8] apache/(1/1) ...latform/testInsert/insert
2016-05-17 22:35:11,600 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1463524511426_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8/.tez/application_1463524511426_0001/localmode-log-dir/dag_1463524511426_0001_1.dot
2016-05-17 22:35:11,601 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8/.tez/application_1463524511426_0001/localmode-log-dir/dag_1463524511426_0001_1-tez-dag.pb.txt
2016-05-17 22:35:11,635 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463524511426_0001_1
2016-05-17 22:35:11,635 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:11,635 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8] apache/(1/1) ...latform/testInsert/insert
2016-05-17 22:35:11 Running Dag: dag_1463524511426_0001_1
2016-05-17 22:35:11,654 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463524511426_0001_1, submitTime=1463524511595
2016-05-17 22:35:11,654 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-05-17 22:35:11,656 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex FC6A0E576D474A12849B19D0F32E8242
2016-05-17 22:35:11,662 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-17 22:35:11,662 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-05-17 22:35:11,663 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463524511426_0001_1, initTime=1463524511654
2016-05-17 22:35:11,663 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524511426_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-17 22:35:11,665 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1463524511426_0001, dagName=[A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8] apache/(1/1) ...latform/testInsert/insert
2016-05-17 22:35:11,667 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:DAG_STARTED]: dagID=dag_1463524511426_0001_1, startTime=1463524511664
2016-05-17 22:35:11,668 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-05-17 22:35:11,668 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524511426_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-17 22:35:11,668 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: E01FA4D33961423D8373B7C4C22503E7 : {95BC8784B89B4B909058983D9F64A61E={InputName=95BC8784B89B4B909058983D9F64A61E}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-17 22:35:11,668 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 95BC8784B89B4B909058983D9F64A61E, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-17 22:35:11,668 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:11,669 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:11,669 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:11,669 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]. Starting root input initializers: 1
2016-05-17 22:35:11,667 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-05-17 22:35:11,670 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-17 22:35:11,670 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:11,673 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 95BC8784B89B4B909058983D9F64A61E on vertex vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:11,687 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-05-17 22:35:11,688 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 95BC8784B89B4B909058983D9F64A61E asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-05-17 22:35:11,692 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-05-17 22:35:11,693 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-05-17 22:35:11,698 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 410
2016-05-17 22:35:11,700 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache] submitted tez dag to app master: application_1463524511426_0001, with dag id: dag_1463524511426_0001_1
2016-05-17 22:35:11,701 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 95BC8784B89B4B909058983D9F64A61E on vertex vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:11,705 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(696)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-05-17 22:35:11,705 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:11,706 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:11,706 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:11,706 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=F7419484FCE74A489B0755DE9029F55C, vertexId=vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-17 22:35:11,707 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=F7419484FCE74A489B0755DE9029F55C, vertexId=vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:11,716 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=F7419484FCE74A489B0755DE9029F55C, vertexName=FC6A0E576D474A12849B19D0F32E8242, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-17 22:35:11,717 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=F7419484FCE74A489B0755DE9029F55C, vertexId=vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:11,719 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 22:35:11,719 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:VERTEX_INITIALIZED]: vertexName=FC6A0E576D474A12849B19D0F32E8242, vertexId=vertex_1463524511426_0001_1_01, initRequestedTime=1463524511670, initedTime=1463524511719, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-05-17 22:35:11,720 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242] transitioned from NEW to INITED due to event V_INIT
2016-05-17 22:35:11,723 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 22:35:11,723 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {95BC8784B89B4B909058983D9F64A61E=forAllWorkUnits=true, update=[1]}
2016-05-17 22:35:11,724 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] parallelism set to 1
2016-05-17 22:35:11,725 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 22:35:11,726 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463524511426_0001_1_00, eventCount=1
2016-05-17 22:35:11,728 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 22:35:11,728 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:VERTEX_INITIALIZED]: vertexName=E01FA4D33961423D8373B7C4C22503E7, vertexId=vertex_1463524511426_0001_1_00, initRequestedTime=1463524511668, initedTime=1463524511727, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-05-17 22:35:11,729 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] with distanceFromRoot: 0
2016-05-17 22:35:11,730 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-05-17 22:35:11,731 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:11,731 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:11,732 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 22:35:11,733 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463524511426_0001_1_00, startRequestedTime=1463524511731, startedTime=1463524511731
2016-05-17 22:35:11,734 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] transitioned from INITED to RUNNING due to event V_START
2016-05-17 22:35:11,737 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 22:35:11,738 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:TASK_STARTED]: vertexName=E01FA4D33961423D8373B7C4C22503E7, taskId=task_1463524511426_0001_1_00_000000, scheduledTime=1463524511737, launchTime=1463524511737
2016-05-17 22:35:11,739 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524511426_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 22:35:11,739 INFO  impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1463524511426_0001_1_00 for vertex: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242] numStartedSources: 1 numSources: 1
2016-05-17 22:35:11,740 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242] with distanceFromRoot: 1
2016-05-17 22:35:11,741 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:11,744 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: E01FA4D33961423D8373B7C4C22503E7 in vertex: FC6A0E576D474A12849B19D0F32E8242
2016-05-17 22:35:11,746 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: FC6A0E576D474A12849B19D0F32E8242 with 1 source tasks and 1 pending tasks
2016-05-17 22:35:11,747 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 22:35:11,747 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463524511426_0001_1_01, startRequestedTime=1463524511742, startedTime=1463524511742
2016-05-17 22:35:11,747 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242] transitioned from INITED to RUNNING due to event V_START
2016-05-17 22:35:11,748 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8] apache/(1/1) ...latform/testInsert/insert, VertexName: E01FA4D33961423D8373B7C4C22503E7, VertexParallelism: 1, TaskAttemptID:attempt_1463524511426_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=95BC8784B89B4B909058983D9F64A61E, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=FC6A0E576D474A12849B19D0F32E8242, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 22:35:11,749 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524511426_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 22:35:11,749 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 22:35:11,751 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-05-17 22:35:11,752 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-05-17 22:35:11,752 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-05-17 22:35:11,754 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463524511426_0001_00_000001
2016-05-17 22:35:11,754 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 22:35:11,758 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1463524511426_0001_00_000001
2016-05-17 22:35:11,759 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-05-17 22:35:11,760 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 22:35:11,760 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 22:35:11,760 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463524511426_0001_00_000001, launchTime=1463524511760
2016-05-17 22:35:11,761 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463524511426_0001_00_000001
2016-05-17 22:35:11,762 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463524511426_0001_1_00_000000_0] to container: [container_1463524511426_0001_00_000001]
2016-05-17 22:35:11,763 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 22:35:11,763 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463524511426_0001_00_000001 given task: attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:11,763 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463524511426_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:11,763 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463524511426_0001_1_00_000000_0] started. Is using containerId: [container_1463524511426_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-17 22:35:11,764 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 22:35:11,764 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=E01FA4D33961423D8373B7C4C22503E7, taskAttemptId=attempt_1463524511426_0001_1_00_000000_0, startTime=1463524511763, containerId=container_1463524511426_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463524511426_0001_00_000001/teamcity, completedLogs=
2016-05-17 22:35:11,764 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524511426_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 22:35:11,764 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524511426_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 22:35:11 Starting to run new task attempt: attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:11,765 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:11,765 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:11,766 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 22:35:11,766 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 22:35:11,767 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 22:35:11,767 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 22:35:11,767 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-05-17 22:35:11,768 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8] apache/(1/1) ...latform/testInsert/insert, VertexName: E01FA4D33961423D8373B7C4C22503E7, VertexParallelism: 1, TaskAttemptID:attempt_1463524511426_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=95BC8784B89B4B909058983D9F64A61E, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=FC6A0E576D474A12849B19D0F32E8242, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 22:35:11,768 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 22:35:11,769 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:11,771 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 22:35:11,772 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:11,773 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463524511426_0001_1_00_000000_0 sent events: (0-1)
2016-05-17 22:35:11,773 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=95BC8784B89B4B909058983D9F64A61E, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-05-17 22:35:11,774 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:11,774 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=FC6A0E576D474A12849B19D0F32E8242, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-05-17 22:35:11,775 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 22:35:11,776 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 95BC8784B89B4B909058983D9F64A61E
2016-05-17 22:35:11,777 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 95BC8784B89B4B909058983D9F64A61E
2016-05-17 22:35:11,778 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 22:35:11,781 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 22:35:11,787 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-05-17 22:35:11,788 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 95BC8784B89B4B909058983D9F64A61E
2016-05-17 22:35:11,788 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 95BC8784B89B4B909058983D9F64A61E
2016-05-17 22:35:11,790 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: FC6A0E576D474A12849B19D0F32E8242
2016-05-17 22:35:11,796 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: E01FA4D33961423D8373B7C4C22503E7, ordinal: 0
2016-05-17 22:35:11,796 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E01FA4D33961423D8373B7C4C22503E7, mem on start (mb), free: 160, total: 281, max: 672
2016-05-17 22:35:11,797 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:11,797 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 22:35:11,797 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 22:35:11,799 INFO  impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-05-17 22:35:11,799 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: FC6A0E576D474A12849B19D0F32E8242
2016-05-17 22:35:11,799 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: FC6A0E576D474A12849B19D0F32E8242
2016-05-17 22:35:11,800 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 22:35:11,800 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 22:35:11,800 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-05-17 22:35:11,801 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 22:35:11,801 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-05-17 22:35:11,802 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 22:35:11,802 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 104857600, TotalRequestedScaled: 9.679163076923077E7, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.15
2016-05-17 22:35:11,803 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 95BC8784B89B4B909058983D9F64A61E, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-05-17 22:35:11,803 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, FC6A0E576D474A12849B19D0F32E8242, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-05-17 22:35:11,803 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 22:35:11,803 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 95BC8784B89B4B909058983D9F64A61E being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 22:35:11,804 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 22:35:11,804 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 22:35:11,804 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 95BC8784B89B4B909058983D9F64A61E
2016-05-17 22:35:11,805 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 22:35:11,805 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 95BC8784B89B4B909058983D9F64A61E
2016-05-17 22:35:11,806 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 22:35:11,806 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:11,807 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-05-17 22:35:11,807 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@70545eb3
2016-05-17 22:35:11,808 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@70545eb3
2016-05-17 22:35:11,809 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-05-17 22:35:11,809 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-05-17 22:35:11,815 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.200.txt"]
2016-05-17 22:35:11,825 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.200.txt"] streamed: true, id: 95BC8784B89B4B909058983D9F64A61E
2016-05-17 22:35:11,826 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(apache)[by:[{1}:'A']], id: E9FAC2AB477B484DA176D2E13EE09789
2016-05-17 22:35:11,826 INFO  element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(apache)[by:[{1}:'A']] E9FAC2AB477B484DA176D2E13EE09789
2016-05-17 22:35:11,863 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.KeyTupleSerializer@738e435a; valueSerializer=cascading.tuple.hadoop.io.ValueTupleSerializer@e804fb; comparator=cascading.tuple.hadoop.util.TupleComparator@9efb34; conf=cascading.tuple.hadoop.TupleSerialization,org.apache.hadoop.io.serializer.WritableSerialization,org.apache.hadoop.io.serializer.avro.AvroSpecificSerialization,org.apache.hadoop.io.serializer.avro.AvroReflectSerialization
2016-05-17 22:35:11,866 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-05-17 22:35:11,867 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-05-17 22:35:11,867 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 22:35:11,989 INFO  dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-05-17 22:35:11,989 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-05-17 22:35:11,989 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-05-17 22:35:11,989 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-05-17 22:35:11,990 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-05-17 22:35:11,991 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.200.txt"]
2016-05-17 22:35:11,991 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 22:35:11,991 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: E01FA4D33961423D8373B7C4C22503E7, all 1 inputs ready in: 00:00:00.000
2016-05-17 22:35:12,011 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:12,012 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: E01FA4D33961423D8373B7C4C22503E7, mem on close (mb), free: 53, total: 281, max: 672
2016-05-17 22:35:12,012 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-05-17 22:35:12,013 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-05-17 22:35:12,013 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 3000; bufvoid = 104857600
2016-05-17 22:35:12,013 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26213600(104854400); length = 797/6553600
2016-05-17 22:35:12,039 INFO  dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-05-17 22:35:12 Completed running task attempt: attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:12,059 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463524511426_0001_1_00_000000_0, fatalErrorOccurred=false
2016-05-17 22:35:12,060 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463524511426_0001_1_00, eventCount=1
2016-05-17 22:35:12,061 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 27 [[File System Counters FILE_BYTES_READ=36812, FILE_BYTES_WRITTEN=1852, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=200, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=200, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0][cascading.flow.SliceCounters Process_Begin_Time=1463524511992, Process_Duration=19, Process_End_Time=1463524512011, Read_Duration=6, Tuples_Read=200, Tuples_Written=200, Write_Duration=10][cascading.flow.StepCounters Tuples_Read=200]]
2016-05-17 22:35:12,062 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 22:35:12,062 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-05-17 22:35:12,063 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:12,064 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463524511426_0001_00_000001
2016-05-17 22:35:12,064 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=E01FA4D33961423D8373B7C4C22503E7, taskAttemptId=attempt_1463524511426_0001_1_00_000000_0, startTime=1463524511763, finishTime=1463524512060, timeTaken=297, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=36812, FILE_BYTES_WRITTEN=1852, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=200, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=200, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463524511992, Process_Duration=19, Process_End_Time=1463524512011, Read_Duration=6, Tuples_Read=200, Tuples_Written=200, Write_Duration=10, cascading.flow.StepCounters, Tuples_Read=200
2016-05-17 22:35:12,064 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524511426_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 22:35:12,065 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:12,065 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 22:35:12,065 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 22:35:12,068 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:TASK_FINISHED]: vertexName=E01FA4D33961423D8373B7C4C22503E7, taskId=task_1463524511426_0001_1_00_000000, startTime=1463524511763, finishTime=1463524512065, timeTaken=302, status=SUCCEEDED, successfulAttemptID=attempt_1463524511426_0001_1_00_000000_0, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=36812, FILE_BYTES_WRITTEN=1852, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=200, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=200, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463524511992, Process_Duration=19, Process_End_Time=1463524512011, Read_Duration=6, Tuples_Read=200, Tuples_Written=200, Write_Duration=10, cascading.flow.StepCounters, Tuples_Read=200
2016-05-17 22:35:12,068 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524511426_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 22:35:12,069 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] : 1
2016-05-17 22:35:12,070 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:12,071 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 22:35:12,072 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:VERTEX_FINISHED]: vertexName=E01FA4D33961423D8373B7C4C22503E7, vertexId=vertex_1463524511426_0001_1_00, initRequestedTime=1463524511668, initedTime=1463524511727, startRequestedTime=1463524511731, startedTime=1463524511731, finishTime=1463524512070, timeTaken=339, status=SUCCEEDED, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=36812, FILE_BYTES_WRITTEN=1852, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=200, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=200, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463524511992, Process_Duration=19, Process_End_Time=1463524512011, Read_Duration=6, Tuples_Read=200, Tuples_Written=200, Write_Duration=10, cascading.flow.StepCounters, Tuples_Read=200, vertexStats=firstTaskStartTime=1463524511763, firstTasksToStart=[ task_1463524511426_0001_1_00_000000 ], lastTaskFinishTime=1463524512060, lastTasksToFinish=[ task_1463524511426_0001_1_00_000000 ], minTaskDuration=297, maxTaskDuration=297, avgTaskDuration=297.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463524511426_0001_1_00_000000 ], longestDurationTasks=[ task_1463524511426_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 22:35:12,073 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 22:35:12,073 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 22:35:12,074 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 22:35:12,074 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463524511426_0001_00_000001, stoppedTime=1463524512074, exitStatus=0
2016-05-17 22:35:12,075 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 22:35:12,075 INFO  impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242] attempt: attempt_1463524511426_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-17 22:35:12,076 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463524511426_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-17 22:35:12,076 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463524511426_0001_00_000001: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 22:35:12,076 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463524511426_0001_00_000001, Exiting
2016-05-17 22:35:12,076 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463524511426_0001_00_000001
2016-05-17 22:35:12,076 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463524511426_0001_00_000001
2016-05-17 22:35:12,076 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: FC6A0E576D474A12849B19D0F32E8242
2016-05-17 22:35:12,079 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:12,080 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463524511426_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 22:35:12,080 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463524511426_0001_00_000001 completed successfully
2016-05-17 22:35:12,082 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-17 22:35:12,082 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1463524511426_0001_00_000001
2016-05-17 22:35:12,082 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000001 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-05-17 22:35:12,083 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 22:35:12,083 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:TASK_STARTED]: vertexName=FC6A0E576D474A12849B19D0F32E8242, taskId=task_1463524511426_0001_1_01_000000, scheduledTime=1463524512083, launchTime=1463524512083
2016-05-17 22:35:12,084 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524511426_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 22:35:12,084 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:12,085 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8] apache/(1/1) ...latform/testInsert/insert, VertexName: FC6A0E576D474A12849B19D0F32E8242, VertexParallelism: 1, TaskAttemptID:attempt_1463524511426_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=E01FA4D33961423D8373B7C4C22503E7, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=F7419484FCE74A489B0755DE9029F55C, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 22:35:12,085 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524511426_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 22:35:12,085 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 22:35:12,087 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463524511426_0001_00_000002
2016-05-17 22:35:12,088 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 22:35:12,092 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1463524511426_0001_00_000002
2016-05-17 22:35:12,093 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-teztask.properties,hadoop-metrics2.properties
2016-05-17 22:35:12,095 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 22:35:12,095 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 22:35:12,095 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463524511426_0001_00_000002, launchTime=1463524512095
2016-05-17 22:35:12,097 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463524511426_0001_00_000002
2016-05-17 22:35:12,097 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463524511426_0001_1_01_000000_0] to container: [container_1463524511426_0001_00_000002]
2016-05-17 22:35:12,098 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 22:35:12,098 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463524511426_0001_00_000002 given task: attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,098 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463524511426_0001_1_01_000000_0] started. Is using containerId: [container_1463524511426_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-17 22:35:12,098 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463524511426_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,099 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=FC6A0E576D474A12849B19D0F32E8242, taskAttemptId=attempt_1463524511426_0001_1_01_000000_0, startTime=1463524512098, containerId=container_1463524511426_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463524511426_0001_00_000002/teamcity, completedLogs=
2016-05-17 22:35:12,099 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 22:35:12 Starting to run new task attempt: attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,100 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,100 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:12,100 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 22:35:12,100 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 22:35:12,100 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524511426_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 22:35:12,100 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 22:35:12,101 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 22:35:12,101 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524511426_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 22:35:12,101 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-05-17 22:35:12,101 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8] apache/(1/1) ...latform/testInsert/insert, VertexName: FC6A0E576D474A12849B19D0F32E8242, VertexParallelism: 1, TaskAttemptID:attempt_1463524511426_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=E01FA4D33961423D8373B7C4C22503E7, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=F7419484FCE74A489B0755DE9029F55C, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 22:35:12,102 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 22:35:12,102 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,102 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 22:35:12,103 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:12,125 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:12,127 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=E01FA4D33961423D8373B7C4C22503E7, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-05-17 22:35:12,127 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 22:35:12,130 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=F7419484FCE74A489B0755DE9029F55C, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-05-17 22:35:12,135 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:12,133 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463524511426_0001_1_01_000000_0 sent events: (0-1)
2016-05-17 22:35:12,135 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 22:35:12,137 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: F7419484FCE74A489B0755DE9029F55C
2016-05-17 22:35:12,137 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-05-17 22:35:12,137 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: F7419484FCE74A489B0755DE9029F55C
2016-05-17 22:35:12,143 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 22:35:12,154 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-05-17 22:35:12,154 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: F7419484FCE74A489B0755DE9029F55C
2016-05-17 22:35:12,157 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-05-17 22:35:12,157 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-05-17 22:35:12,158 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:12,159 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:12,161 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: FC6A0E576D474A12849B19D0F32E8242, ordinal: 1
2016-05-17 22:35:12,161 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FC6A0E576D474A12849B19D0F32E8242, mem on start (mb), free: 156, total: 281, max: 672
2016-05-17 22:35:12,161 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:12,161 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 22:35:12,161 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 22:35:12,162 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 22:35:12,162 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 22:35:12,162 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-05-17 22:35:12,162 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 22:35:12,162 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-05-17 22:35:12,163 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 22:35:12,163 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 13, TotalRequested: 634178752, TotalRequestedScaled: 5.853957710769231E8, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.90
2016-05-17 22:35:12,163 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, F7419484FCE74A489B0755DE9029F55C, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-05-17 22:35:12,163 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, E01FA4D33961423D8373B7C4C22503E7, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=472110858
2016-05-17 22:35:12,163 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 22:35:12,163 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: E01FA4D33961423D8373B7C4C22503E7 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 22:35:12,163 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:12,164 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 22:35:12,168 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 22:35:12,175 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 22:35:12,175 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-05-17 22:35:12,179 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: E01FA4D33961423D8373B7C4C22503E7 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-05-17 22:35:12,181 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=472110858. Updated to: ShuffleMem=472110858, postMergeMem: 0
2016-05-17 22:35:12,181 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=472110858, maxSingleShuffleLimit=118027712, mergeThreshold=424899744, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-05-17 22:35:12,185 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-05-17 22:35:12,189 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:12,189 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 22:35:12,190 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,190 INFO  orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:processDataMovementEvent(84)) - DME srcIdx: 0, targetIdx: 0, attemptNum: 0, payload: [host: ip-10-123-148-208, port: 0, pathComponent: attempt_1463524511426_0001_1_00_000000_0_10006, runDuration: 253141, ]
2016-05-17 22:35:12,196 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(apache)[by:[{1}:'A']]
2016-05-17 22:35:12,197 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1463524511426_0001_1_00_000000_0_10006] to DISK_DIRECT, CompressedSize=1820, DecompressedSize=1816,EndTime=1463524512197, TimeTaken=4, Rate=0.43 MB/s
2016-05-17 22:35:12,197 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:12,198 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-17 22:35:12,199 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-123-148-208:0 freed by fetcher [E01FA4D33961423D8373B7C4C22503E7] #1 in 6ms
2016-05-17 22:35:12,199 INFO  orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [E01FA4D33961423D8373B7C4C22503E7] #1, status:false, isInterrupted:false
2016-05-17 22:35:12,201 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-17 22:35:12,201 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(apache)[by:[{1}:'A']] streamed: true, id: E9FAC2AB477B484DA176D2E13EE09789
2016-05-17 22:35:12,201 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"], id: F7419484FCE74A489B0755DE9029F55C
2016-05-17 22:35:12,201 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert"]
2016-05-17 22:35:12,202 INFO  element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(apache)[by:[{1}:'A']] E9FAC2AB477B484DA176D2E13EE09789, for 1 inputs
2016-05-17 22:35:12,204 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 1820 bytes from disk
2016-05-17 22:35:12,205 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 22:35:12,209 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-05-17 22:35:12,212 INFO  impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 1803 bytes
2016-05-17 22:35:12,212 INFO  orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:12,213 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: FC6A0E576D474A12849B19D0F32E8242, all 1 inputs ready in: 00:00:00.010
2016-05-17 22:35:12,213 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-05-17 22:35:12,216 INFO  common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.KeyTupleDeserializer@2c9af8c3; valueDeserializer=cascading.tuple.hadoop.io.ValueTupleDeserializer@7241e115
2016-05-17 22:35:12,245 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-05-17 22:35:12,246 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-05-17 22:35:12,246 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,247 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1463524511426_0001_1_01_000000_0 given a go for committing the task output.
2016-05-17 22:35:12,247 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,248 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FC6A0E576D474A12849B19D0F32E8242, mem on close (mb), free: 149, total: 281, max: 672
2016-05-17 22:35:12,248 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: E01FA4D33961423D8373B7C4C22503E7
2016-05-17 22:35:12,248 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-05-17 22:35:12,249 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-05-17 22:35:12,250 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 22:35:12,250 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-05-17 22:35:12,250 INFO  impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-05-17 22:35:12 Completed running task attempt: attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,252 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463524511426_0001_1_01_000000_0, fatalErrorOccurred=false
2016-05-17 22:35:12,253 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=1852, FILE_BYTES_WRITTEN=816, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=0, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=200, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=21, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=200, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=24, MERGE_PHASE_TIME=37, FIRST_EVENT_RECEIVED=18, LAST_EVENT_RECEIVED=18][Shuffle Errors BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0][cascading.flow.SliceCounters Process_Begin_Time=1463524512213, Process_Duration=34, Process_End_Time=1463524512247, Read_Duration=13, Tuples_Read=200, Tuples_Written=200, Write_Duration=3][cascading.flow.StepCounters Tuples_Written=200]]
2016-05-17 22:35:12,256 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-05-17 22:35:12,256 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:12,255 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=FC6A0E576D474A12849B19D0F32E8242, taskAttemptId=attempt_1463524511426_0001_1_01_000000_0, startTime=1463524512098, finishTime=1463524512253, timeTaken=155, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=1852, FILE_BYTES_WRITTEN=816, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=200, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=21, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=200, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=24, MERGE_PHASE_TIME=37, FIRST_EVENT_RECEIVED=18, LAST_EVENT_RECEIVED=18, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1463524512213, Process_Duration=34, Process_End_Time=1463524512247, Read_Duration=13, Tuples_Read=200, Tuples_Written=200, Write_Duration=3, cascading.flow.StepCounters, Tuples_Written=200
2016-05-17 22:35:12,257 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524511426_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 22:35:12,255 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 22:35:12,258 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12,257 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463524511426_0001_00_000002
2016-05-17 22:35:12,259 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 22:35:12,259 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 22:35:12,259 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:TASK_FINISHED]: vertexName=FC6A0E576D474A12849B19D0F32E8242, taskId=task_1463524511426_0001_1_01_000000, startTime=1463524512098, finishTime=1463524512258, timeTaken=160, status=SUCCEEDED, successfulAttemptID=attempt_1463524511426_0001_1_01_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=1852, FILE_BYTES_WRITTEN=816, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=200, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=21, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=200, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=24, MERGE_PHASE_TIME=37, FIRST_EVENT_RECEIVED=18, LAST_EVENT_RECEIVED=18, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1463524512213, Process_Duration=34, Process_End_Time=1463524512247, Read_Duration=13, Tuples_Read=200, Tuples_Written=200, Write_Duration=3, cascading.flow.StepCounters, Tuples_Written=200
2016-05-17 22:35:12,260 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524511426_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 22:35:12,261 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242] : 1
2016-05-17 22:35:12,261 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:12,263 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 22:35:12,264 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:VERTEX_FINISHED]: vertexName=FC6A0E576D474A12849B19D0F32E8242, vertexId=vertex_1463524511426_0001_1_01, initRequestedTime=1463524511670, initedTime=1463524511719, startRequestedTime=1463524511742, startedTime=1463524511742, finishTime=1463524512261, timeTaken=519, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=1852, FILE_BYTES_WRITTEN=816, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=200, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=21, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=200, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=24, MERGE_PHASE_TIME=37, FIRST_EVENT_RECEIVED=18, LAST_EVENT_RECEIVED=18, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=1463524512213, Process_Duration=34, Process_End_Time=1463524512247, Read_Duration=13, Tuples_Read=200, Tuples_Written=200, Write_Duration=3, cascading.flow.StepCounters, Tuples_Written=200, vertexStats=firstTaskStartTime=1463524512098, firstTasksToStart=[ task_1463524511426_0001_1_01_000000 ], lastTaskFinishTime=1463524512253, lastTasksToFinish=[ task_1463524511426_0001_1_01_000000 ], minTaskDuration=155, maxTaskDuration=155, avgTaskDuration=155.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463524511426_0001_1_01_000000 ], longestDurationTasks=[ task_1463524511426_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 22:35:12,265 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 22:35:12,265 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 22:35:12,266 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 22:35:12,266 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463524511426_0001_00_000002, stoppedTime=1463524512266, exitStatus=0
2016-05-17 22:35:12,267 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 22:35:12,267 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-17 22:35:12,268 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1463524511426_0001_1
2016-05-17 22:35:12,268 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463524511426_0001_1
2016-05-17 22:35:12,269 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: F7419484FCE74A489B0755DE9029F55C for vertex: vertex_1463524511426_0001_1_01 [FC6A0E576D474A12849B19D0F32E8242]
2016-05-17 22:35:12,269 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463524511426_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-17 22:35:12,269 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463524511426_0001_00_000002: 10 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 22:35:12,269 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463524511426_0001_00_000002, Exiting
2016-05-17 22:35:12,269 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463524511426_0001_00_000002
2016-05-17 22:35:12,270 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463524511426_0001_00_000002
2016-05-17 22:35:12,274 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463524511426_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 22:35:12,274 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463524511426_0001_00_000002 completed successfully
2016-05-17 22:35:12,286 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1463524511426_0001_1_00 [E01FA4D33961423D8373B7C4C22503E7]
2016-05-17 22:35:12,289 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1463524511426_0001_1, queueSize=0
2016-05-17 22:35:12,289 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-05-17 22:35:12,291 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524511426_0001_1][Event:DAG_FINISHED]: dagId=dag_1463524511426_0001_1, startTime=1463524511664, finishTime=1463524512286, timeTaken=622, status=SUCCEEDED, diagnostics=, counters=Counters: 55, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=2, TOTAL_LAUNCHED_TASKS=2, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=38664, FILE_BYTES_WRITTEN=2668, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0, REDUCE_INPUT_RECORDS=200, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=400, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=21, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=590348288, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=400, OUTPUT_BYTES=3000, OUTPUT_BYTES_WITH_OVERHEAD=1816, OUTPUT_BYTES_PHYSICAL=1820, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=1820, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=1820, SHUFFLE_BYTES_DECOMPRESSED=1816, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=1820, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=24, MERGE_PHASE_TIME=37, FIRST_EVENT_RECEIVED=18, LAST_EVENT_RECEIVED=18, Shuffle Errors, BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0, cascading.flow.SliceCounters, Process_Begin_Time=2927049024205, Process_Duration=53, Process_End_Time=2927049024258, Read_Duration=19, Tuples_Read=400, Tuples_Written=400, Write_Duration=13, cascading.flow.StepCounters, Tuples_Read=200, Tuples_Written=200
2016-05-17 22:35:12,291 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1463524511426_0001_1 finished with state: SUCCEEDED
2016-05-17 22:35:12,291 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524511426_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-05-17 22:35:12,292 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1463524511426_0001_00_000002
2016-05-17 22:35:12,292 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524511426_0001_00_000002 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-05-17 22:35:12 Completed Dag: dag_1463524511426_0001_1
2016-05-17 22:35:12,294 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1463524511426_0001_1, dagState=SUCCEEDED
2016-05-17 22:35:12,295 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463524511426_0001_1_post
2016-05-17 22:35:12,295 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:12,296 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-05-17 22:35:12,302 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...latform/testInsert/insert, applicationId=application_1463524511426_0001
2016-05-17 22:35:12,305 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-05-17 22:35:12,305 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-05-17 22:35:12,305 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-05-17 22:35:12,305 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-05-17 22:35:12,306 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-05-17 22:35:12,306 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-05-17 22:35:12,308 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-05-17 22:35:12,308 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-05-17 22:35:12,308 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-05-17 22:35:12,308 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-05-17 22:35:12,308 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-05-17 22:35:12,310 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-17 22:35:12,310 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-17 22:35:12,316 INFO  app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/A4C86E58B6EF441490D11FC579A3EA14/D91386BB83394824BE0E14D480B8D3F8/.tez/application_1463524511426_0001
2016-05-17 22:35:12,317 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testInsert/insert/_temporary
2016-05-17 22:35:12,317 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [apache]  completed in: 00:00.920
2016-05-17 22:35:12,429 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/functionplatform/testInsert/insert
2016-05-17 22:35:12,462 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-17 22:35:12,462 INFO  planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(151)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.1.0/226af02e24d5195c60e4ebe911d0c7c9780f59f0/cascading-hadoop2-tez-3.1.0.jar
2016-05-17 22:35:12,537 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.040
2016-05-17 22:35:12,545 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.047
2016-05-17 22:35:12,546 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-17 22:35:12,546 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 1
2016-05-17 22:35:12,547 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-17 22:35:12,565 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt
2016-05-17 22:35:12,566 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue
2016-05-17 22:35:12,587 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] starting
2016-05-17 22:35:12,587 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue]  source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-05-17 22:35:12,588 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue]  sink: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"]
2016-05-17 22:35:12,588 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue]  parallel execution of steps is enabled: false
2016-05-17 22:35:12,588 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue]  executing total steps: 1
2016-05-17 22:35:12,588 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue]  allocating management threads: 1
2016-05-17 22:35:12,590 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] starting step: (1/1) ...orm/testSetValue/setvalue
2016-05-17 22:35:12,591 WARN  flow.Flow (BaseFlow.java:logWarn(1516)) - [setvalue] 'yarn.timeline-service.enabled' is disabled, please enable to capture detailed metrics of completed flows, this may require starting the YARN timeline server daemon
2016-05-17 22:35:12,606 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] tez session mode enabled: true
2016-05-17 22:35:12,612 INFO  client.TezClient (TezClient.java:<init>(153)) - Tez Client Version: [ component=tez-api, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-05-17 22:35:12,612 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-05-17 22:35:12,612 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-05-17 22:35:12,623 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0/.tez/application_1463524512612_0001 doesn't exist and is created
2016-05-17 22:35:12,643 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-05-17 22:35:12,643 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 22:35:12,644 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0/.tez/application_1463524512612_0001
2016-05-17 22:35:12,649 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1463524512612_0001_000000, versionInfo=[ component=tez-dag, version=0.6.2, revision=c04283bf91fd96823eec37056d5c8b1a92728265, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20150804-1436 ]
2016-05-17 22:35:12,662 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-05-17 22:35:12,663 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-05-17 22:35:12,665 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-05-17 22:35:12,666 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-05-17 22:35:12,666 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0/.tez/application_1463524512612_0001/localmode-log-dir
2016-05-17 22:35:12,666 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0/.tez/application_1463524512612_0001/localmode-log-dir/history.txt.appattempt_1463524512612_0001_000000, maxErrors=10
2016-05-17 22:35:12,667 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-05-17 22:35:12,667 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463524512612_0001_000000, appSubmitTime=1463524512648, launchTime=1463524512648
2016-05-17 22:35:12,673 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-05-17 22:35:12,675 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-17 22:35:12,677 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-05-17 22:35:12,677 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-05-17 22:35:12,680 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:57085
2016-05-17 22:35:12,681 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-05-17 22:35:12,683 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463524512612_0001_000000, startTime=1463524512683
2016-05-17 22:35:12,683 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-05-17 22:35:12,684 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-05-17 22:35:12,743 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-17 22:35:12,743 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-05-17 22:35:12,743 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1463524512612_0001, dagName=[E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-05-17 22:35:12,763 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-05-17 22:35:12,764 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1463524512612_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0/.tez/application_1463524512612_0001/localmode-log-dir/dag_1463524512612_0001_1.dot
2016-05-17 22:35:12,765 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0/.tez/application_1463524512612_0001/localmode-log-dir/dag_1463524512612_0001_1-tez-dag.pb.txt
2016-05-17 22:35:12,792 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463524512612_0001_1
2016-05-17 22:35:12,792 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:12,793 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-05-17 22:35:12 Running Dag: dag_1463524512612_0001_1
2016-05-17 22:35:12,807 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-05-17 22:35:12,807 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463524512612_0001_1, submitTime=1463524512763
2016-05-17 22:35:12,808 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex B077CBBEFABD4144AD9913BCDC0051A5
2016-05-17 22:35:12,808 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-17 22:35:12,808 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-05-17 22:35:12,809 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463524512612_0001_1, initTime=1463524512807
2016-05-17 22:35:12,809 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524512612_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-17 22:35:12,810 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-05-17 22:35:12,810 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:DAG_STARTED]: dagID=dag_1463524512612_0001_1, startTime=1463524512810
2016-05-17 22:35:12,811 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-05-17 22:35:12,811 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524512612_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-17 22:35:12,811 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: B077CBBEFABD4144AD9913BCDC0051A5 : {810BDBCEB6684D498184CAB590B34872={InputName=810BDBCEB6684D498184CAB590B34872}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-17 22:35:12,811 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 810BDBCEB6684D498184CAB590B34872, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-17 22:35:12,811 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,811 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,812 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,812 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]. Starting root input initializers: 1
2016-05-17 22:35:12,813 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-17 22:35:12,813 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1463524512612_0001, dagName=[E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0] setvalue/(1/1) ...orm/testSetValue/setvalue
2016-05-17 22:35:12,813 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 810BDBCEB6684D498184CAB590B34872 on vertex vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,815 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-05-17 22:35:12,815 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 810BDBCEB6684D498184CAB590B34872 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-05-17 22:35:12,816 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-05-17 22:35:12,816 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-05-17 22:35:12,818 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 522
2016-05-17 22:35:12,818 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 810BDBCEB6684D498184CAB590B34872 on vertex vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,819 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 22:35:12,819 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {810BDBCEB6684D498184CAB590B34872=forAllWorkUnits=true, update=[1]}
2016-05-17 22:35:12,819 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] parallelism set to 1
2016-05-17 22:35:12,819 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 22:35:12,820 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463524512612_0001_1_00, eventCount=1
2016-05-17 22:35:12,820 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,820 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=205701D854C34A908B8E0F982B95FE80, vertexId=vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-17 22:35:12,820 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=205701D854C34A908B8E0F982B95FE80, vertexId=vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,823 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=205701D854C34A908B8E0F982B95FE80, vertexName=B077CBBEFABD4144AD9913BCDC0051A5, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-17 22:35:12,823 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=205701D854C34A908B8E0F982B95FE80, vertexId=vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,828 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:VERTEX_INITIALIZED]: vertexName=B077CBBEFABD4144AD9913BCDC0051A5, vertexId=vertex_1463524512612_0001_1_00, initRequestedTime=1463524512811, initedTime=1463524512828, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-05-17 22:35:12,828 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] with distanceFromRoot: 0
2016-05-17 22:35:12,828 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-05-17 22:35:12,829 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in B077CBBEFABD4144AD9913BCDC0051A5
2016-05-17 22:35:12,829 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,829 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463524512612_0001_1_00, startRequestedTime=1463524512829, startedTime=1463524512829
2016-05-17 22:35:12,830 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] transitioned from INITED to RUNNING due to event V_START
2016-05-17 22:35:12,830 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 22:35:12,830 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:TASK_STARTED]: vertexName=B077CBBEFABD4144AD9913BCDC0051A5, taskId=task_1463524512612_0001_1_00_000000, scheduledTime=1463524512830, launchTime=1463524512830
2016-05-17 22:35:12,831 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 22:35:12,831 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524512612_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 22:35:12,831 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 22:35:12,832 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,834 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0] setvalue/(1/1) ...orm/testSetValue/setvalue, VertexName: B077CBBEFABD4144AD9913BCDC0051A5, VertexParallelism: 1, TaskAttemptID:attempt_1463524512612_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=810BDBCEB6684D498184CAB590B34872, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=205701D854C34A908B8E0F982B95FE80, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 22:35:12,834 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524512612_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 22:35:12,834 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 22:35:12,835 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-05-17 22:35:12,837 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-05-17 22:35:12,837 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-05-17 22:35:12,838 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463524512612_0001_00_000001
2016-05-17 22:35:12,838 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524512612_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 22:35:12,840 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1463524512612_0001_00_000001
2016-05-17 22:35:12,840 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-05-17 22:35:12,841 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524512612_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 22:35:12,841 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 22:35:12,841 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463524512612_0001_00_000001, launchTime=1463524512841
2016-05-17 22:35:12,842 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463524512612_0001_00_000001
2016-05-17 22:35:12,843 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463524512612_0001_1_00_000000_0] to container: [container_1463524512612_0001_00_000001]
2016-05-17 22:35:12,843 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue] submitted tez dag to app master: application_1463524512612_0001, with dag id: dag_1463524512612_0001_1
2016-05-17 22:35:12,843 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524512612_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 22:35:12,845 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463524512612_0001_00_000001 given task: attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,845 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463524512612_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,845 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463524512612_0001_1_00_000000_0] started. Is using containerId: [container_1463524512612_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-17 22:35:12,846 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 22:35:12,846 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=B077CBBEFABD4144AD9913BCDC0051A5, taskAttemptId=attempt_1463524512612_0001_1_00_000000_0, startTime=1463524512845, containerId=container_1463524512612_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463524512612_0001_00_000001/teamcity, completedLogs=
2016-05-17 22:35:12,846 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524512612_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 22:35:12,847 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524512612_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 22:35:12 Starting to run new task attempt: attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,847 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,848 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:12,848 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 22:35:12,848 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 22:35:12,848 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 22:35:12,849 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 22:35:12,852 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-05-17 22:35:12,852 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0] setvalue/(1/1) ...orm/testSetValue/setvalue, VertexName: B077CBBEFABD4144AD9913BCDC0051A5, VertexParallelism: 1, TaskAttemptID:attempt_1463524512612_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=810BDBCEB6684D498184CAB590B34872, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=205701D854C34A908B8E0F982B95FE80, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 22:35:12,853 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 22:35:12,854 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,856 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 22:35:12,856 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:12,856 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463524512612_0001_1_00_000000_0 sent events: (0-1)
2016-05-17 22:35:12,857 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:12,858 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=810BDBCEB6684D498184CAB590B34872, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-05-17 22:35:12,859 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 22:35:12,859 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 810BDBCEB6684D498184CAB590B34872
2016-05-17 22:35:12,859 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 810BDBCEB6684D498184CAB590B34872
2016-05-17 22:35:12,861 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=205701D854C34A908B8E0F982B95FE80, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-05-17 22:35:12,862 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 22:35:12,862 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-05-17 22:35:12,863 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 22:35:12,863 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 810BDBCEB6684D498184CAB590B34872
2016-05-17 22:35:12,863 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 810BDBCEB6684D498184CAB590B34872
2016-05-17 22:35:12,864 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 205701D854C34A908B8E0F982B95FE80
2016-05-17 22:35:12,864 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-05-17 22:35:12,864 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 205701D854C34A908B8E0F982B95FE80
2016-05-17 22:35:12,876 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-05-17 22:35:12,876 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: B077CBBEFABD4144AD9913BCDC0051A5, ordinal: 0
2016-05-17 22:35:12,876 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: B077CBBEFABD4144AD9913BCDC0051A5, mem on start (mb), free: 71, total: 281, max: 672
2016-05-17 22:35:12,876 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 22:35:12,877 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 22:35:12,877 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 22:35:12,876 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 205701D854C34A908B8E0F982B95FE80
2016-05-17 22:35:12,877 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 22:35:12,877 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 22:35:12,878 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-05-17 22:35:12,878 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 22:35:12,878 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-05-17 22:35:12,878 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 22:35:12,879 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 22:35:12,879 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:assignMemory(126)) - Scaling Requests. NumRequests: 2, numScaledRequests: 2, TotalRequested: 0, TotalRequestedScaled: 0.0, TotalJVMHeap: 704643072, TotalAvailable: 472110858, TotalRequested/TotalJVMHeap:0.00
2016-05-17 22:35:12,879 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 810BDBCEB6684D498184CAB590B34872, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-05-17 22:35:12,879 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 205701D854C34A908B8E0F982B95FE80, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-05-17 22:35:12,880 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 22:35:12,880 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 810BDBCEB6684D498184CAB590B34872 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 22:35:12,880 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 22:35:12,880 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 22:35:12,880 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 810BDBCEB6684D498184CAB590B34872
2016-05-17 22:35:12,882 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 22:35:12,882 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 810BDBCEB6684D498184CAB590B34872
2016-05-17 22:35:12,883 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 22:35:12,883 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,883 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-05-17 22:35:12,884 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@50a302a5
2016-05-17 22:35:12,886 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@50a302a5
2016-05-17 22:35:12,886 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-05-17 22:35:12,886 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-05-17 22:35:12,888 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-05-17 22:35:12,888 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt"] streamed: true, id: 810BDBCEB6684D498184CAB590B34872
2016-05-17 22:35:12,889 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"], id: 205701D854C34A908B8E0F982B95FE80
2016-05-17 22:35:12,889 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue"]
2016-05-17 22:35:12,890 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/classes/test/data/upper.txt"]
2016-05-17 22:35:12,891 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 22:35:12,891 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: B077CBBEFABD4144AD9913BCDC0051A5, all 1 inputs ready in: 00:00:00.000
2016-05-17 22:35:12,895 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-05-17 22:35:12,896 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-05-17 22:35:12,896 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,897 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1463524512612_0001_1_00_000000_0 given a go for committing the task output.
2016-05-17 22:35:12,898 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,898 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: B077CBBEFABD4144AD9913BCDC0051A5, mem on close (mb), free: 70, total: 281, max: 672
2016-05-17 22:35:12 Completed running task attempt: attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,899 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463524512612_0001_1_00_000000_0, fatalErrorOccurred=false
2016-05-17 22:35:12,900 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 21 [[File System Counters FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5][cascading.flow.SliceCounters Process_Begin_Time=1463524512891, Process_Duration=7, Process_End_Time=1463524512898, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=5, Tuples_Written=5]]
2016-05-17 22:35:12,900 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 22:35:12,901 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-05-17 22:35:12,904 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:12,904 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=B077CBBEFABD4144AD9913BCDC0051A5, taskAttemptId=attempt_1463524512612_0001_1_00_000000_0, startTime=1463524512845, finishTime=1463524512900, timeTaken=55, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463524512891, Process_Duration=7, Process_End_Time=1463524512898, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-17 22:35:12,904 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463524512612_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 22:35:12,904 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 22:35:12,904 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463524512612_0001_00_000001
2016-05-17 22:35:12,904 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12,906 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 22:35:12,906 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:TASK_FINISHED]: vertexName=B077CBBEFABD4144AD9913BCDC0051A5, taskId=task_1463524512612_0001_1_00_000000, startTime=1463524512845, finishTime=1463524512905, timeTaken=60, status=SUCCEEDED, successfulAttemptID=attempt_1463524512612_0001_1_00_000000_0, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463524512891, Process_Duration=7, Process_End_Time=1463524512898, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-17 22:35:12,906 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463524512612_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 22:35:12,906 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] : 1
2016-05-17 22:35:12,907 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,910 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 22:35:12,910 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:VERTEX_FINISHED]: vertexName=B077CBBEFABD4144AD9913BCDC0051A5, vertexId=vertex_1463524512612_0001_1_00, initRequestedTime=1463524512811, initedTime=1463524512828, startRequestedTime=1463524512829, startedTime=1463524512829, finishTime=1463524512907, timeTaken=78, status=SUCCEEDED, diagnostics=, counters=Counters: 22, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463524512891, Process_Duration=7, Process_End_Time=1463524512898, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5, vertexStats=firstTaskStartTime=1463524512845, firstTasksToStart=[ task_1463524512612_0001_1_00_000000 ], lastTaskFinishTime=1463524512900, lastTasksToFinish=[ task_1463524512612_0001_1_00_000000 ], minTaskDuration=55, maxTaskDuration=55, avgTaskDuration=55.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463524512612_0001_1_00_000000 ], longestDurationTasks=[ task_1463524512612_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 22:35:12,910 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 22:35:12,911 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524512612_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 22:35:12,911 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463524512612_0001_00_000001, stoppedTime=1463524512911, exitStatus=0
2016-05-17 22:35:12,912 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 22:35:12,912 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524512612_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 22:35:12,913 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=1
2016-05-17 22:35:12,914 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1463524512612_0001_1
2016-05-17 22:35:12,914 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463524512612_0001_1
2016-05-17 22:35:12,915 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 205701D854C34A908B8E0F982B95FE80 for vertex: vertex_1463524512612_0001_1_00 [B077CBBEFABD4144AD9913BCDC0051A5]
2016-05-17 22:35:12,920 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463524512612_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-17 22:35:12,920 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463524512612_0001_00_000001: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 22:35:12,920 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463524512612_0001_00_000001, Exiting
2016-05-17 22:35:12,920 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463524512612_0001_00_000001
2016-05-17 22:35:12,920 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463524512612_0001_00_000001
2016-05-17 22:35:12,922 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463524512612_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 22:35:12,923 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463524512612_0001_00_000001 completed successfully
2016-05-17 22:35:12,929 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1463524512612_0001_1, queueSize=0
2016-05-17 22:35:12,929 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-05-17 22:35:12,929 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463524512612_0001_1][Event:DAG_FINISHED]: dagId=dag_1463524512612_0001_1, startTime=1463524512810, finishTime=1463524512928, timeTaken=118, status=SUCCEEDED, diagnostics=, counters=Counters: 24, org.apache.tez.common.counters.DAGCounter, NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=30, FILE_BYTES_WRITTEN=39, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=5, cascading.flow.SliceCounters, Process_Begin_Time=1463524512891, Process_Duration=7, Process_End_Time=1463524512898, Read_Duration=2, Tuples_Read=5, Tuples_Written=5, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=5, Tuples_Written=5
2016-05-17 22:35:12,929 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1463524512612_0001_1 finished with state: SUCCEEDED
2016-05-17 22:35:12,930 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463524512612_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-05-17 22:35:12,930 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463524512612_0001_00_000001 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-05-17 22:35:12 Completed Dag: dag_1463524512612_0001_1
2016-05-17 22:35:12,930 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1463524512612_0001_00_000001
2016-05-17 22:35:12,930 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1463524512612_0001_1, dagState=SUCCEEDED
2016-05-17 22:35:12,931 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463524512612_0001_1_post
2016-05-17 22:35:12,931 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 22:35:12,932 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-05-17 22:35:12,938 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...orm/testSetValue/setvalue, applicationId=application_1463524512612_0001
2016-05-17 22:35:12,943 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-05-17 22:35:12,943 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-05-17 22:35:12,943 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-05-17 22:35:12,943 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-05-17 22:35:12,944 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-05-17 22:35:12,944 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-05-17 22:35:12,945 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-05-17 22:35:12,945 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-05-17 22:35:12,945 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-05-17 22:35:12,945 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-05-17 22:35:12,946 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-05-17 22:35:12,947 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-17 22:35:12,947 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-17 22:35:12,954 INFO  app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/E79DF708E0D944A0AAC4AB33D03D93A2/F8F042318A954030B9E576619AACFFE0/.tez/application_1463524512612_0001
2016-05-17 22:35:12,954 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/functionplatform/testSetValue/setvalue/_temporary
2016-05-17 22:35:12,955 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [setvalue]  completed in: 00:00.367
2016-05-17 22:35:13,033 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/functionplatform/testSetValue/setvalue

2016-05-17 22:35:10 Running Dag: dag_1463524509266_0001_1
2016-05-17 22:35:10 Starting to run new task attempt: attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10 Completed running task attempt: attempt_1463524509266_0001_1_00_000000_0
2016-05-17 22:35:10 Completed Dag: dag_1463524509266_0001_1
2016-05-17 22:35:11 Running Dag: dag_1463524511426_0001_1
2016-05-17 22:35:11 Starting to run new task attempt: attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:12 Completed running task attempt: attempt_1463524511426_0001_1_00_000000_0
2016-05-17 22:35:12 Starting to run new task attempt: attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12 Completed running task attempt: attempt_1463524511426_0001_1_01_000000_0
2016-05-17 22:35:12 Completed Dag: dag_1463524511426_0001_1
2016-05-17 22:35:12 Running Dag: dag_1463524512612_0001_1
2016-05-17 22:35:12 Starting to run new task attempt: attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12 Completed running task attempt: attempt_1463524512612_0001_1_00_000000_0
2016-05-17 22:35:12 Completed Dag: dag_1463524512612_0001_1