Class cascading.flow.AssemblyPlannerPlatformTest

2

tests

0

failures

0

ignored

4.894s

duration

100%

successful

Tests

Test Duration Result
testCompositeAssembly 3.958s passed
testSimpleAssembly 0.936s passed

Standard output

2016-05-17 21:20:46,334 INFO  platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(197)) - found 1 test platforms from classpath
2016-05-17 21:20:46,366 INFO  platform.PlatformRunner (PlatformRunner.java:addPlatform(246)) - adding test: cascading.flow.AssemblyPlannerPlatformTest, with platform: hadoop2-tez
2016-05-17 21:20:46,398 INFO  tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-05-17 21:20:46,749 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 21:20:47,062 INFO  platform.TestPlatform (TestPlatform.java:getGlobalProperties(75)) - platform property overrides: 
2016-05-17 21:20:47,219 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-17 21:20:47,221 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 21:20:47,348 INFO  property.AppProps (AppProps.java:getAppID(177)) - using app.id: DD1475B47536455CAE04DB04ADC11107
2016-05-17 21:20:47,577 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.077
2016-05-17 21:20:47,602 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.103
2016-05-17 21:20:47,608 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-17 21:20:47,608 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-17 21:20:47,610 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-17 21:20:47,756 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt
2016-05-17 21:20:47,926 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite
2016-05-17 21:20:48,126 INFO  util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.1.0
2016-05-17 21:20:48,129 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting
2016-05-17 21:20:48,129 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-05-17 21:20:48,130 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite"]
2016-05-17 21:20:48,130 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  parallel execution of steps is enabled: false
2016-05-17 21:20:48,130 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  executing total steps: 1
2016-05-17 21:20:48,130 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  allocating management threads: 1
2016-05-17 21:20:48,132 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting step: (1/1) ...mpositeAssembly/composite
2016-05-17 21:20:48,132 WARN  flow.Flow (BaseFlow.java:logWarn(1516)) - [] '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 21:20:48,155 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] tez session mode enabled: true
2016-05-17 21:20:48,333 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 21:20:48,339 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-05-17 21:20:48,339 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-05-17 21:20:48,381 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C/.tez/application_1463520048338_0001 doesn't exist and is created
2016-05-17 21:20:48,447 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-05-17 21:20:48,447 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 21:20:48,448 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C/.tez/application_1463520048338_0001
2016-05-17 21:20:48,482 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1463520048338_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 21:20:48,522 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-05-17 21:20:48,537 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-05-17 21:20:48,548 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-05-17 21:20:48,548 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-05-17 21:20:48,548 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 21:20:48,561 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-05-17 21:20:48,565 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-05-17 21:20:48,568 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.4.x-tez-0.6.x/build/test/tmp/.staging/C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C/.tez/application_1463520048338_0001/localmode-log-dir
2016-05-17 21:20:48,569 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C/.tez/application_1463520048338_0001/localmode-log-dir/history.txt.appattempt_1463520048338_0001_000000, maxErrors=10
2016-05-17 21:20:48,569 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-05-17 21:20:48,571 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463520048338_0001_000000, appSubmitTime=1463520048464, launchTime=1463520048481
2016-05-17 21:20:48,576 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-05-17 21:20:48,577 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-17 21:20:48,580 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-05-17 21:20:48,580 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-05-17 21:20:48,638 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:39415
2016-05-17 21:20:48,648 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-05-17 21:20:48,648 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-05-17 21:20:48,648 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 21:20:48,677 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-05-17 21:20:48,743 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-05-17 21:20:48,743 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463520048338_0001_000000, startTime=1463520048742
2016-05-17 21:20:48,743 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-05-17 21:20:48,749 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-17 21:20:48,768 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-05-17 21:20:48,768 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...mpositeAssembly/composite, applicationId=application_1463520048338_0001, dagName=[C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C] null/(1/1) ...mpositeAssembly/composite
2016-05-17 21:20:49,014 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C] null/(1/1) ...mpositeAssembly/composite
2016-05-17 21:20:49,119 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1463520048338_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C/.tez/application_1463520048338_0001/localmode-log-dir/dag_1463520048338_0001_1.dot
2016-05-17 21:20:49,124 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C/.tez/application_1463520048338_0001/localmode-log-dir/dag_1463520048338_0001_1-tez-dag.pb.txt
2016-05-17 21:20:49,231 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463520048338_0001_1
2016-05-17 21:20:49,231 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:49,232 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C] null/(1/1) ...mpositeAssembly/composite
2016-05-17 21:20:49 Running Dag: dag_1463520048338_0001_1
2016-05-17 21:20:49,268 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-05-17 21:20:49,268 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463520048338_0001_1, submitTime=1463520049014
2016-05-17 21:20:49,302 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex FB1279D1728F47C7943818772B2862EA
2016-05-17 21:20:49,309 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-17 21:20:49,311 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-05-17 21:20:49,312 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463520048338_0001_1, initTime=1463520049270
2016-05-17 21:20:49,312 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463520048338_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-17 21:20:49,314 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-05-17 21:20:49,314 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:DAG_STARTED]: dagID=dag_1463520048338_0001_1, startTime=1463520049313
2016-05-17 21:20:49,315 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-05-17 21:20:49,316 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463520048338_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-17 21:20:49,317 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: DA7B235D7B0E4EB18615E170B916605F : {D01257236B1E46E2A3B6596791DF3766={InputName=D01257236B1E46E2A3B6596791DF3766}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-17 21:20:49,317 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: D01257236B1E46E2A3B6596791DF3766, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-17 21:20:49,318 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:49,324 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...mpositeAssembly/composite, applicationId=application_1463520048338_0001, dagName=[C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C] null/(1/1) ...mpositeAssembly/composite
2016-05-17 21:20:49,325 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:49,325 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:49,328 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]. Starting root input initializers: 1
2016-05-17 21:20:49,338 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: D01257236B1E46E2A3B6596791DF3766 on vertex vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:49,348 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-17 21:20:49,351 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:49,373 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] submitted tez dag to app master: application_1463520048338_0001, with dag id: dag_1463520048338_0001_1
2016-05-17 21:20:49,379 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-05-17 21:20:49,382 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input D01257236B1E46E2A3B6596791DF3766 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-05-17 21:20:49,384 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-05-17 21:20:49,384 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-05-17 21:20:49,388 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 21:20:49,389 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:49,409 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:49,411 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:49,412 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=0E0D80A4DBF94A0DB9524BB3B5C6634E, vertexId=vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-17 21:20:49,416 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=0E0D80A4DBF94A0DB9524BB3B5C6634E, vertexId=vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:49,434 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=0E0D80A4DBF94A0DB9524BB3B5C6634E, vertexName=FB1279D1728F47C7943818772B2862EA, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-17 21:20:49,436 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 408
2016-05-17 21:20:49,438 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: D01257236B1E46E2A3B6596791DF3766 on vertex vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:49,446 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=0E0D80A4DBF94A0DB9524BB3B5C6634E, vertexId=vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:49,449 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 21:20:49,449 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:VERTEX_INITIALIZED]: vertexName=FB1279D1728F47C7943818772B2862EA, vertexId=vertex_1463520048338_0001_1_01, initRequestedTime=1463520049349, initedTime=1463520049448, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-05-17 21:20:49,450 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA] transitioned from NEW to INITED due to event V_INIT
2016-05-17 21:20:49,451 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 21:20:49,451 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {D01257236B1E46E2A3B6596791DF3766=forAllWorkUnits=true, update=[1]}
2016-05-17 21:20:49,452 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] parallelism set to 1
2016-05-17 21:20:49,453 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 21:20:49,465 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463520048338_0001_1_00, eventCount=1
2016-05-17 21:20:49,466 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 21:20:49,466 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:VERTEX_INITIALIZED]: vertexName=DA7B235D7B0E4EB18615E170B916605F, vertexId=vertex_1463520048338_0001_1_00, initRequestedTime=1463520049317, initedTime=1463520049466, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-05-17 21:20:49,467 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] with distanceFromRoot: 0
2016-05-17 21:20:49,468 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-05-17 21:20:49,469 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:49,469 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:49,472 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 21:20:49,472 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463520048338_0001_1_00, startRequestedTime=1463520049468, startedTime=1463520049468
2016-05-17 21:20:49,473 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] transitioned from INITED to RUNNING due to event V_START
2016-05-17 21:20:49,496 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 21:20:49,496 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:TASK_STARTED]: vertexName=DA7B235D7B0E4EB18615E170B916605F, taskId=task_1463520048338_0001_1_00_000000, scheduledTime=1463520049495, launchTime=1463520049495
2016-05-17 21:20:49,497 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520048338_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 21:20:49,497 INFO  impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1463520048338_0001_1_00 for vertex: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA] numStartedSources: 1 numSources: 1
2016-05-17 21:20:49,498 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA] with distanceFromRoot: 1
2016-05-17 21:20:49,503 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:49,508 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: DA7B235D7B0E4EB18615E170B916605F in vertex: FB1279D1728F47C7943818772B2862EA
2016-05-17 21:20:49,512 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: FB1279D1728F47C7943818772B2862EA with 1 source tasks and 1 pending tasks
2016-05-17 21:20:49,513 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 21:20:49,513 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463520048338_0001_1_01, startRequestedTime=1463520049504, startedTime=1463520049504
2016-05-17 21:20:49,513 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA] transitioned from INITED to RUNNING due to event V_START
2016-05-17 21:20:49,516 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C] null/(1/1) ...mpositeAssembly/composite, VertexName: DA7B235D7B0E4EB18615E170B916605F, VertexParallelism: 1, TaskAttemptID:attempt_1463520048338_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D01257236B1E46E2A3B6596791DF3766, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=FB1279D1728F47C7943818772B2862EA, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 21:20:49,518 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520048338_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 21:20:49,518 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 21:20:49,594 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-05-17 21:20:49,597 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-05-17 21:20:49,598 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-05-17 21:20:49,601 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463520048338_0001_00_000001
2016-05-17 21:20:49,602 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 21:20:49,610 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1463520048338_0001_00_000001
2016-05-17 21:20:49,610 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-05-17 21:20:49,616 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 21:20:49,617 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 21:20:49,617 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463520048338_0001_00_000001, launchTime=1463520049616
2016-05-17 21:20:49,620 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463520048338_0001_00_000001
2016-05-17 21:20:49,625 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463520048338_0001_1_00_000000_0] to container: [container_1463520048338_0001_00_000001]
2016-05-17 21:20:49,625 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 21:20:49,626 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463520048338_0001_00_000001 given task: attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:49,626 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463520048338_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:49 Starting to run new task attempt: attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:49,627 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:49,627 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:49,628 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463520048338_0001_1_00_000000_0] started. Is using containerId: [container_1463520048338_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-17 21:20:49,630 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 21:20:49,628 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 21:20:49,630 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 21:20:49,631 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=DA7B235D7B0E4EB18615E170B916605F, taskAttemptId=attempt_1463520048338_0001_1_00_000000_0, startTime=1463520049626, containerId=container_1463520048338_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463520048338_0001_00_000001/teamcity, completedLogs=
2016-05-17 21:20:49,631 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 21:20:49,631 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520048338_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 21:20:49,632 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 21:20:49,633 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 21:20:49,635 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520048338_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 21:20:49,659 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-05-17 21:20:49,659 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C] null/(1/1) ...mpositeAssembly/composite, VertexName: DA7B235D7B0E4EB18615E170B916605F, VertexParallelism: 1, TaskAttemptID:attempt_1463520048338_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D01257236B1E46E2A3B6596791DF3766, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=FB1279D1728F47C7943818772B2862EA, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 21:20:49,662 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 21:20:49,669 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:49,669 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 21:20:49,669 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:49,674 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=D01257236B1E46E2A3B6596791DF3766, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-05-17 21:20:49,674 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463520048338_0001_1_00_000000_0 sent events: (0-1)
2016-05-17 21:20:49,675 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:49,677 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=FB1279D1728F47C7943818772B2862EA, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-05-17 21:20:49,678 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 21:20:49,679 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 21:20:49,679 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: D01257236B1E46E2A3B6596791DF3766
2016-05-17 21:20:49,682 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: D01257236B1E46E2A3B6596791DF3766
2016-05-17 21:20:49,689 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: FB1279D1728F47C7943818772B2862EA
2016-05-17 21:20:49,694 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 21:20:49,694 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-05-17 21:20:49,696 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: D01257236B1E46E2A3B6596791DF3766
2016-05-17 21:20:49,696 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: D01257236B1E46E2A3B6596791DF3766
2016-05-17 21:20:49,702 INFO  impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-05-17 21:20:49,702 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: FB1279D1728F47C7943818772B2862EA
2016-05-17 21:20:49,703 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: FB1279D1728F47C7943818772B2862EA
2016-05-17 21:20:49,713 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: DA7B235D7B0E4EB18615E170B916605F, ordinal: 0
2016-05-17 21:20:49,713 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: DA7B235D7B0E4EB18615E170B916605F, mem on start (mb), free: 246, total: 281, max: 672
2016-05-17 21:20:49,714 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:49,714 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 21:20:49,714 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 21:20:49,714 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 21:20:49,716 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 21:20:49,722 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-05-17 21:20:49,723 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 21:20:49,723 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-05-17 21:20:49,723 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 21:20:49,724 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 21:20:49,724 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, D01257236B1E46E2A3B6596791DF3766, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-05-17 21:20:49,724 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, FB1279D1728F47C7943818772B2862EA, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-05-17 21:20:49,724 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 21:20:49,725 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: D01257236B1E46E2A3B6596791DF3766 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 21:20:49,725 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: D01257236B1E46E2A3B6596791DF3766
2016-05-17 21:20:49,725 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 21:20:49,725 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 21:20:49,726 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: D01257236B1E46E2A3B6596791DF3766
2016-05-17 21:20:49,726 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 21:20:49,726 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 21:20:49,729 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:49,730 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-05-17 21:20:49,742 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@1fa2fc5f
2016-05-17 21:20:49,759 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@1fa2fc5f
2016-05-17 21:20:49,760 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-05-17 21:20:49,761 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-05-17 21:20:49,769 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-05-17 21:20:49,812 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt"] streamed: true, id: D01257236B1E46E2A3B6596791DF3766
2016-05-17 21:20:49,812 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'ip']], id: 85B858DC8DF948DEBBEDBB3FD99F98B2
2016-05-17 21:20:49,813 INFO  element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'ip']] 85B858DC8DF948DEBBEDBB3FD99F98B2
2016-05-17 21:20:49,857 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.KeyTupleSerializer@27a464d7; valueSerializer=cascading.tuple.hadoop.io.ValueTupleSerializer@19d87396; comparator=cascading.tuple.hadoop.util.TupleComparator@61bf1c70; 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 21:20:49,861 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-05-17 21:20:49,864 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-05-17 21:20:49,864 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 21:20:49,981 INFO  dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-05-17 21:20:49,981 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-05-17 21:20:49,981 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-05-17 21:20:49,981 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-05-17 21:20:49,981 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-05-17 21:20:49,983 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-05-17 21:20:49,984 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 21:20:49,986 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: DA7B235D7B0E4EB18615E170B916605F, all 1 inputs ready in: 00:00:00.001
2016-05-17 21:20:49,994 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:49,994 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: DA7B235D7B0E4EB18615E170B916605F, mem on close (mb), free: 135, total: 281, max: 672
2016-05-17 21:20:49,994 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-05-17 21:20:49,994 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-05-17 21:20:49,994 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2016-05-17 21:20:49,995 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-05-17 21:20:50,010 INFO  dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-05-17 21:20:50 Completed running task attempt: attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:50,029 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463520048338_0001_1_00_000000_0, fatalErrorOccurred=false
2016-05-17 21:20:50,030 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463520048338_0001_1_00, eventCount=1
2016-05-17 21:20:50,031 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 21:20:50,038 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 28 [[org.apache.tez.common.counters.DAGCounter RACK_LOCAL_TASKS=1][File System Counters FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=756, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, 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=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0][cascading.flow.SliceCounters Process_Begin_Time=1463520049986, Process_Duration=8, Process_End_Time=1463520049994, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1][cascading.flow.StepCounters Tuples_Read=10]]
2016-05-17 21:20:50,039 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=DA7B235D7B0E4EB18615E170B916605F, taskAttemptId=attempt_1463520048338_0001_1_00_000000_0, startTime=1463520049626, finishTime=1463520050030, timeTaken=404, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=756, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, 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=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463520049986, Process_Duration=8, Process_End_Time=1463520049994, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-05-17 21:20:50,040 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-05-17 21:20:50,040 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:50,041 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520048338_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 21:20:50,042 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463520048338_0001_00_000001
2016-05-17 21:20:50,042 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 21:20:50,043 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:50,046 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 21:20:50,048 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:TASK_FINISHED]: vertexName=DA7B235D7B0E4EB18615E170B916605F, taskId=task_1463520048338_0001_1_00_000000, startTime=1463520049626, finishTime=1463520050045, timeTaken=419, status=SUCCEEDED, successfulAttemptID=attempt_1463520048338_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=2206, FILE_BYTES_WRITTEN=756, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, 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=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463520049986, Process_Duration=8, Process_End_Time=1463520049994, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-05-17 21:20:50,049 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520048338_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 21:20:50,050 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 21:20:50,051 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] : 1
2016-05-17 21:20:50,051 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:50,058 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 21:20:50,061 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:VERTEX_FINISHED]: vertexName=DA7B235D7B0E4EB18615E170B916605F, vertexId=vertex_1463520048338_0001_1_00, initRequestedTime=1463520049317, initedTime=1463520049466, startRequestedTime=1463520049468, startedTime=1463520049468, finishTime=1463520050051, timeTaken=583, status=SUCCEEDED, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=756, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, 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=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463520049986, Process_Duration=8, Process_End_Time=1463520049994, Read_Duration=1, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1463520049626, firstTasksToStart=[ task_1463520048338_0001_1_00_000000 ], lastTaskFinishTime=1463520050030, lastTasksToFinish=[ task_1463520048338_0001_1_00_000000 ], minTaskDuration=404, maxTaskDuration=404, avgTaskDuration=404.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463520048338_0001_1_00_000000 ], longestDurationTasks=[ task_1463520048338_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 21:20:50,062 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 21:20:50,064 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 21:20:50,066 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463520048338_0001_00_000001, stoppedTime=1463520050063, exitStatus=0
2016-05-17 21:20:50,067 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 21:20:50,067 INFO  impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA] attempt: attempt_1463520048338_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-17 21:20:50,067 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: FB1279D1728F47C7943818772B2862EA
2016-05-17 21:20:50,068 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:50,069 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-17 21:20:50,070 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1463520048338_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-17 21:20:50,070 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:TASK_STARTED]: vertexName=FB1279D1728F47C7943818772B2862EA, taskId=task_1463520048338_0001_1_01_000000, scheduledTime=1463520050070, launchTime=1463520050070
2016-05-17 21:20:50,070 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520048338_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 21:20:50,071 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000001 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-05-17 21:20:50,071 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:50,071 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 21:20:50,072 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C] null/(1/1) ...mpositeAssembly/composite, VertexName: FB1279D1728F47C7943818772B2862EA, VertexParallelism: 1, TaskAttemptID:attempt_1463520048338_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=DA7B235D7B0E4EB18615E170B916605F, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=0E0D80A4DBF94A0DB9524BB3B5C6634E, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 21:20:50,072 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520048338_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 21:20:50,073 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 21:20:50,073 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463520048338_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-17 21:20:50,073 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463520048338_0001_00_000001: 31 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 21:20:50,073 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463520048338_0001_00_000001, Exiting
2016-05-17 21:20:50,074 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463520048338_0001_00_000001
2016-05-17 21:20:50,074 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463520048338_0001_00_000001
2016-05-17 21:20:50,078 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463520048338_0001_00_000002
2016-05-17 21:20:50,078 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 21:20:50,081 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463520048338_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 21:20:50,081 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463520048338_0001_00_000001 completed successfully
2016-05-17 21:20:50,082 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000001 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-05-17 21:20:50,083 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1463520048338_0001_00_000002
2016-05-17 21:20:50,084 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-teztask.properties,hadoop-metrics2.properties
2016-05-17 21:20:50,087 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 21:20:50,087 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 21:20:50,088 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463520048338_0001_00_000002, launchTime=1463520050086
2016-05-17 21:20:50,089 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463520048338_0001_00_000002
2016-05-17 21:20:50,095 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463520048338_0001_1_01_000000_0] to container: [container_1463520048338_0001_00_000002]
2016-05-17 21:20:50,095 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 21:20:50,096 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463520048338_0001_1_01_000000_0] started. Is using containerId: [container_1463520048338_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-17 21:20:50,096 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 21:20:50,096 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=FB1279D1728F47C7943818772B2862EA, taskAttemptId=attempt_1463520048338_0001_1_01_000000_0, startTime=1463520050095, containerId=container_1463520048338_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463520048338_0001_00_000002/teamcity, completedLogs=
2016-05-17 21:20:50,096 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520048338_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 21:20:50,097 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520048338_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 21:20:50,097 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463520048338_0001_00_000002 given task: attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,097 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463520048338_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50 Starting to run new task attempt: attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,097 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,098 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:50,098 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 21:20:50,098 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 21:20:50,098 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 21:20:50,098 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 21:20:50,098 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-05-17 21:20:50,100 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C] null/(1/1) ...mpositeAssembly/composite, VertexName: FB1279D1728F47C7943818772B2862EA, VertexParallelism: 1, TaskAttemptID:attempt_1463520048338_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=DA7B235D7B0E4EB18615E170B916605F, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=0E0D80A4DBF94A0DB9524BB3B5C6634E, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 21:20:50,100 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 21:20:50,100 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,102 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 21:20:50,102 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:50,101 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463520048338_0001_1_01_000000_0 sent events: (0-1)
2016-05-17 21:20:50,103 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=DA7B235D7B0E4EB18615E170B916605F, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-05-17 21:20:50,104 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 21:20:50,104 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:50,104 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=0E0D80A4DBF94A0DB9524BB3B5C6634E, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-05-17 21:20:50,105 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 21:20:50,105 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 0E0D80A4DBF94A0DB9524BB3B5C6634E
2016-05-17 21:20:50,106 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-05-17 21:20:50,106 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 0E0D80A4DBF94A0DB9524BB3B5C6634E
2016-05-17 21:20:50,110 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:50,110 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 21:20:50,123 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-05-17 21:20:50,123 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-05-17 21:20:50,124 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:50,125 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:50,129 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: FB1279D1728F47C7943818772B2862EA, ordinal: 1
2016-05-17 21:20:50,129 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FB1279D1728F47C7943818772B2862EA, mem on start (mb), free: 123, total: 281, max: 672
2016-05-17 21:20:50,130 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:50,130 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 21:20:50,130 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 21:20:50,140 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-05-17 21:20:50,140 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 0E0D80A4DBF94A0DB9524BB3B5C6634E
2016-05-17 21:20:50,141 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 21:20:50,141 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 21:20:50,141 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-05-17 21:20:50,142 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 21:20:50,142 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-05-17 21:20:50,142 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 21:20:50,143 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 21:20:50,143 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 0E0D80A4DBF94A0DB9524BB3B5C6634E, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-05-17 21:20:50,143 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, DA7B235D7B0E4EB18615E170B916605F, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=472110858
2016-05-17 21:20:50,144 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 21:20:50,144 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:50,145 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: DA7B235D7B0E4EB18615E170B916605F being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 21:20:50,145 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 21:20:50,145 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 21:20:50,153 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 21:20:50,153 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-05-17 21:20:50,156 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: DA7B235D7B0E4EB18615E170B916605F with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-05-17 21:20:50,159 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=472110858. Updated to: ShuffleMem=472110858, postMergeMem: 0
2016-05-17 21:20:50,159 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=472110858, maxSingleShuffleLimit=118027712, mergeThreshold=424899744, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-05-17 21:20:50,164 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-05-17 21:20:50,167 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:50,168 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 21:20:50,171 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,173 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_1463520048338_0001_1_00_000000_0_10003, runDuration: 323986, ]
2016-05-17 21:20:50,179 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'ip']]
2016-05-17 21:20:50,183 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1463520048338_0001_1_00_000000_0_10003] to DISK_DIRECT, CompressedSize=204, DecompressedSize=200,EndTime=1463520050183, TimeTaken=3, Rate=0.06 MB/s
2016-05-17 21:20:50,184 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:50,185 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-17 21:20:50,186 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-123-148-208:0 freed by fetcher [DA7B235D7B0E4EB18615E170B916605F] #1 in 7ms
2016-05-17 21:20:50,186 INFO  orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [DA7B235D7B0E4EB18615E170B916605F] #1, status:false, isInterrupted:false
2016-05-17 21:20:50,187 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-17 21:20:50,194 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 204 bytes from disk
2016-05-17 21:20:50,194 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 21:20:50,195 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'ip']] streamed: true, id: 85B858DC8DF948DEBBEDBB3FD99F98B2
2016-05-17 21:20:50,195 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite"], id: 0E0D80A4DBF94A0DB9524BB3B5C6634E
2016-05-17 21:20:50,196 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite"]
2016-05-17 21:20:50,198 INFO  element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'ip']] 85B858DC8DF948DEBBEDBB3FD99F98B2, for 1 inputs
2016-05-17 21:20:50,199 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-05-17 21:20:50,202 INFO  impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 175 bytes
2016-05-17 21:20:50,202 INFO  orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:50,203 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: FB1279D1728F47C7943818772B2862EA, all 1 inputs ready in: 00:00:00.003
2016-05-17 21:20:50,203 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-05-17 21:20:50,209 INFO  common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.KeyTupleDeserializer@16c05b8c; valueDeserializer=cascading.tuple.hadoop.io.ValueTupleDeserializer@2eba4fff
2016-05-17 21:20:50,217 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-05-17 21:20:50,220 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-05-17 21:20:50,222 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,223 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1463520048338_0001_1_01_000000_0 given a go for committing the task output.
2016-05-17 21:20:50,224 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,224 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: FB1279D1728F47C7943818772B2862EA, mem on close (mb), free: 116, total: 281, max: 672
2016-05-17 21:20:50,224 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: DA7B235D7B0E4EB18615E170B916605F
2016-05-17 21:20:50,225 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-05-17 21:20:50,226 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-05-17 21:20:50,226 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 21:20:50,226 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-05-17 21:20:50,227 INFO  impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-05-17 21:20:50 Completed running task attempt: attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,229 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463520048338_0001_1_01_000000_0, fatalErrorOccurred=false
2016-05-17 21:20:50,232 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 21:20:50,235 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=FB1279D1728F47C7943818772B2862EA, taskAttemptId=attempt_1463520048338_0001_1_01_000000_0, startTime=1463520050095, finishTime=1463520050231, timeTaken=136, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=32, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26, 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=1463520050204, Process_Duration=20, Process_End_Time=1463520050224, Read_Duration=4, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-05-17 21:20:50,235 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520048338_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 21:20:50,236 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 21:20:50,237 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50,240 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 21:20:50,240 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:TASK_FINISHED]: vertexName=FB1279D1728F47C7943818772B2862EA, taskId=task_1463520048338_0001_1_01_000000, startTime=1463520050095, finishTime=1463520050237, timeTaken=142, status=SUCCEEDED, successfulAttemptID=attempt_1463520048338_0001_1_01_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=32, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26, 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=1463520050204, Process_Duration=20, Process_End_Time=1463520050224, Read_Duration=4, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-05-17 21:20:50,242 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520048338_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 21:20:50,242 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA] : 1
2016-05-17 21:20:50,243 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:50,245 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 21:20:50,245 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=32, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26][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=1463520050204, Process_Duration=20, Process_End_Time=1463520050224, Read_Duration=4, Tuples_Read=10, Tuples_Written=8, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=8]]
2016-05-17 21:20:50,245 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-05-17 21:20:50,246 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:50,248 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463520048338_0001_00_000002
2016-05-17 21:20:50,248 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:VERTEX_FINISHED]: vertexName=FB1279D1728F47C7943818772B2862EA, vertexId=vertex_1463520048338_0001_1_01, initRequestedTime=1463520049349, initedTime=1463520049448, startRequestedTime=1463520049504, startedTime=1463520049504, finishTime=1463520050243, timeTaken=739, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=295174144, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=32, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26, 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=1463520050204, Process_Duration=20, Process_End_Time=1463520050224, Read_Duration=4, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8, vertexStats=firstTaskStartTime=1463520050095, firstTasksToStart=[ task_1463520048338_0001_1_01_000000 ], lastTaskFinishTime=1463520050231, lastTasksToFinish=[ task_1463520048338_0001_1_01_000000 ], minTaskDuration=136, maxTaskDuration=136, avgTaskDuration=136.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463520048338_0001_1_01_000000 ], longestDurationTasks=[ task_1463520048338_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 21:20:50,249 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 21:20:50,249 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 21:20:50,250 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463520048338_0001_00_000002, stoppedTime=1463520050250, exitStatus=0
2016-05-17 21:20:50,250 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 21:20:50,250 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 21:20:50,250 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-17 21:20:50,251 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1463520048338_0001_1
2016-05-17 21:20:50,256 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463520048338_0001_1
2016-05-17 21:20:50,256 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 0E0D80A4DBF94A0DB9524BB3B5C6634E for vertex: vertex_1463520048338_0001_1_01 [FB1279D1728F47C7943818772B2862EA]
2016-05-17 21:20:50,259 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463520048338_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-17 21:20:50,259 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463520048338_0001_00_000002: 10 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 21:20:50,259 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463520048338_0001_00_000002, Exiting
2016-05-17 21:20:50,260 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463520048338_0001_00_000002
2016-05-17 21:20:50,260 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463520048338_0001_00_000002
2016-05-17 21:20:50,261 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463520048338_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 21:20:50,262 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463520048338_0001_00_000002 completed successfully
2016-05-17 21:20:50,270 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1463520048338_0001_1_00 [DA7B235D7B0E4EB18615E170B916605F]
2016-05-17 21:20:50,276 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1463520048338_0001_1, queueSize=0
2016-05-17 21:20:50,276 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-05-17 21:20:50,277 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520048338_0001_1][Event:DAG_FINISHED]: dagId=dag_1463520048338_0001_1, startTime=1463520049313, finishTime=1463520050270, timeTaken=957, 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=2442, FILE_BYTES_WRITTEN=896, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=590348288, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=18, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=32, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=26, LAST_EVENT_RECEIVED=26, 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=2927040100190, Process_Duration=28, Process_End_Time=2927040100218, Read_Duration=5, Tuples_Read=20, Tuples_Written=18, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=8
2016-05-17 21:20:50,277 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1463520048338_0001_1 finished with state: SUCCEEDED
2016-05-17 21:20:50,278 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463520048338_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-05-17 21:20:50,278 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520048338_0001_00_000002 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-05-17 21:20:50,278 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1463520048338_0001_00_000002
2016-05-17 21:20:50 Completed Dag: dag_1463520048338_0001_1
2016-05-17 21:20:50,279 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1463520048338_0001_1, dagState=SUCCEEDED
2016-05-17 21:20:50,279 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463520048338_0001_1_post
2016-05-17 21:20:50,279 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:50,279 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-05-17 21:20:50,289 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...mpositeAssembly/composite, applicationId=application_1463520048338_0001
2016-05-17 21:20:50,294 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-05-17 21:20:50,294 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-05-17 21:20:50,295 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-05-17 21:20:50,295 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-05-17 21:20:50,295 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-05-17 21:20:50,296 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-05-17 21:20:50,298 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-05-17 21:20:50,298 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-05-17 21:20:50,299 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-05-17 21:20:50,299 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-05-17 21:20:50,299 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-05-17 21:20:50,299 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-17 21:20:50,300 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-17 21:20:50,305 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.4.x-tez-0.6.x/build/test/tmp/.staging/C6141635A95C4E69881DF349FF956A16/A3DC886F1B5048A4A5AF28DB678C136C/.tez/application_1463520048338_0001
2016-05-17 21:20:50,306 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite/_temporary
2016-05-17 21:20:50,307 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  completed in: 00:02.176
2016-05-17 21:20:50,353 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite
2016-05-17 21:20:50,387 INFO  util.Util (Util.java:findMainClass(1374)) - using default application jar, may cause class not found exceptions on the cluster
2016-05-17 21:20:50,388 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 21:20:50,461 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.037
2016-05-17 21:20:50,494 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.070
2016-05-17 21:20:50,495 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-17 21:20:50,496 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-05-17 21:20:50,496 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-05-17 21:20:50,519 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt
2016-05-17 21:20:50,536 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple
2016-05-17 21:20:50,615 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting
2016-05-17 21:20:50,616 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-05-17 21:20:50,616 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  sink: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple"]
2016-05-17 21:20:50,616 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  parallel execution of steps is enabled: false
2016-05-17 21:20:50,617 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  executing total steps: 1
2016-05-17 21:20:50,617 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  allocating management threads: 1
2016-05-17 21:20:50,617 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] starting step: (1/1) ...testSimpleAssembly/simple
2016-05-17 21:20:50,618 WARN  flow.Flow (BaseFlow.java:logWarn(1516)) - [] '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 21:20:50,632 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] tez session mode enabled: true
2016-05-17 21:20:50,638 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 21:20:50,638 INFO  client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-05-17 21:20:50,638 INFO  client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since  'tez.ignore.lib.uris' is set to true
2016-05-17 21:20:50,650 INFO  client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269/.tez/application_1463520050638_0001 doesn't exist and is created
2016-05-17 21:20:50,675 INFO  client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-05-17 21:20:50,675 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-05-17 21:20:50,676 INFO  client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269/.tez/application_1463520050638_0001
2016-05-17 21:20:50,680 INFO  app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1463520050638_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 21:20:50,697 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-05-17 21:20:50,699 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-05-17 21:20:50,702 INFO  node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-05-17 21:20:50,702 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-05-17 21:20:50,703 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.4.x-tez-0.6.x/build/test/tmp/.staging/CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269/.tez/application_1463520050638_0001/localmode-log-dir
2016-05-17 21:20:50,703 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269/.tez/application_1463520050638_0001/localmode-log-dir/history.txt.appattempt_1463520050638_0001_000000, maxErrors=10
2016-05-17 21:20:50,703 INFO  recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-05-17 21:20:50,704 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1463520050638_0001_000000, appSubmitTime=1463520050679, launchTime=1463520050680
2016-05-17 21:20:50,708 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-05-17 21:20:50,711 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-05-17 21:20:50,713 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-05-17 21:20:50,716 INFO  recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-05-17 21:20:50,716 INFO  client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-123-148-208.ec2.internal/10.123.148.208:57160
2016-05-17 21:20:50,718 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-05-17 21:20:50,720 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-05-17 21:20:50,720 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1463520050638_0001_000000, startTime=1463520050720
2016-05-17 21:20:50,721 INFO  app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-05-17 21:20:50,776 INFO  client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-05-17 21:20:50,776 INFO  client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-05-17 21:20:50,777 INFO  client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...testSimpleAssembly/simple, applicationId=application_1463520050638_0001, dagName=[CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269] null/(1/1) ...testSimpleAssembly/simple
2016-05-17 21:20:50,811 INFO  app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269] null/(1/1) ...testSimpleAssembly/simple
2016-05-17 21:20:50,852 INFO  app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1463520050638_0001_1, filePath=/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269/.tez/application_1463520050638_0001/localmode-log-dir/dag_1463520050638_0001_1.dot
2016-05-17 21:20:50,855 INFO  app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/tmp/.staging/CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269/.tez/application_1463520050638_0001/localmode-log-dir/dag_1463520050638_0001_1-tez-dag.pb.txt
2016-05-17 21:20:50,886 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463520050638_0001_1
2016-05-17 21:20:50,886 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:50,886 INFO  app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269] null/(1/1) ...testSimpleAssembly/simple
2016-05-17 21:20:50 Running Dag: dag_1463520050638_0001_1
2016-05-17 21:20:50,901 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-05-17 21:20:50,902 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1463520050638_0001_1, submitTime=1463520050811
2016-05-17 21:20:50,903 INFO  impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex F0F68A8E6A8644DA8BB31ECE89CEAA22
2016-05-17 21:20:50,904 INFO  impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-05-17 21:20:50,904 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-05-17 21:20:50,904 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1463520050638_0001_1, initTime=1463520050902
2016-05-17 21:20:50,905 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463520050638_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-05-17 21:20:50,906 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:DAG_STARTED]: dagID=dag_1463520050638_0001_1, startTime=1463520050905
2016-05-17 21:20:50,906 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-05-17 21:20:50,906 INFO  impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-05-17 21:20:50,906 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463520050638_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-05-17 21:20:50,907 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: C221F1781E104FAA86526462B63DB46A : {6193E80609164E54BEA5A74B25271DC0={InputName=6193E80609164E54BEA5A74B25271DC0}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-05-17 21:20:50,907 INFO  impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 6193E80609164E54BEA5A74B25271DC0, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-05-17 21:20:50,907 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:50,907 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:50,907 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:50,908 INFO  impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]. Starting root input initializers: 1
2016-05-17 21:20:50,908 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] transitioned from NEW to INITIALIZING due to event V_INIT
2016-05-17 21:20:50,907 INFO  client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...testSimpleAssembly/simple, applicationId=application_1463520050638_0001, dagName=[CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269] null/(1/1) ...testSimpleAssembly/simple
2016-05-17 21:20:50,908 INFO  impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:50,908 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 6193E80609164E54BEA5A74B25271DC0 on vertex vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:50,915 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-05-17 21:20:50,916 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 6193E80609164E54BEA5A74B25271DC0 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-05-17 21:20:50,918 INFO  common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-05-17 21:20:50,918 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-05-17 21:20:50,921 INFO  hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 408
2016-05-17 21:20:50,922 INFO  dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 6193E80609164E54BEA5A74B25271DC0 on vertex vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:50,926 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 21:20:50,926 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:50,929 INFO  impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:50,930 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:50,930 INFO  impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=E6733693E389481F982523B018FD483A, vertexId=vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-05-17 21:20:50,931 INFO  impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=E6733693E389481F982523B018FD483A, vertexId=vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:50,939 INFO  committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=E6733693E389481F982523B018FD483A, vertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-05-17 21:20:50,940 INFO  impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=E6733693E389481F982523B018FD483A, vertexId=vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:50,940 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - [] submitted tez dag to app master: application_1463520050638_0001, with dag id: dag_1463520050638_0001_1
2016-05-17 21:20:50,947 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 21:20:50,947 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:VERTEX_INITIALIZED]: vertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, vertexId=vertex_1463520050638_0001_1_01, initRequestedTime=1463520050908, initedTime=1463520050947, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-05-17 21:20:50,948 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22] transitioned from NEW to INITED due to event V_INIT
2016-05-17 21:20:50,948 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 21:20:50,949 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {6193E80609164E54BEA5A74B25271DC0=forAllWorkUnits=true, update=[1]}
2016-05-17 21:20:50,950 INFO  impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] parallelism set to 1
2016-05-17 21:20:50,950 INFO  impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-05-17 21:20:50,952 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463520050638_0001_1_00, eventCount=1
2016-05-17 21:20:50,954 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-05-17 21:20:50,955 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:VERTEX_INITIALIZED]: vertexName=C221F1781E104FAA86526462B63DB46A, vertexId=vertex_1463520050638_0001_1_00, initRequestedTime=1463520050906, initedTime=1463520050954, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-05-17 21:20:50,955 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] with distanceFromRoot: 0
2016-05-17 21:20:50,955 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-05-17 21:20:50,955 INFO  impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:50,956 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:50,957 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 21:20:50,957 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463520050638_0001_1_00, startRequestedTime=1463520050955, startedTime=1463520050955
2016-05-17 21:20:50,957 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] transitioned from INITED to RUNNING due to event V_START
2016-05-17 21:20:50,959 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 21:20:50,959 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:TASK_STARTED]: vertexName=C221F1781E104FAA86526462B63DB46A, taskId=task_1463520050638_0001_1_00_000000, scheduledTime=1463520050959, launchTime=1463520050959
2016-05-17 21:20:50,960 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520050638_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 21:20:50,961 INFO  impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1463520050638_0001_1_00 for vertex: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22] numStartedSources: 1 numSources: 1
2016-05-17 21:20:50,964 INFO  impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22] with distanceFromRoot: 1
2016-05-17 21:20:50,964 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:50,964 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: C221F1781E104FAA86526462B63DB46A in vertex: F0F68A8E6A8644DA8BB31ECE89CEAA22
2016-05-17 21:20:50,965 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: F0F68A8E6A8644DA8BB31ECE89CEAA22 with 1 source tasks and 1 pending tasks
2016-05-17 21:20:50,965 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-05-17 21:20:50,965 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1463520050638_0001_1_01, startRequestedTime=1463520050964, startedTime=1463520050964
2016-05-17 21:20:50,966 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22] transitioned from INITED to RUNNING due to event V_START
2016-05-17 21:20:50,968 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269] null/(1/1) ...testSimpleAssembly/simple, VertexName: C221F1781E104FAA86526462B63DB46A, VertexParallelism: 1, TaskAttemptID:attempt_1463520050638_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=6193E80609164E54BEA5A74B25271DC0, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 21:20:50,970 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520050638_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 21:20:50,970 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 21:20:50,971 INFO  node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-05-17 21:20:50,974 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-05-17 21:20:50,976 INFO  container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-05-17 21:20:50,976 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463520050638_0001_00_000001
2016-05-17 21:20:50,977 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 21:20:50,980 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1463520050638_0001_00_000001
2016-05-17 21:20:50,980 WARN  impl.MetricsSystemImpl (MetricsSystemImpl.java:init(144)) - DAGAppMaster metrics system already initialized!
2016-05-17 21:20:50,981 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 21:20:50,982 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 21:20:50,982 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463520050638_0001_00_000001, launchTime=1463520050982
2016-05-17 21:20:50,983 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463520050638_0001_00_000001
2016-05-17 21:20:50,984 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463520050638_0001_1_00_000000_0] to container: [container_1463520050638_0001_00_000001]
2016-05-17 21:20:50,984 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 21:20:50,985 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463520050638_0001_1_00_000000_0] started. Is using containerId: [container_1463520050638_0001_00_000001] on NM: [127.0.0.1:0]
2016-05-17 21:20:50,985 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=C221F1781E104FAA86526462B63DB46A, taskAttemptId=attempt_1463520050638_0001_1_00_000000_0, startTime=1463520050984, containerId=container_1463520050638_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463520050638_0001_00_000001/teamcity, completedLogs=
2016-05-17 21:20:50,985 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520050638_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 21:20:50,986 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463520050638_0001_00_000001 given task: attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:50,986 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520050638_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 21:20:50,986 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463520050638_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:50,986 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 21:20:50 Starting to run new task attempt: attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:50,987 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:50,987 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:50,987 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 21:20:50,987 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 21:20:50,987 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 21:20:50,987 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 21:20:50,988 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-05-17 21:20:50,988 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269] null/(1/1) ...testSimpleAssembly/simple, VertexName: C221F1781E104FAA86526462B63DB46A, VertexParallelism: 1, TaskAttemptID:attempt_1463520050638_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=6193E80609164E54BEA5A74B25271DC0, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-05-17 21:20:50,988 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 21:20:50,992 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:50,993 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 21:20:50,993 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:50,994 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=6193E80609164E54BEA5A74B25271DC0, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-05-17 21:20:50,995 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 21:20:50,995 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 6193E80609164E54BEA5A74B25271DC0
2016-05-17 21:20:50,995 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 6193E80609164E54BEA5A74B25271DC0
2016-05-17 21:20:50,994 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463520050638_0001_1_00_000000_0 sent events: (0-1)
2016-05-17 21:20:50,996 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-05-17 21:20:50,996 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:50,997 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 21:20:50,997 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: F0F68A8E6A8644DA8BB31ECE89CEAA22
2016-05-17 21:20:51,000 INFO  impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-05-17 21:20:51,001 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: F0F68A8E6A8644DA8BB31ECE89CEAA22
2016-05-17 21:20:51,002 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: F0F68A8E6A8644DA8BB31ECE89CEAA22
2016-05-17 21:20:51,004 INFO  input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-05-17 21:20:51,004 INFO  input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 6193E80609164E54BEA5A74B25271DC0
2016-05-17 21:20:51,005 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 6193E80609164E54BEA5A74B25271DC0
2016-05-17 21:20:51,007 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 21:20:51,014 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: C221F1781E104FAA86526462B63DB46A, ordinal: 0
2016-05-17 21:20:51,014 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: C221F1781E104FAA86526462B63DB46A, mem on start (mb), free: 249, total: 397, max: 672
2016-05-17 21:20:51,014 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:51,014 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 21:20:51,014 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 21:20:51,015 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 21:20:51,015 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 21:20:51,015 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-05-17 21:20:51,016 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 21:20:51,016 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-05-17 21:20:51,016 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 21:20:51,016 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 21:20:51,017 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 6193E80609164E54BEA5A74B25271DC0, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-05-17 21:20:51,017 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, F0F68A8E6A8644DA8BB31ECE89CEAA22, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-05-17 21:20:51,017 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 21:20:51,018 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 6193E80609164E54BEA5A74B25271DC0 being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 21:20:51,018 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 6193E80609164E54BEA5A74B25271DC0
2016-05-17 21:20:51,021 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 21:20:51,021 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 6193E80609164E54BEA5A74B25271DC0
2016-05-17 21:20:51,018 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 21:20:51,022 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 21:20:51,022 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 21:20:51,023 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:51,023 INFO  input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-05-17 21:20:51,024 INFO  input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@22f19b06
2016-05-17 21:20:51,025 INFO  lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@22f19b06
2016-05-17 21:20:51,025 INFO  input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-05-17 21:20:51,025 INFO  input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-05-17 21:20:51,030 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-05-17 21:20:51,031 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt"] streamed: true, id: 6193E80609164E54BEA5A74B25271DC0
2016-05-17 21:20:51,032 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'ip']], id: 7BAFE7C2CFA4442BB8FB8F46180237BA
2016-05-17 21:20:51,032 INFO  element.TezGroupGate (TezGroupGate.java:prepare(98)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'ip']] 7BAFE7C2CFA4442BB8FB8F46180237BA
2016-05-17 21:20:51,035 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.KeyTupleSerializer@5b389c59; valueSerializer=cascading.tuple.hadoop.io.ValueTupleSerializer@61a0c5d8; comparator=cascading.tuple.hadoop.util.TupleComparator@4494aed2; 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 21:20:51,035 INFO  impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-05-17 21:20:51,036 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-05-17 21:20:51,036 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 21:20:51,050 INFO  dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-05-17 21:20:51,050 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-05-17 21:20:51,050 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-05-17 21:20:51,050 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-05-17 21:20:51,051 INFO  dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-05-17 21:20:51,051 INFO  element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-05-17 21:20:51,052 INFO  input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-05-17 21:20:51,052 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: C221F1781E104FAA86526462B63DB46A, all 1 inputs ready in: 00:00:00.000
2016-05-17 21:20:51,055 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:51,055 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: C221F1781E104FAA86526462B63DB46A, mem on close (mb), free: 147, total: 397, max: 672
2016-05-17 21:20:51,055 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-05-17 21:20:51,055 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-05-17 21:20:51,055 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2016-05-17 21:20:51,055 INFO  dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-05-17 21:20:51,058 INFO  dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-05-17 21:20:51 Completed running task attempt: attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:51,062 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463520050638_0001_1_00_000000_0, fatalErrorOccurred=false
2016-05-17 21:20:51,063 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1463520050638_0001_1_00, eventCount=1
2016-05-17 21:20:51,063 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 27 [[File System Counters FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=236, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter SPILLED_RECORDS=10, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=416808960, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0][cascading.flow.SliceCounters Process_Begin_Time=1463520051052, Process_Duration=3, Process_End_Time=1463520051055, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=10]]
2016-05-17 21:20:51,065 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-05-17 21:20:51,066 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:51,066 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 21:20:51,066 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463520050638_0001_00_000001
2016-05-17 21:20:51,068 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=C221F1781E104FAA86526462B63DB46A, taskAttemptId=attempt_1463520050638_0001_1_00_000000_0, startTime=1463520050984, finishTime=1463520051066, timeTaken=82, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=236, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=416808960, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463520051052, Process_Duration=3, Process_End_Time=1463520051055, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10
2016-05-17 21:20:51,068 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520050638_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 21:20:51,068 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:51,069 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 21:20:51,072 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 21:20:51,072 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:TASK_FINISHED]: vertexName=C221F1781E104FAA86526462B63DB46A, taskId=task_1463520050638_0001_1_00_000000, startTime=1463520050984, finishTime=1463520051069, timeTaken=85, status=SUCCEEDED, successfulAttemptID=attempt_1463520050638_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=2206, FILE_BYTES_WRITTEN=236, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=416808960, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463520051052, Process_Duration=3, Process_End_Time=1463520051055, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10
2016-05-17 21:20:51,073 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520050638_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 21:20:51,073 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] : 1
2016-05-17 21:20:51,073 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:51,075 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 21:20:51,075 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:VERTEX_FINISHED]: vertexName=C221F1781E104FAA86526462B63DB46A, vertexId=vertex_1463520050638_0001_1_00, initRequestedTime=1463520050906, initedTime=1463520050954, startRequestedTime=1463520050955, startedTime=1463520050955, finishTime=1463520051073, timeTaken=118, status=SUCCEEDED, diagnostics=, counters=Counters: 28, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE_BYTES_READ=2206, FILE_BYTES_WRITTEN=236, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, SPILLED_RECORDS=10, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=416808960, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=10, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=0, ADDITIONAL_SPILL_COUNT=0, cascading.flow.SliceCounters, Process_Begin_Time=1463520051052, Process_Duration=3, Process_End_Time=1463520051055, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1463520050984, firstTasksToStart=[ task_1463520050638_0001_1_00_000000 ], lastTaskFinishTime=1463520051066, lastTasksToFinish=[ task_1463520050638_0001_1_00_000000 ], minTaskDuration=82, maxTaskDuration=82, avgTaskDuration=82.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463520050638_0001_1_00_000000 ], longestDurationTasks=[ task_1463520050638_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 21:20:51,076 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 21:20:51,076 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 21:20:51,076 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463520050638_0001_00_000001, stoppedTime=1463520051076, exitStatus=0
2016-05-17 21:20:51,076 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 21:20:51,077 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 21:20:51,077 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463520050638_0001_00_000001 is valid, but no longer registered, and will be killed
2016-05-17 21:20:51,077 INFO  impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22] attempt: attempt_1463520050638_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-05-17 21:20:51,078 INFO  vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: F0F68A8E6A8644DA8BB31ECE89CEAA22
2016-05-17 21:20:51,078 INFO  impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:51,078 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-17 21:20:51,078 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463520050638_0001_00_000001: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 21:20:51,079 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463520050638_0001_00_000001, Exiting
2016-05-17 21:20:51,079 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463520050638_0001_00_000001
2016-05-17 21:20:51,079 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463520050638_0001_00_000001
2016-05-17 21:20:51,080 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1463520050638_0001_00_000001. Relying on regular task shutdown for it to end
2016-05-17 21:20:51,081 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-05-17 21:20:51,081 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:TASK_STARTED]: vertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, taskId=task_1463520050638_0001_1_01_000000, scheduledTime=1463520051081, launchTime=1463520051081
2016-05-17 21:20:51,082 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520050638_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-05-17 21:20:51,082 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000001 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-05-17 21:20:51,082 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463520050638_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 21:20:51,082 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463520050638_0001_00_000001 completed successfully
2016-05-17 21:20:51,082 INFO  impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:51,083 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000001 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-05-17 21:20:51,083 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269] null/(1/1) ...testSimpleAssembly/simple, VertexName: F0F68A8E6A8644DA8BB31ECE89CEAA22, VertexParallelism: 1, TaskAttemptID:attempt_1463520050638_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=C221F1781E104FAA86526462B63DB46A, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=E6733693E389481F982523B018FD483A, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 21:20:51,084 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520050638_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-05-17 21:20:51,084 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-05-17 21:20:51,085 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1463520050638_0001_00_000002
2016-05-17 21:20:51,085 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-05-17 21:20:51,090 INFO  task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier:  null, container_1463520050638_0001_00_000002
2016-05-17 21:20:51,090 WARN  impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-teztask.properties,hadoop-metrics2.properties
2016-05-17 21:20:51,093 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-05-17 21:20:51,093 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-05-17 21:20:51,093 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1463520050638_0001_00_000002, launchTime=1463520051092
2016-05-17 21:20:51,094 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463520050638_0001_00_000002
2016-05-17 21:20:51,094 INFO  container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1463520050638_0001_1_01_000000_0] to container: [container_1463520050638_0001_00_000002]
2016-05-17 21:20:51,095 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-05-17 21:20:51,095 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1463520050638_0001_1_01_000000_0] started. Is using containerId: [container_1463520050638_0001_00_000002] on NM: [127.0.0.1:0]
2016-05-17 21:20:51,095 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-05-17 21:20:51,095 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, taskAttemptId=attempt_1463520050638_0001_1_01_000000_0, startTime=1463520051095, containerId=container_1463520050638_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1463520050638_0001_00_000002/teamcity, completedLogs=
2016-05-17 21:20:51,096 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520050638_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-05-17 21:20:51,096 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520050638_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-05-17 21:20:51,096 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1463520050638_0001_00_000002 given task: attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,097 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463520050638_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51 Starting to run new task attempt: attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,097 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,098 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:51,098 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-05-17 21:20:51,098 INFO  task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-05-17 21:20:51,099 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-05-17 21:20:51,099 INFO  task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-05-17 21:20:51,100 INFO  metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) -  Using ResourceCalculatorProcessTree : [ ]
2016-05-17 21:20:51,100 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269] null/(1/1) ...testSimpleAssembly/simple, VertexName: F0F68A8E6A8644DA8BB31ECE89CEAA22, VertexParallelism: 1, TaskAttemptID:attempt_1463520050638_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=C221F1781E104FAA86526462B63DB46A, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=E6733693E389481F982523B018FD483A, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-05-17 21:20:51,101 INFO  resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-05-17 21:20:51,102 INFO  task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,103 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-05-17 21:20:51,103 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:51,103 INFO  impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1463520050638_0001_1_01_000000_0 sent events: (0-1)
2016-05-17 21:20:51,105 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=C221F1781E104FAA86526462B63DB46A, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-05-17 21:20:51,105 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=E6733693E389481F982523B018FD483A, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-05-17 21:20:51,105 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:51,106 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-05-17 21:20:51,107 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:51,107 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-05-17 21:20:51,109 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: E6733693E389481F982523B018FD483A
2016-05-17 21:20:51,109 INFO  output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-05-17 21:20:51,109 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: E6733693E389481F982523B018FD483A
2016-05-17 21:20:51,111 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-05-17 21:20:51,111 INFO  orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-05-17 21:20:51,111 INFO  resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:51,113 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:51,122 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.1.0
2016-05-17 21:20:51,134 INFO  output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-05-17 21:20:51,134 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: E6733693E389481F982523B018FD483A
2016-05-17 21:20:51,142 INFO  tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: F0F68A8E6A8644DA8BB31ECE89CEAA22, ordinal: 1
2016-05-17 21:20:51,142 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: F0F68A8E6A8644DA8BB31ECE89CEAA22, mem on start (mb), free: 139, total: 397, max: 672
2016-05-17 21:20:51,143 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-05-17 21:20:51,143 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-05-17 21:20:51,143 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-05-17 21:20:51,144 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-05-17 21:20:51,144 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-05-17 21:20:51,145 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-05-17 21:20:51,145 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-05-17 21:20:51,145 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-05-17 21:20:51,146 INFO  resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-05-17 21:20:51,146 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 21:20:51,146 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, E6733693E389481F982523B018FD483A, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-05-17 21:20:51,147 INFO  resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, C221F1781E104FAA86526462B63DB46A, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=472110858
2016-05-17 21:20:51,147 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-05-17 21:20:51,147 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:51,147 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: C221F1781E104FAA86526462B63DB46A being auto started by the framework. Subsequent instances will not be auto-started
2016-05-17 21:20:51,148 INFO  common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-05-17 21:20:51,149 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-05-17 21:20:51,150 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: C221F1781E104FAA86526462B63DB46A with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-05-17 21:20:51,150 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=472110858. Updated to: ShuffleMem=472110858, postMergeMem: 0
2016-05-17 21:20:51,150 INFO  orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=472110858, maxSingleShuffleLimit=118027712, mergeThreshold=424899744, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-05-17 21:20:51,150 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-05-17 21:20:51,151 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-05-17 21:20:51,150 INFO  orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-05-17 21:20:51,156 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:51,156 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-05-17 21:20:51,157 INFO  task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,160 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_1463520050638_0001_1_00_000000_0_10009, runDuration: 63410, ]
2016-05-17 21:20:51,162 INFO  graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'ip']]
2016-05-17 21:20:51,163 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1463520050638_0001_1_00_000000_0_10009] to DISK_DIRECT, CompressedSize=204, DecompressedSize=200,EndTime=1463520051163, TimeTaken=2, Rate=0.10 MB/s
2016-05-17 21:20:51,163 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:51,163 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-05-17 21:20:51,164 INFO  orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-123-148-208:0 freed by fetcher [C221F1781E104FAA86526462B63DB46A] #2 in 4ms
2016-05-17 21:20:51,164 INFO  orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [C221F1781E104FAA86526462B63DB46A] #2, status:false, isInterrupted:false
2016-05-17 21:20:51,164 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-05-17 21:20:51,165 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 204 bytes from disk
2016-05-17 21:20:51,163 INFO  tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'ip']] streamed: true, id: 7BAFE7C2CFA4442BB8FB8F46180237BA
2016-05-17 21:20:51,165 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 21:20:51,166 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-05-17 21:20:51,166 INFO  impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 175 bytes
2016-05-17 21:20:51,166 INFO  orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:51,167 INFO  orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-05-17 21:20:51,167 INFO  tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple"], id: E6733693E389481F982523B018FD483A
2016-05-17 21:20:51,168 INFO  element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line' | long, String]->[ALL]]"]["/opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple"]
2016-05-17 21:20:51,168 INFO  element.TezGroupGate (TezGroupGate.java:prepare(90)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'ip']] 7BAFE7C2CFA4442BB8FB8F46180237BA, for 1 inputs
2016-05-17 21:20:51,168 INFO  tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: F0F68A8E6A8644DA8BB31ECE89CEAA22, all 1 inputs ready in: 00:00:00.000
2016-05-17 21:20:51,171 INFO  common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.KeyTupleDeserializer@726e1b6e; valueDeserializer=cascading.tuple.hadoop.io.ValueTupleDeserializer@1acb0d73
2016-05-17 21:20:51,173 INFO  output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-05-17 21:20:51,173 INFO  output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-05-17 21:20:51,174 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,174 INFO  impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1463520050638_0001_1_01_000000_0 given a go for committing the task output.
2016-05-17 21:20:51,175 INFO  task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,176 INFO  tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: F0F68A8E6A8644DA8BB31ECE89CEAA22, mem on close (mb), free: 135, total: 397, max: 672
2016-05-17 21:20:51,176 INFO  orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: C221F1781E104FAA86526462B63DB46A
2016-05-17 21:20:51,176 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-05-17 21:20:51,177 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-05-17 21:20:51,177 INFO  orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-05-17 21:20:51,177 INFO  impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-05-17 21:20:51,177 INFO  impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-05-17 21:20:51 Completed running task attempt: attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,181 INFO  task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1463520050638_0001_1_01_000000_0, fatalErrorOccurred=false
2016-05-17 21:20:51,182 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-05-17 21:20:51,184 INFO  runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0][org.apache.tez.common.counters.TaskCounter REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=416808960, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=15, MERGE_PHASE_TIME=17, FIRST_EVENT_RECEIVED=11, LAST_EVENT_RECEIVED=11][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=1463520051169, Process_Duration=6, Process_End_Time=1463520051175, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=8]]
2016-05-17 21:20:51,184 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, taskAttemptId=attempt_1463520050638_0001_1_01_000000_0, startTime=1463520051095, finishTime=1463520051182, timeTaken=87, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=416808960, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=15, MERGE_PHASE_TIME=17, FIRST_EVENT_RECEIVED=11, LAST_EVENT_RECEIVED=11, 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=1463520051169, Process_Duration=6, Process_End_Time=1463520051175, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-05-17 21:20:51,185 INFO  impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1463520050638_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-05-17 21:20:51,185 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-05-17 21:20:51,184 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: 
2016-05-17 21:20:51,186 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:51,186 INFO  impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51,187 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:TASK_FINISHED]: vertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, taskId=task_1463520050638_0001_1_01_000000, startTime=1463520051095, finishTime=1463520051186, timeTaken=91, status=SUCCEEDED, successfulAttemptID=attempt_1463520050638_0001_1_01_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=416808960, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=15, MERGE_PHASE_TIME=17, FIRST_EVENT_RECEIVED=11, LAST_EVENT_RECEIVED=11, 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=1463520051169, Process_Duration=6, Process_End_Time=1463520051175, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-05-17 21:20:51,187 INFO  impl.TaskImpl (TaskImpl.java:handle(862)) - task_1463520050638_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-05-17 21:20:51,187 INFO  impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22] : 1
2016-05-17 21:20:51,187 INFO  impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:51,190 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-05-17 21:20:51,190 INFO  task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1463520050638_0001_00_000002
2016-05-17 21:20:51,193 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-05-17 21:20:51,194 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:VERTEX_FINISHED]: vertexName=F0F68A8E6A8644DA8BB31ECE89CEAA22, vertexId=vertex_1463520050638_0001_1_01, initRequestedTime=1463520050908, initedTime=1463520050947, startRequestedTime=1463520050964, startedTime=1463520050964, finishTime=1463520051188, timeTaken=224, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=140, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=10, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=416808960, OUTPUT_RECORDS=8, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=15, MERGE_PHASE_TIME=17, FIRST_EVENT_RECEIVED=11, LAST_EVENT_RECEIVED=11, 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=1463520051169, Process_Duration=6, Process_End_Time=1463520051175, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8, vertexStats=firstTaskStartTime=1463520051095, firstTasksToStart=[ task_1463520050638_0001_1_01_000000 ], lastTaskFinishTime=1463520051182, lastTasksToFinish=[ task_1463520050638_0001_1_01_000000 ], minTaskDuration=87, maxTaskDuration=87, avgTaskDuration=87.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1463520050638_0001_1_01_000000 ], longestDurationTasks=[ task_1463520050638_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-05-17 21:20:51,195 INFO  impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-05-17 21:20:51,195 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-05-17 21:20:51,196 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1463520050638_0001_00_000002, stoppedTime=1463520051195, exitStatus=0
2016-05-17 21:20:51,196 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-05-17 21:20:51,196 INFO  impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-05-17 21:20:51,196 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1463520050638_0001_1
2016-05-17 21:20:51,197 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1463520050638_0001_1
2016-05-17 21:20:51,197 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: E6733693E389481F982523B018FD483A for vertex: vertex_1463520050638_0001_1_01 [F0F68A8E6A8644DA8BB31ECE89CEAA22]
2016-05-17 21:20:51,196 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-05-17 21:20:51,204 INFO  app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1463520050638_0001_00_000002 is valid, but no longer registered, and will be killed
2016-05-17 21:20:51,204 INFO  task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1463520050638_0001_00_000002: 13 ms after starting to poll. TaskInfo: shouldDie: true
2016-05-17 21:20:51,204 INFO  task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1463520050638_0001_00_000002, Exiting
2016-05-17 21:20:51,204 INFO  task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1463520050638_0001_00_000002
2016-05-17 21:20:51,205 INFO  task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1463520050638_0001_00_000002
2016-05-17 21:20:51,206 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1463520050638_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-05-17 21:20:51,206 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1463520050638_0001_00_000002 completed successfully
2016-05-17 21:20:51,209 INFO  impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1463520050638_0001_1_00 [C221F1781E104FAA86526462B63DB46A]
2016-05-17 21:20:51,212 INFO  recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1463520050638_0001_1, queueSize=0
2016-05-17 21:20:51,212 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-05-17 21:20:51,213 INFO  history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1463520050638_0001_1][Event:DAG_FINISHED]: dagId=dag_1463520050638_0001_1, startTime=1463520050905, finishTime=1463520051210, timeTaken=305, 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=2442, FILE_BYTES_WRITTEN=376, FILE_READ_OPS=0, FILE_LARGE_READ_OPS=0, FILE_WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=7, REDUCE_INPUT_RECORDS=10, COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=20, NUM_SHUFFLED_INPUTS=1, NUM_SKIPPED_INPUTS=0, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=1, GC_TIME_MILLIS=0, CPU_MILLISECONDS=0, PHYSICAL_MEMORY_BYTES=0, VIRTUAL_MEMORY_BYTES=0, COMMITTED_HEAP_BYTES=833617920, INPUT_RECORDS_PROCESSED=0, OUTPUT_RECORDS=18, OUTPUT_BYTES=210, OUTPUT_BYTES_WITH_OVERHEAD=200, OUTPUT_BYTES_PHYSICAL=204, ADDITIONAL_SPILLS_BYTES_WRITTEN=0, ADDITIONAL_SPILLS_BYTES_READ=204, ADDITIONAL_SPILL_COUNT=0, SHUFFLE_BYTES=204, SHUFFLE_BYTES_DECOMPRESSED=200, SHUFFLE_BYTES_TO_MEM=0, SHUFFLE_BYTES_TO_DISK=0, SHUFFLE_BYTES_DISK_DIRECT=204, NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=15, MERGE_PHASE_TIME=17, FIRST_EVENT_RECEIVED=11, LAST_EVENT_RECEIVED=11, 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=2927040102221, Process_Duration=9, Process_End_Time=2927040102230, Read_Duration=3, Tuples_Read=20, Tuples_Written=18, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=8
2016-05-17 21:20:51,213 INFO  impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1463520050638_0001_1 finished with state: SUCCEEDED
2016-05-17 21:20:51,214 INFO  impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1463520050638_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-05-17 21:20:51,214 INFO  launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1463520050638_0001_00_000002
2016-05-17 21:20:51,215 INFO  container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1463520050638_0001_00_000002 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-05-17 21:20:51 Completed Dag: dag_1463520050638_0001_1
2016-05-17 21:20:51,217 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1463520050638_0001_1, dagState=SUCCEEDED
2016-05-17 21:20:51,218 INFO  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1463520050638_0001_1_post
2016-05-17 21:20:51,218 WARN  common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-05-17 21:20:51,219 INFO  app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-05-17 21:20:51,224 INFO  client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...testSimpleAssembly/simple, applicationId=application_1463520050638_0001
2016-05-17 21:20:51,228 INFO  client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-05-17 21:20:51,228 INFO  rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-05-17 21:20:51,228 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-05-17 21:20:51,228 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-05-17 21:20:51,228 INFO  app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-05-17 21:20:51,230 INFO  history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-05-17 21:20:51,230 INFO  app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-05-17 21:20:51,230 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-05-17 21:20:51,231 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-05-17 21:20:51,231 INFO  recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-05-17 21:20:51,232 INFO  recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-05-17 21:20:51,233 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-05-17 21:20:51,233 INFO  impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-05-17 21:20:51,240 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.4.x-tez-0.6.x/build/test/tmp/.staging/CDBF9794D4CB4DA484F8879ED10A07DF/A50CBE519B0740A8A11D1C5E01FC9269/.tez/application_1463520050638_0001
2016-05-17 21:20:51,241 INFO  util.Hadoop18TapUtil (Hadoop18TapUtil.java:cleanTempPath(226)) - deleting temp path /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple/_temporary
2016-05-17 21:20:51,242 INFO  flow.Flow (BaseFlow.java:logInfo(1504)) - []  completed in: 00:00.626
2016-05-17 21:20:51,290 INFO  cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/2f4c45215847827d/apache-2.4.x-tez-0.6.x/build/test/output//hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple

Standard error

2016-05-17 21:20:49 Running Dag: dag_1463520048338_0001_1
2016-05-17 21:20:49 Starting to run new task attempt: attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:50 Completed running task attempt: attempt_1463520048338_0001_1_00_000000_0
2016-05-17 21:20:50 Starting to run new task attempt: attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50 Completed running task attempt: attempt_1463520048338_0001_1_01_000000_0
2016-05-17 21:20:50 Completed Dag: dag_1463520048338_0001_1
2016-05-17 21:20:50 Running Dag: dag_1463520050638_0001_1
2016-05-17 21:20:50 Starting to run new task attempt: attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:51 Completed running task attempt: attempt_1463520050638_0001_1_00_000000_0
2016-05-17 21:20:51 Starting to run new task attempt: attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51 Completed running task attempt: attempt_1463520050638_0001_1_01_000000_0
2016-05-17 21:20:51 Completed Dag: dag_1463520050638_0001_1