2016-01-14 17:07:09,870 INFO platform.PlatformRunner (PlatformRunner.java:getPlatformClassesFromClasspath(195)) - found 1 test platforms from classpath
2016-01-14 17:07:09,902 INFO platform.PlatformRunner (PlatformRunner.java:addPlatform(244)) - adding test: cascading.flow.AssemblyPlannerPlatformTest, with platform: hadoop2-tez
2016-01-14 17:07:09,935 INFO tez.Hadoop2TezPlatform (Hadoop2TezPlatform.java:setUp(136)) - not using cluster
2016-01-14 17:07:10,298 WARN util.NativeCodeLoader (NativeCodeLoader.java:<clinit>(62)) - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2016-01-14 17:07:10,646 INFO platform.TestPlatform (TestPlatform.java:getGlobalProperties(73)) - platform property overrides:
2016-01-14 17:07:10,812 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 17:07:10,813 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(149)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.0.4/561447ee876073bb61fddc52e2ad157f45c8edd/cascading-hadoop2-tez-3.0.4.jar
2016-01-14 17:07:10,928 INFO property.AppProps (AppProps.java:getAppID(177)) - using app.id: 6392CBBAAEF441A7A7E96F9C0C56166A
2016-01-14 17:07:11,213 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.087
2016-01-14 17:07:11,255 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.130
2016-01-14 17:07:11,257 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-01-14 17:07:11,258 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-01-14 17:07:11,259 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 17:07:11,443 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt
2016-01-14 17:07:11,595 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite
2016-01-14 17:07:11,780 INFO util.Version (Version.java:printBanner(82)) - Concurrent, Inc - Cascading 3.0.4
2016-01-14 17:07:11,783 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] starting
2016-01-14 17:07:11,784 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:07:11,784 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite"]
2016-01-14 17:07:11,785 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] parallel execution of steps is enabled: false
2016-01-14 17:07:11,785 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executing total steps: 1
2016-01-14 17:07:11,786 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] allocating management threads: 1
2016-01-14 17:07:11,787 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] starting step: (1/1) ...mpositeAssembly/composite
2016-01-14 17:07:11,787 WARN flow.Flow (BaseFlow.java:logWarn(1445)) - [] '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-01-14 17:07:11,806 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tez session mode enabled: true
2016-01-14 17:07:11,975 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-01-14 17:07:11,984 INFO client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 17:07:11,985 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-01-14 17:07:12,041 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF/.tez/application_1452791231984_0001 doesn't exist and is created
2016-01-14 17:07:12,119 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 17:07:12,120 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:07:12,121 INFO client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF/.tez/application_1452791231984_0001
2016-01-14 17:07:12,156 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452791231984_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-01-14 17:07:12,196 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 17:07:12,210 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 17:07:12,222 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: NEW
2016-01-14 17:07:12,222 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(238)) - DAGAppMaster is not started wait for 100ms...
2016-01-14 17:07:12,222 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:07:12,234 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 17:07:12,237 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 17:07:12,240 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF/.tez/application_1452791231984_0001/localmode-log-dir
2016-01-14 17:07:12,241 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF/.tez/application_1452791231984_0001/localmode-log-dir/history.txt.appattempt_1452791231984_0001_000000, maxErrors=10
2016-01-14 17:07:12,241 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 17:07:12,243 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452791231984_0001_000000, appSubmitTime=1452791232142, launchTime=1452791232155
2016-01-14 17:07:12,250 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 17:07:12,251 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 17:07:12,254 INFO recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 17:07:12,254 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 17:07:12,310 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:38489
2016-01-14 17:07:12,322 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2016-01-14 17:07:12,322 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait for 100ms...
2016-01-14 17:07:12,323 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:07:12,349 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 17:07:12,419 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 17:07:12,420 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452791231984_0001_000000, startTime=1452791232419
2016-01-14 17:07:12,421 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 17:07:12,423 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 17:07:12,444 INFO client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 17:07:12,444 INFO client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...mpositeAssembly/composite, applicationId=application_1452791231984_0001, dagName=[8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF] null/(1/1) ...mpositeAssembly/composite
2016-01-14 17:07:12,695 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF] null/(1/1) ...mpositeAssembly/composite
2016-01-14 17:07:12,801 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452791231984_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF/.tez/application_1452791231984_0001/localmode-log-dir/dag_1452791231984_0001_1.dot
2016-01-14 17:07:12,805 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF/.tez/application_1452791231984_0001/localmode-log-dir/dag_1452791231984_0001_1-tez-dag.pb.txt
2016-01-14 17:07:12,895 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791231984_0001_1
2016-01-14 17:07:12,895 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:12,896 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF] null/(1/1) ...mpositeAssembly/composite
2016-01-14 17:07:12 Running Dag: dag_1452791231984_0001_1
2016-01-14 17:07:12,930 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 17:07:12,930 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452791231984_0001_1, submitTime=1452791232696
2016-01-14 17:07:12,962 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex AE0163FB26794DCB967E06C5379760E5
2016-01-14 17:07:12,970 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 17:07:12,972 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 17:07:12,972 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452791231984_0001_1, initTime=1452791232932
2016-01-14 17:07:12,973 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791231984_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 17:07:12,975 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 17:07:12,975 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:DAG_STARTED]: dagID=dag_1452791231984_0001_1, startTime=1452791232974
2016-01-14 17:07:12,976 INFO impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 17:07:12,978 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791231984_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 17:07:12,978 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: F49FD5E173734EEF9A5666BAF533C787 : {9065CC5FDAB84E8EA436E6912DF47DB5={InputName=9065CC5FDAB84E8EA436E6912DF47DB5}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 17:07:12,979 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: 9065CC5FDAB84E8EA436E6912DF47DB5, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 17:07:12,979 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:12,985 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:12,985 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:12,987 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]. Starting root input initializers: 1
2016-01-14 17:07:12,988 INFO client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...mpositeAssembly/composite, applicationId=application_1452791231984_0001, dagName=[8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF] null/(1/1) ...mpositeAssembly/composite
2016-01-14 17:07:12,993 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: 9065CC5FDAB84E8EA436E6912DF47DB5 on vertex vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:13,005 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 17:07:13,008 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,031 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] submitted tez dag to app master: application_1452791231984_0001, with dag id: dag_1452791231984_0001_1
2016-01-14 17:07:13,034 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 17:07:13,036 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input 9065CC5FDAB84E8EA436E6912DF47DB5 asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 17:07:13,037 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 17:07:13,038 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 17:07:13,039 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(696)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-01-14 17:07:13,039 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,058 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,061 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,061 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=0FE59DE7622B42A79BB1E226016D86B2, vertexId=vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 17:07:13,064 INFO impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=0FE59DE7622B42A79BB1E226016D86B2, vertexId=vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,087 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 408
2016-01-14 17:07:13,089 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: 9065CC5FDAB84E8EA436E6912DF47DB5 on vertex vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:13,092 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=0FE59DE7622B42A79BB1E226016D86B2, vertexName=AE0163FB26794DCB967E06C5379760E5, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 17:07:13,100 INFO impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=0FE59DE7622B42A79BB1E226016D86B2, vertexId=vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,104 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 17:07:13,104 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:VERTEX_INITIALIZED]: vertexName=AE0163FB26794DCB967E06C5379760E5, vertexId=vertex_1452791231984_0001_1_01, initRequestedTime=1452791233006, initedTime=1452791233103, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-01-14 17:07:13,104 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5] transitioned from NEW to INITED due to event V_INIT
2016-01-14 17:07:13,115 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:07:13,115 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {9065CC5FDAB84E8EA436E6912DF47DB5=forAllWorkUnits=true, update=[1]}
2016-01-14 17:07:13,117 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] parallelism set to 1
2016-01-14 17:07:13,117 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:07:13,137 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452791231984_0001_1_00, eventCount=1
2016-01-14 17:07:13,138 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 17:07:13,138 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:VERTEX_INITIALIZED]: vertexName=F49FD5E173734EEF9A5666BAF533C787, vertexId=vertex_1452791231984_0001_1_00, initRequestedTime=1452791232978, initedTime=1452791233138, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 17:07:13,139 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] with distanceFromRoot: 0
2016-01-14 17:07:13,139 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 17:07:13,147 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,147 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:13,150 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 17:07:13,150 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452791231984_0001_1_00, startRequestedTime=1452791233145, startedTime=1452791233145
2016-01-14 17:07:13,152 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] transitioned from INITED to RUNNING due to event V_START
2016-01-14 17:07:13,188 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 17:07:13,189 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:TASK_STARTED]: vertexName=F49FD5E173734EEF9A5666BAF533C787, taskId=task_1452791231984_0001_1_00_000000, scheduledTime=1452791233187, launchTime=1452791233187
2016-01-14 17:07:13,189 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791231984_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 17:07:13,190 INFO impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1452791231984_0001_1_00 for vertex: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5] numStartedSources: 1 numSources: 1
2016-01-14 17:07:13,190 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5] with distanceFromRoot: 1
2016-01-14 17:07:13,192 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:13,196 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: F49FD5E173734EEF9A5666BAF533C787 in vertex: AE0163FB26794DCB967E06C5379760E5
2016-01-14 17:07:13,200 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: AE0163FB26794DCB967E06C5379760E5 with 1 source tasks and 1 pending tasks
2016-01-14 17:07:13,200 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 17:07:13,201 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452791231984_0001_1_01, startRequestedTime=1452791233192, startedTime=1452791233192
2016-01-14 17:07:13,201 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5] transitioned from INITED to RUNNING due to event V_START
2016-01-14 17:07:13,203 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF] null/(1/1) ...mpositeAssembly/composite, VertexName: F49FD5E173734EEF9A5666BAF533C787, VertexParallelism: 1, TaskAttemptID:attempt_1452791231984_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=9065CC5FDAB84E8EA436E6912DF47DB5, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=AE0163FB26794DCB967E06C5379760E5, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 17:07:13,205 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791231984_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 17:07:13,206 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 17:07:13,278 INFO node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 17:07:13,282 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 17:07:13,282 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 17:07:13,286 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452791231984_0001_00_000001
2016-01-14 17:07:13,286 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 17:07:13,299 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452791231984_0001_00_000001
2016-01-14 17:07:13,299 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-01-14 17:07:13,304 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 17:07:13,305 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452791231984_0001_00_000001, launchTime=1452791233304
2016-01-14 17:07:13,307 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 17:07:13,307 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791231984_0001_00_000001
2016-01-14 17:07:13,314 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452791231984_0001_1_00_000000_0] to container: [container_1452791231984_0001_00_000001]
2016-01-14 17:07:13,315 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 17:07:13,316 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452791231984_0001_00_000001 given task: attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13,316 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791231984_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13 Starting to run new task attempt: attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13,317 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13,318 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:13,318 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452791231984_0001_1_00_000000_0] started. Is using containerId: [container_1452791231984_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 17:07:13,319 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 17:07:13,321 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 17:07:13,321 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 17:07:13,323 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 17:07:13,325 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 17:07:13,325 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=F49FD5E173734EEF9A5666BAF533C787, taskAttemptId=attempt_1452791231984_0001_1_00_000000_0, startTime=1452791233316, containerId=container_1452791231984_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452791231984_0001_00_000001/teamcity, completedLogs=
2016-01-14 17:07:13,326 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791231984_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 17:07:13,326 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-01-14 17:07:13,330 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791231984_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 17:07:13,350 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 17:07:13,350 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF] null/(1/1) ...mpositeAssembly/composite, VertexName: F49FD5E173734EEF9A5666BAF533C787, VertexParallelism: 1, TaskAttemptID:attempt_1452791231984_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=9065CC5FDAB84E8EA436E6912DF47DB5, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=AE0163FB26794DCB967E06C5379760E5, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 17:07:13,354 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 17:07:13,358 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13,360 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 17:07:13,360 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:13,367 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452791231984_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 17:07:13,368 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=9065CC5FDAB84E8EA436E6912DF47DB5, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 17:07:13,369 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:13,369 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=AE0163FB26794DCB967E06C5379760E5, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-01-14 17:07:13,371 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 17:07:13,372 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 17:07:13,372 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: 9065CC5FDAB84E8EA436E6912DF47DB5
2016-01-14 17:07:13,375 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: 9065CC5FDAB84E8EA436E6912DF47DB5
2016-01-14 17:07:13,382 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: AE0163FB26794DCB967E06C5379760E5
2016-01-14 17:07:13,394 INFO impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-01-14 17:07:13,394 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: AE0163FB26794DCB967E06C5379760E5
2016-01-14 17:07:13,395 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: AE0163FB26794DCB967E06C5379760E5
2016-01-14 17:07:13,395 INFO input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 17:07:13,396 INFO input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: 9065CC5FDAB84E8EA436E6912DF47DB5
2016-01-14 17:07:13,396 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: 9065CC5FDAB84E8EA436E6912DF47DB5
2016-01-14 17:07:13,396 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 17:07:13,409 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: F49FD5E173734EEF9A5666BAF533C787, ordinal: 0
2016-01-14 17:07:13,410 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: F49FD5E173734EEF9A5666BAF533C787, mem on start (mb), free: 248, total: 281, max: 672
2016-01-14 17:07:13,410 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:13,410 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 17:07:13,410 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 17:07:13,410 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 17:07:13,411 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 17:07:13,417 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 17:07:13,418 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:07:13,418 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-01-14 17:07:13,418 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 17:07:13,421 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-01-14 17:07:13,422 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, 9065CC5FDAB84E8EA436E6912DF47DB5, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 17:07:13,422 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, AE0163FB26794DCB967E06C5379760E5, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-01-14 17:07:13,422 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 17:07:13,423 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: 9065CC5FDAB84E8EA436E6912DF47DB5 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 17:07:13,423 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: 9065CC5FDAB84E8EA436E6912DF47DB5
2016-01-14 17:07:13,423 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:07:13,423 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 17:07:13,424 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 17:07:13,423 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: 9065CC5FDAB84E8EA436E6912DF47DB5
2016-01-14 17:07:13,424 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 17:07:13,428 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13,429 INFO input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 17:07:13,437 INFO input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@1d53ffa8
2016-01-14 17:07:13,444 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@1d53ffa8
2016-01-14 17:07:13,445 INFO input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 17:07:13,445 INFO input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 17:07:13,465 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:07:13,493 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"] streamed: true, id: 9065CC5FDAB84E8EA436E6912DF47DB5
2016-01-14 17:07:13,493 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'ip']], id: DE7D56C8CAB4425F94663FF606F12154
2016-01-14 17:07:13,493 INFO element.TezGroupGate (TezGroupGate.java:prepare(96)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'ip']] DE7D56C8CAB4425F94663FF606F12154
2016-01-14 17:07:13,510 INFO impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.TupleSerializer@678697ba; valueSerializer=cascading.tuple.hadoop.io.TupleSerializer@3553696f; comparator=cascading.tuple.hadoop.util.TupleComparator@772f11c2; 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-01-14 17:07:13,513 INFO impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-01-14 17:07:13,516 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-01-14 17:07:13,516 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 17:07:13,639 INFO dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-14 17:07:13,639 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-01-14 17:07:13,639 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-01-14 17:07:13,640 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-01-14 17:07:13,640 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-01-14 17:07:13,646 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:07:13,646 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:07:13,648 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: F49FD5E173734EEF9A5666BAF533C787, all 1 inputs ready in: 00:00:00.002
2016-01-14 17:07:13,657 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13,657 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: F49FD5E173734EEF9A5666BAF533C787, mem on close (mb), free: 138, total: 281, max: 672
2016-01-14 17:07:13,657 INFO dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-01-14 17:07:13,657 INFO dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-01-14 17:07:13,658 INFO dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2016-01-14 17:07:13,658 INFO dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-01-14 17:07:13,673 INFO dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-01-14 17:07:13 Completed running task attempt: attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13,694 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452791231984_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 17:07:13,695 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452791231984_0001_1_00, eventCount=1
2016-01-14 17:07:13,698 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 27 [[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=1452791233648, Process_Duration=9, Process_End_Time=1452791233657, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1][cascading.flow.StepCounters Tuples_Read=10]]
2016-01-14 17:07:13,701 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=F49FD5E173734EEF9A5666BAF533C787, taskAttemptId=attempt_1452791231984_0001_1_00_000000_0, startTime=1452791233316, finishTime=1452791233696, timeTaken=380, 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=1452791233648, Process_Duration=9, Process_End_Time=1452791233657, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 17:07:13,703 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 17:07:13,703 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:13,699 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 17:07:13,704 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791231984_0001_00_000001
2016-01-14 17:07:13,705 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791231984_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 17:07:13,706 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 17:07:13,707 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452791231984_0001_1_00_000000_0
2016-01-14 17:07:13,709 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 17:07:13,712 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:TASK_FINISHED]: vertexName=F49FD5E173734EEF9A5666BAF533C787, taskId=task_1452791231984_0001_1_00_000000, startTime=1452791233316, finishTime=1452791233708, timeTaken=392, status=SUCCEEDED, successfulAttemptID=attempt_1452791231984_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=1452791233648, Process_Duration=9, Process_End_Time=1452791233657, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 17:07:13,713 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791231984_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 17:07:13,714 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] : 1
2016-01-14 17:07:13,714 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:13,722 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 17:07:13,725 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:VERTEX_FINISHED]: vertexName=F49FD5E173734EEF9A5666BAF533C787, vertexId=vertex_1452791231984_0001_1_00, initRequestedTime=1452791232978, initedTime=1452791233138, startRequestedTime=1452791233145, startedTime=1452791233145, finishTime=1452791233715, timeTaken=570, 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=1452791233648, Process_Duration=9, Process_End_Time=1452791233657, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1452791233316, firstTasksToStart=[ task_1452791231984_0001_1_00_000000 ], lastTaskFinishTime=1452791233696, lastTasksToFinish=[ task_1452791231984_0001_1_00_000000 ], minTaskDuration=380, maxTaskDuration=380, avgTaskDuration=380.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452791231984_0001_1_00_000000 ], longestDurationTasks=[ task_1452791231984_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 17:07:13,726 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 17:07:13,726 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 17:07:13,728 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452791231984_0001_00_000001, stoppedTime=1452791233728, exitStatus=0
2016-01-14 17:07:13,729 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 17:07:13,729 INFO impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5] attempt: attempt_1452791231984_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-01-14 17:07:13,730 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: AE0163FB26794DCB967E06C5379760E5
2016-01-14 17:07:13,730 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,732 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 17:07:13,732 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-01-14 17:07:13,733 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1452791231984_0001_00_000001. Relying on regular task shutdown for it to end
2016-01-14 17:07:13,734 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:TASK_STARTED]: vertexName=AE0163FB26794DCB967E06C5379760E5, taskId=task_1452791231984_0001_1_01_000000, scheduledTime=1452791233733, launchTime=1452791233733
2016-01-14 17:07:13,734 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791231984_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 17:07:13,734 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,735 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452791231984_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 17:07:13,735 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791231984_0001_00_000001: 31 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 17:07:13,735 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452791231984_0001_00_000001, Exiting
2016-01-14 17:07:13,735 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452791231984_0001_00_000001
2016-01-14 17:07:13,736 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452791231984_0001_00_000001
2016-01-14 17:07:13,735 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 17:07:13,739 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000001 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-01-14 17:07:13,741 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF] null/(1/1) ...mpositeAssembly/composite, VertexName: AE0163FB26794DCB967E06C5379760E5, VertexParallelism: 1, TaskAttemptID:attempt_1452791231984_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=F49FD5E173734EEF9A5666BAF533C787, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=0FE59DE7622B42A79BB1E226016D86B2, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:07:13,742 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791231984_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 17:07:13,742 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 17:07:13,746 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452791231984_0001_00_000002
2016-01-14 17:07:13,746 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 17:07:13,747 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452791231984_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 17:07:13,747 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452791231984_0001_00_000001 completed successfully
2016-01-14 17:07:13,748 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000001 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-01-14 17:07:13,750 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452791231984_0001_00_000002
2016-01-14 17:07:13,751 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-teztask.properties,hadoop-metrics2.properties
2016-01-14 17:07:13,753 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 17:07:13,754 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 17:07:13,754 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452791231984_0001_00_000002, launchTime=1452791233754
2016-01-14 17:07:13,756 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791231984_0001_00_000002
2016-01-14 17:07:13,757 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452791231984_0001_1_01_000000_0] to container: [container_1452791231984_0001_00_000002]
2016-01-14 17:07:13,757 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 17:07:13,758 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452791231984_0001_1_01_000000_0] started. Is using containerId: [container_1452791231984_0001_00_000002] on NM: [127.0.0.1:0]
2016-01-14 17:07:13,758 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=AE0163FB26794DCB967E06C5379760E5, taskAttemptId=attempt_1452791231984_0001_1_01_000000_0, startTime=1452791233758, containerId=container_1452791231984_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452791231984_0001_00_000002/teamcity, completedLogs=
2016-01-14 17:07:13,758 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791231984_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 17:07:13,759 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791231984_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 17:07:13,758 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 17:07:13,759 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452791231984_0001_00_000002 given task: attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,759 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791231984_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13 Starting to run new task attempt: attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,760 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,760 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:13,760 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 17:07:13,760 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 17:07:13,761 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 17:07:13,761 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 17:07:13,761 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 17:07:13,762 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF] null/(1/1) ...mpositeAssembly/composite, VertexName: AE0163FB26794DCB967E06C5379760E5, VertexParallelism: 1, TaskAttemptID:attempt_1452791231984_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=F49FD5E173734EEF9A5666BAF533C787, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=0FE59DE7622B42A79BB1E226016D86B2, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:07:13,762 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 17:07:13,763 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,764 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 17:07:13,764 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:13,766 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=F49FD5E173734EEF9A5666BAF533C787, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-01-14 17:07:13,767 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 17:07:13,769 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,770 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:13,774 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=0FE59DE7622B42A79BB1E226016D86B2, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 17:07:13,775 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 17:07:13,776 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 0FE59DE7622B42A79BB1E226016D86B2
2016-01-14 17:07:13,777 INFO output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 17:07:13,778 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 0FE59DE7622B42A79BB1E226016D86B2
2016-01-14 17:07:13,774 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452791231984_0001_1_01_000000_0 sent events: (0-1)
2016-01-14 17:07:13,781 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 17:07:13,800 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-01-14 17:07:13,800 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-01-14 17:07:13,800 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,808 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: AE0163FB26794DCB967E06C5379760E5, ordinal: 1
2016-01-14 17:07:13,809 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,810 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: AE0163FB26794DCB967E06C5379760E5, mem on start (mb), free: 125, total: 281, max: 672
2016-01-14 17:07:13,810 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:13,811 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 17:07:13,811 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 17:07:13,820 INFO output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 17:07:13,820 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 0FE59DE7622B42A79BB1E226016D86B2
2016-01-14 17:07:13,820 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 17:07:13,820 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 17:07:13,821 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 17:07:13,822 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:07:13,822 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-01-14 17:07:13,822 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 17:07:13,823 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-01-14 17:07:13,823 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 0FE59DE7622B42A79BB1E226016D86B2, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 17:07:13,823 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, F49FD5E173734EEF9A5666BAF533C787, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=472110858
2016-01-14 17:07:13,823 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 17:07:13,823 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: F49FD5E173734EEF9A5666BAF533C787 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 17:07:13,823 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 17:07:13,824 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 17:07:13,826 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,840 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 17:07:13,841 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-01-14 17:07:13,846 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: F49FD5E173734EEF9A5666BAF533C787 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-01-14 17:07:13,848 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=472110858. Updated to: ShuffleMem=472110858, postMergeMem: 0
2016-01-14 17:07:13,849 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=472110858, maxSingleShuffleLimit=118027712, mergeThreshold=424899744, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-01-14 17:07:13,854 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-01-14 17:07:13,858 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,858 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 17:07:13,860 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,865 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'ip']]
2016-01-14 17:07:13,869 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:processDataMovementEvent(84)) - DME srcIdx: 0, targetIdx: 0, attemptNum: 0, payload: [host: ip-10-187-41-40, port: 0, pathComponent: attempt_1452791231984_0001_1_00_000000_0_10003, runDuration: 295881, ]
2016-01-14 17:07:13,871 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'ip']] streamed: true, id: DE7D56C8CAB4425F94663FF606F12154
2016-01-14 17:07:13,872 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite"], id: 0FE59DE7622B42A79BB1E226016D86B2
2016-01-14 17:07:13,872 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite"]
2016-01-14 17:07:13,873 INFO element.TezGroupGate (TezGroupGate.java:prepare(88)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'ip']] DE7D56C8CAB4425F94663FF606F12154, for 1 inputs
2016-01-14 17:07:13,877 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1452791231984_0001_1_00_000000_0_10003] to DISK_DIRECT, CompressedSize=204, DecompressedSize=200,EndTime=1452791233877, TimeTaken=3, Rate=0.06 MB/s
2016-01-14 17:07:13,877 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,878 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-01-14 17:07:13,879 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-187-41-40:0 freed by fetcher [F49FD5E173734EEF9A5666BAF533C787] #1 in 5ms
2016-01-14 17:07:13,879 INFO orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [F49FD5E173734EEF9A5666BAF533C787] #1, status:false, isInterrupted:false
2016-01-14 17:07:13,880 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-01-14 17:07:13,882 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 204 bytes from disk
2016-01-14 17:07:13,883 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 17:07:13,887 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-01-14 17:07:13,890 INFO impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 175 bytes
2016-01-14 17:07:13,890 INFO orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,891 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-01-14 17:07:13,891 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: AE0163FB26794DCB967E06C5379760E5, all 1 inputs ready in: 00:00:00.016
2016-01-14 17:07:13,898 INFO common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@40fc732f; valueDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@7dee33fd
2016-01-14 17:07:13,905 INFO output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 17:07:13,906 INFO output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 17:07:13,907 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,908 INFO impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452791231984_0001_1_01_000000_0 given a go for committing the task output.
2016-01-14 17:07:13,909 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,910 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: AE0163FB26794DCB967E06C5379760E5, mem on close (mb), free: 118, total: 281, max: 672
2016-01-14 17:07:13,910 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: F49FD5E173734EEF9A5666BAF533C787
2016-01-14 17:07:13,910 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-01-14 17:07:13,911 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-01-14 17:07:13,911 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 17:07:13,911 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-01-14 17:07:13,912 INFO impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-01-14 17:07:13 Completed running task attempt: attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,914 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452791231984_0001_1_01_000000_0, fatalErrorOccurred=false
2016-01-14 17:07:13,916 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 17:07:13,917 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=660, 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=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=33, LAST_EVENT_RECEIVED=33][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=1452791233891, Process_Duration=18, Process_End_Time=1452791233909, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=8]]
2016-01-14 17:07:13,919 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=AE0163FB26794DCB967E06C5379760E5, taskAttemptId=attempt_1452791231984_0001_1_01_000000_0, startTime=1452791233758, finishTime=1452791233915, timeTaken=157, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=660, 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=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=33, LAST_EVENT_RECEIVED=33, 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=1452791233891, Process_Duration=18, Process_End_Time=1452791233909, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-01-14 17:07:13,919 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791231984_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 17:07:13,920 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452791231984_0001_1_01_000000_0
2016-01-14 17:07:13,920 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 17:07:13,920 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 17:07:13,921 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:13,921 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 17:07:13,922 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791231984_0001_00_000002
2016-01-14 17:07:13,923 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:TASK_FINISHED]: vertexName=AE0163FB26794DCB967E06C5379760E5, taskId=task_1452791231984_0001_1_01_000000, startTime=1452791233758, finishTime=1452791233920, timeTaken=162, status=SUCCEEDED, successfulAttemptID=attempt_1452791231984_0001_1_01_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=660, 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=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=33, LAST_EVENT_RECEIVED=33, 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=1452791233891, Process_Duration=18, Process_End_Time=1452791233909, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-01-14 17:07:13,923 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791231984_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 17:07:13,924 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5] : 1
2016-01-14 17:07:13,924 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,927 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 17:07:13,931 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:VERTEX_FINISHED]: vertexName=AE0163FB26794DCB967E06C5379760E5, vertexId=vertex_1452791231984_0001_1_01, initRequestedTime=1452791233006, initedTime=1452791233103, startRequestedTime=1452791233192, startedTime=1452791233192, finishTime=1452791233926, timeTaken=734, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=660, 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=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=33, LAST_EVENT_RECEIVED=33, 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=1452791233891, Process_Duration=18, Process_End_Time=1452791233909, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8, vertexStats=firstTaskStartTime=1452791233758, firstTasksToStart=[ task_1452791231984_0001_1_01_000000 ], lastTaskFinishTime=1452791233915, lastTasksToFinish=[ task_1452791231984_0001_1_01_000000 ], minTaskDuration=157, maxTaskDuration=157, avgTaskDuration=157.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452791231984_0001_1_01_000000 ], longestDurationTasks=[ task_1452791231984_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 17:07:13,931 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 17:07:13,931 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 17:07:13,932 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 17:07:13,933 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452791231984_0001_00_000002, stoppedTime=1452791233932, exitStatus=0
2016-01-14 17:07:13,933 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452791231984_0001_00_000002 is valid, but no longer registered, and will be killed
2016-01-14 17:07:13,933 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791231984_0001_00_000002: 11 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 17:07:13,933 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 17:07:13,933 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452791231984_0001_00_000002, Exiting
2016-01-14 17:07:13,934 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452791231984_0001_00_000002
2016-01-14 17:07:13,934 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452791231984_0001_00_000002
2016-01-14 17:07:13,934 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-01-14 17:07:13,936 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452791231984_0001_1
2016-01-14 17:07:13,937 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452791231984_0001_1
2016-01-14 17:07:13,937 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1452791231984_0001_1_00 [F49FD5E173734EEF9A5666BAF533C787]
2016-01-14 17:07:13,937 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 0FE59DE7622B42A79BB1E226016D86B2 for vertex: vertex_1452791231984_0001_1_01 [AE0163FB26794DCB967E06C5379760E5]
2016-01-14 17:07:13,941 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452791231984_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 17:07:13,942 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452791231984_0001_00_000002 completed successfully
2016-01-14 17:07:13,963 INFO recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452791231984_0001_1, queueSize=0
2016-01-14 17:07:13,963 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 17:07:13,964 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791231984_0001_1][Event:DAG_FINISHED]: dagId=dag_1452791231984_0001_1, startTime=1452791232974, finishTime=1452791233952, timeTaken=978, 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=1416, 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=37, MERGE_PHASE_TIME=49, FIRST_EVENT_RECEIVED=33, LAST_EVENT_RECEIVED=33, 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=2905582467539, Process_Duration=27, Process_End_Time=2905582467566, Read_Duration=3, Tuples_Read=20, Tuples_Written=18, Write_Duration=1, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=8
2016-01-14 17:07:13,965 INFO impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452791231984_0001_1 finished with state: SUCCEEDED
2016-01-14 17:07:13,966 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791231984_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 17:07:13,966 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452791231984_0001_00_000002
2016-01-14 17:07:13,968 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791231984_0001_00_000002 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 17:07:13 Completed Dag: dag_1452791231984_0001_1
2016-01-14 17:07:13,971 INFO app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452791231984_0001_1, dagState=SUCCEEDED
2016-01-14 17:07:13,972 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791231984_0001_1_post
2016-01-14 17:07:13,972 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:13,974 INFO app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 17:07:13,981 INFO client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...mpositeAssembly/composite, applicationId=application_1452791231984_0001
2016-01-14 17:07:13,986 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 17:07:13,986 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 17:07:13,986 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 17:07:13,986 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 17:07:13,987 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 17:07:13,988 INFO app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 17:07:13,991 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 17:07:13,991 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 17:07:13,991 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 17:07:13,992 INFO recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 17:07:13,992 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 17:07:13,993 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 17:07:13,994 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 17:07:13,999 INFO app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/8ACF30E59374463AA40754170900BE87/C29696099D7B4050BCE04D31574570FF/.tez/application_1452791231984_0001
2016-01-14 17:07:14,000 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] completed in: 00:02.217
2016-01-14 17:07:14,047 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/assemblyplannerplatform/testCompositeAssembly/composite
2016-01-14 17:07:14,081 INFO util.Util (Util.java:findMainClass(1327)) - using default application jar, may cause class not found exceptions on the cluster
2016-01-14 17:07:14,081 INFO planner.Hadoop2TezPlanner (Hadoop2TezPlanner.java:initialize(149)) - using application jar: /opt/concurrent/home/teamcity/.gradle/caches/modules-2/files-2.1/cascading/cascading-hadoop2-tez/3.0.4/561447ee876073bb61fddc52e2ad157f45c8edd/cascading-hadoop2-tez-3.0.4.jar
2016-01-14 17:07:14,158 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executed rule registry: NoHashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.040
2016-01-14 17:07:14,170 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executed rule registry: HashJoinHadoop2TezRuleRegistry, completed as: SUCCESS, in: 00:00.052
2016-01-14 17:07:14,171 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-01-14 17:07:14,172 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: HashJoinHadoop2TezRuleRegistry, supports assembly with steps: 1, nodes: 2
2016-01-14 17:07:14,172 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] rule registry: NoHashJoinHadoop2TezRuleRegistry, result was selected using: 'default comparator: selects plan with fewest steps and fewest nodes'
2016-01-14 17:07:14,194 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt
2016-01-14 17:07:14,209 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tap forcing step to tez local mode: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple
2016-01-14 17:07:14,282 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] starting
2016-01-14 17:07:14,282 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:07:14,282 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] sink: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple"]
2016-01-14 17:07:14,283 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] parallel execution of steps is enabled: false
2016-01-14 17:07:14,283 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] executing total steps: 1
2016-01-14 17:07:14,283 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] allocating management threads: 1
2016-01-14 17:07:14,285 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] starting step: (1/1) ...testSimpleAssembly/simple
2016-01-14 17:07:14,285 WARN flow.Flow (BaseFlow.java:logWarn(1445)) - [] '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-01-14 17:07:14,302 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] tez session mode enabled: true
2016-01-14 17:07:14,307 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-01-14 17:07:14,308 INFO client.TezClient (TezClient.java:start(333)) - Session mode. Starting session.
2016-01-14 17:07:14,308 INFO client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(159)) - Ignoring 'tez.lib.uris' since 'tez.ignore.lib.uris' is set to true
2016-01-14 17:07:14,319 INFO client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(118)) - Tez system stage directory file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0/.tez/application_1452791234308_0001 doesn't exist and is created
2016-01-14 17:07:14,346 INFO client.LocalClient (LocalClient.java:createDAGAppMaster(328)) - DAGAppMaster thread has been created
2016-01-14 17:07:14,346 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait for 100ms...
2016-01-14 17:07:14,347 INFO client.LocalClient (LocalClient.java:run(275)) - Using staging directory: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0/.tez/application_1452791234308_0001
2016-01-14 17:07:14,351 INFO app.DAGAppMaster (DAGAppMaster.java:<init>(309)) - Created DAGAppMaster for application appattempt_1452791234308_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-01-14 17:07:14,365 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(333)) - Comparing client version with AM version, clientVersion=0.6.2, AMVersion=0.6.2
2016-01-14 17:07:14,366 INFO app.DAGAppMaster (DAGAppMaster.java:serviceInit(386)) - Adding session token to jobTokenSecretManager for application
2016-01-14 17:07:14,368 INFO node.AMNodeTracker (AMNodeTracker.java:serviceInit(77)) - blacklistDisablePercent is 33, blacklistingEnabled: false, maxTaskFailuresPerNode: 1
2016-01-14 17:07:14,368 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceInit(50)) - Initializing HistoryEventHandler
2016-01-14 17:07:14,368 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for SimpleHistoryLoggingService not specified, defaulting to containerLogDir=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0/.tez/application_1452791234308_0001/localmode-log-dir
2016-01-14 17:07:14,368 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing SimpleHistoryLoggingService, logFileLocation=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0/.tez/application_1452791234308_0001/localmode-log-dir/history.txt.appattempt_1452791234308_0001_000000, maxErrors=10
2016-01-14 17:07:14,369 INFO recovery.RecoveryService (RecoveryService.java:serviceInit(109)) - Initializing RecoveryService
2016-01-14 17:07:14,369 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1452791234308_0001_000000, appSubmitTime=1452791234350, launchTime=1452791234351
2016-01-14 17:07:14,376 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStart(73)) - Starting HistoryEventHandler
2016-01-14 17:07:14,379 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStart(95)) - Starting SimpleHistoryLoggingService
2016-01-14 17:07:14,382 INFO recovery.RecoveryService (RecoveryService.java:serviceStart(127)) - Starting RecoveryService
2016-01-14 17:07:14,382 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_LAUNCHED to history file
2016-01-14 17:07:14,388 INFO client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated DAGClientRPCServer at ip-10-187-41-40.ec2.internal/10.187.41.40:55999
2016-01-14 17:07:14,390 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-dagappmaster.properties,hadoop-metrics2.properties
2016-01-14 17:07:14,392 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event AM_STARTED to history file
2016-01-14 17:07:14,392 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1452791234308_0001_000000, startTime=1452791234392
2016-01-14 17:07:14,393 INFO app.DAGAppMaster (DAGAppMaster.java:serviceStart(1644)) - In Session mode. Waiting for DAG over RPC
2016-01-14 17:07:14,446 INFO client.LocalClient (LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2016-01-14 17:07:14,446 INFO client.TezClient (TezClient.java:start(367)) - The url to track the Tez Session: N/A
2016-01-14 17:07:14,446 INFO client.TezClient (TezClient.java:submitDAGSession(405)) - Submitting dag to TezSession, sessionName=(1/1) ...testSimpleAssembly/simple, applicationId=application_1452791234308_0001, dagName=[5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0] null/(1/1) ...testSimpleAssembly/simple
2016-01-14 17:07:14,471 INFO app.DAGAppMaster (DAGAppMaster.java:submitDAGToAppMaster(1126)) - Starting DAG submitted via RPC: [5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0] null/(1/1) ...testSimpleAssembly/simple
2016-01-14 17:07:14,474 INFO app.DAGAppMaster (DAGAppMaster.java:generateDAGVizFile(870)) - Generating DAG graphviz file, dagId=dag_1452791234308_0001_1, filePath=/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0/.tez/application_1452791234308_0001/localmode-log-dir/dag_1452791234308_0001_1.dot
2016-01-14 17:07:14,476 INFO app.DAGAppMaster (DAGAppMaster.java:writePBTextFile(887)) - Writing DAG plan to: /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0/.tez/application_1452791234308_0001/localmode-log-dir/dag_1452791234308_0001_1-tez-dag.pb.txt
2016-01-14 17:07:14,537 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791234308_0001_1
2016-01-14 17:07:14,537 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:14,537 INFO app.DAGAppMaster (DAGAppMaster.java:startDAG(2051)) - Running DAG: [5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0] null/(1/1) ...testSimpleAssembly/simple
2016-01-14 17:07:14 Running Dag: dag_1452791234308_0001_1
2016-01-14 17:07:14,555 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_SUBMITTED to history file
2016-01-14 17:07:14,556 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:DAG_SUBMITTED]: dagID=dag_1452791234308_0001_1, submitTime=1452791234471
2016-01-14 17:07:14,557 INFO impl.VertexImpl (VertexImpl.java:setAdditionalOutputs(4033)) - setting additional outputs for vertex BAB29A0C0F47400BA934EABCD6936D13
2016-01-14 17:07:14,557 INFO impl.DAGImpl (DAGImpl.java:assignDAGScheduler(1381)) - Using DAG Scheduler: org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2016-01-14 17:07:14,558 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:DAG_INITIALIZED]: dagID=dag_1452791234308_0001_1, initTime=1452791234556
2016-01-14 17:07:14,558 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_INITIALIZED to history file
2016-01-14 17:07:14,559 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791234308_0001_1 transitioned from NEW to INITED due to event DAG_INIT
2016-01-14 17:07:14,560 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_STARTED to history file
2016-01-14 17:07:14,560 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:DAG_STARTED]: dagID=dag_1452791234308_0001_1, startTime=1452791234559
2016-01-14 17:07:14,560 INFO impl.DAGImpl (DAGImpl.java:transition(1614)) - Added additional resources : [[]] to classpath
2016-01-14 17:07:14,560 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791234308_0001_1 transitioned from INITED to RUNNING due to event DAG_START
2016-01-14 17:07:14,560 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2068)) - Root Inputs exist for Vertex: D368BDDE74DF427B9EB53272109643D9 : {D0342ACA6C374ED4A4795A2CCB25BBEA={InputName=D0342ACA6C374ED4A4795A2CCB25BBEA}, {Descriptor=ClassName=org.apache.tez.mapreduce.input.MRInput, hasPayload=true}, {ControllerDescriptor=ClassName=org.apache.tez.mapreduce.common.MRInputAMSplitGenerator, hasPayload=false}}
2016-01-14 17:07:14,560 INFO impl.VertexImpl (VertexImpl.java:setupVertex(2078)) - Starting root input initializer for input: D0342ACA6C374ED4A4795A2CCB25BBEA, with class: [org.apache.tez.mapreduce.common.MRInputAMSplitGenerator]
2016-01-14 17:07:14,560 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2191)) - Setting vertexManager to RootInputVertexManager for vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,560 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2983)) - Num tasks is -1. Expecting VertexManager/InputInitializers/1-1 split to set #tasks for the vertex vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,560 INFO client.TezClient (TezClient.java:submitDAGSession(478)) - Submitted dag to TezSession, sessionName=(1/1) ...testSimpleAssembly/simple, applicationId=application_1452791234308_0001, dagName=[5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0] null/(1/1) ...testSimpleAssembly/simple
2016-01-14 17:07:14,561 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(2987)) - Vertex will initialize from input initializer. vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,561 INFO impl.VertexImpl (VertexImpl.java:setupInputInitializerManager(3933)) - Vertex will initialize via inputInitializers vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]. Starting root input initializers: 1
2016-01-14 17:07:14,561 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] transitioned from NEW to INITIALIZING due to event V_INIT
2016-01-14 17:07:14,562 INFO impl.VertexImpl (VertexImpl.java:assignVertexManager(2203)) - Setting vertexManager to ShuffleVertexManager for vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,563 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:run(242)) - Starting InputInitializer for Input: D0342ACA6C374ED4A4795A2CCB25BBEA on vertex vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,566 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:initialize(696)) - Shuffle Vertex Manager: settings minFrac:0.25 maxFrac:0.75 auto:false desiredTaskIput:104857600 minTasks:1
2016-01-14 17:07:14,567 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3014)) - Creating 1 tasks for vertex: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,567 INFO impl.VertexImpl (VertexImpl.java:handleInitEvent(3026)) - Directly initializing vertex: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,567 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1915)) - Invoking committer inits for vertex, vertexId=vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,568 INFO impl.VertexImpl (VertexImpl.java:initializeCommitters(1927)) - Instantiating committer for output=010EFFEA5FBC443D80CC9DCC3321187E, vertexId=vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13], committerClass=org.apache.tez.mapreduce.committer.MROutputCommitter
2016-01-14 17:07:14,568 INFO impl.VertexImpl (VertexImpl.java:run(1945)) - Invoking committer init for output=010EFFEA5FBC443D80CC9DCC3321187E, vertexId=vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,569 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(92)) - Emitting serialized splits: true
2016-01-14 17:07:14,570 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(110)) - Input D0342ACA6C374ED4A4795A2CCB25BBEA asking for 1 tasks. Headroom: 672 Task Resource: 1024 waves: 1.7
2016-01-14 17:07:14,572 INFO common.MRInputAMSplitGenerator (MRInputAMSplitGenerator.java:initialize(121)) - Grouping input splits
2016-01-14 17:07:14,573 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(294)) - Generating mapred api input splits
2016-01-14 17:07:14,575 INFO hadoop.MRInputHelpers (MRInputHelpers.java:generateInputSplitsToMem(300)) - NumSplits: 1, SerializedSize: 408
2016-01-14 17:07:14,575 INFO committer.MROutputCommitter (MROutputCommitter.java:getOutputCommitter(145)) - OutputCommitter for outputName=010EFFEA5FBC443D80CC9DCC3321187E, vertexName=BAB29A0C0F47400BA934EABCD6936D13, outputCommitterClass=org.apache.hadoop.mapred.FileOutputCommitter
2016-01-14 17:07:14,578 INFO dag.RootInputInitializerManager (RootInputInitializerManager.java:onSuccess(272)) - Succeeded InputInitializer for Input: D0342ACA6C374ED4A4795A2CCB25BBEA on vertex vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,578 INFO impl.VertexImpl (VertexImpl.java:run(1949)) - Invoking committer setup for output=010EFFEA5FBC443D80CC9DCC3321187E, vertexId=vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,580 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 17:07:14,581 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:VERTEX_INITIALIZED]: vertexName=BAB29A0C0F47400BA934EABCD6936D13, vertexId=vertex_1452791234308_0001_1_01, initRequestedTime=1452791234562, initedTime=1452791234580, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=0
2016-01-14 17:07:14,581 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13] transitioned from NEW to INITED due to event V_INIT
2016-01-14 17:07:14,581 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] numTasks: -1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:07:14,582 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1374)) - Got updated RootInputsSpecs: {D0342ACA6C374ED4A4795A2CCB25BBEA=forAllWorkUnits=true, update=[1]}
2016-01-14 17:07:14,582 INFO impl.VertexImpl (VertexImpl.java:setParallelism(1393)) - Vertex vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] parallelism set to 1
2016-01-14 17:07:14,582 INFO impl.VertexImpl (VertexImpl.java:canInitVertex(3195)) - Cannot init vertex: vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] numTasks: 1 numUnitializedEdges: 0 numInitializedInputs: 0 initWaitsForRootInitializers: true
2016-01-14 17:07:14,583 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452791234308_0001_1_00, eventCount=1
2016-01-14 17:07:14,584 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:VERTEX_INITIALIZED]: vertexName=D368BDDE74DF427B9EB53272109643D9, vertexId=vertex_1452791234308_0001_1_00, initRequestedTime=1452791234560, initedTime=1452791234583, numTasks=1, processorName=cascading.flow.tez.FlowProcessor, additionalInputsCount=1
2016-01-14 17:07:14,584 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_INITIALIZED to history file
2016-01-14 17:07:14,584 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] with distanceFromRoot: 0
2016-01-14 17:07:14,585 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] transitioned from INITIALIZING to INITED due to event V_ROOT_INPUT_INITIALIZED
2016-01-14 17:07:14,585 INFO impl.ImmediateStartVertexManager (ImmediateStartVertexManager.java:scheduleTasks(99)) - Starting 1 in D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,586 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,586 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 17:07:14,587 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452791234308_0001_1_00, startRequestedTime=1452791234585, startedTime=1452791234585
2016-01-14 17:07:14,588 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] transitioned from INITED to RUNNING due to event V_START
2016-01-14 17:07:14,592 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 17:07:14,592 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:TASK_STARTED]: vertexName=D368BDDE74DF427B9EB53272109643D9, taskId=task_1452791234308_0001_1_00_000000, scheduledTime=1452791234592, launchTime=1452791234592
2016-01-14 17:07:14,593 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791234308_0001_1_00_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 17:07:14,593 INFO impl.VertexImpl (VertexImpl.java:transition(3155)) - Source vertex started: vertex_1452791234308_0001_1_00 for vertex: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13] numStartedSources: 1 numSources: 1
2016-01-14 17:07:14,593 INFO impl.VertexImpl (VertexImpl.java:startIfPossible(3061)) - Triggering start event for vertex: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13] with distanceFromRoot: 1
2016-01-14 17:07:14,594 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,594 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:handleVertexStateUpdate(720)) - Received configured notification : CONFIGURED for vertex: D368BDDE74DF427B9EB53272109643D9 in vertex: BAB29A0C0F47400BA934EABCD6936D13
2016-01-14 17:07:14,594 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:onVertexStarted(355)) - OnVertexStarted vertex: BAB29A0C0F47400BA934EABCD6936D13 with 1 source tasks and 1 pending tasks
2016-01-14 17:07:14,595 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_STARTED to history file
2016-01-14 17:07:14,595 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:VERTEX_STARTED]: vertexId=vertex_1452791234308_0001_1_01, startRequestedTime=1452791234594, startedTime=1452791234594
2016-01-14 17:07:14,596 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13] transitioned from INITED to RUNNING due to event V_START
2016-01-14 17:07:14,596 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0] null/(1/1) ...testSimpleAssembly/simple, VertexName: D368BDDE74DF427B9EB53272109643D9, VertexParallelism: 1, TaskAttemptID:attempt_1452791234308_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D0342ACA6C374ED4A4795A2CCB25BBEA, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=BAB29A0C0F47400BA934EABCD6936D13, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 17:07:14,598 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791234308_0001_1_00_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 17:07:14,598 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 17:07:14,599 INFO node.AMNodeTracker (AMNodeTracker.java:nodeSeen(91)) - Adding new node: 127.0.0.1:0
2016-01-14 17:07:14,599 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(112)) - Adding #1 tokens and #0 secret keys for NM use for launching container
2016-01-14 17:07:14,599 INFO container.AMContainerHelpers (AMContainerHelpers.java:createCommonContainerLaunchContext(122)) - Putting shuffle token in serviceData
2016-01-14 17:07:14,600 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452791234308_0001_00_000001
2016-01-14 17:07:14,600 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000001 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 17:07:14,603 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452791234308_0001_00_000001
2016-01-14 17:07:14,603 WARN impl.MetricsSystemImpl (MetricsSystemImpl.java:init(145)) - DAGAppMaster metrics system already initialized!
2016-01-14 17:07:14,604 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000001 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 17:07:14,604 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 17:07:14,605 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452791234308_0001_00_000001, launchTime=1452791234604
2016-01-14 17:07:14,605 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791234308_0001_00_000001
2016-01-14 17:07:14,608 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452791234308_0001_1_00_000000_0] to container: [container_1452791234308_0001_00_000001]
2016-01-14 17:07:14,609 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000001 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 17:07:14,609 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452791234308_0001_1_00_000000_0] started. Is using containerId: [container_1452791234308_0001_00_000001] on NM: [127.0.0.1:0]
2016-01-14 17:07:14,610 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=D368BDDE74DF427B9EB53272109643D9, taskAttemptId=attempt_1452791234308_0001_1_00_000000_0, startTime=1452791234609, containerId=container_1452791234308_0001_00_000001, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452791234308_0001_00_000001/teamcity, completedLogs=
2016-01-14 17:07:14,610 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791234308_0001_1_00_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 17:07:14,610 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 17:07:14,610 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791234308_0001_1_00_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 17:07:14,611 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] submitted tez dag to app master: application_1452791234308_0001, with dag id: dag_1452791234308_0001_1
2016-01-14 17:07:14,612 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452791234308_0001_00_000001 given task: attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14,613 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791234308_0001_00_000001: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14 Starting to run new task attempt: attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14,614 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14,614 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:14,615 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 17:07:14,615 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 17:07:14,615 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 17:07:14,615 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 17:07:14,615 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 17:07:14,615 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0] null/(1/1) ...testSimpleAssembly/simple, VertexName: D368BDDE74DF427B9EB53272109643D9, VertexParallelism: 1, TaskAttemptID:attempt_1452791234308_0001_1_00_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D0342ACA6C374ED4A4795A2CCB25BBEA, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }}, ], outputSpecList=[{{ destinationVertexName=BAB29A0C0F47400BA934EABCD6936D13, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }}, ]
2016-01-14 17:07:14,616 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 17:07:14,618 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14,618 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 17:07:14,618 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:14,620 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=D0342ACA6C374ED4A4795A2CCB25BBEA, physicalEdgeCount=1, inputClassName=org.apache.tez.mapreduce.input.MRInput }
2016-01-14 17:07:14,620 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 17:07:14,621 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: D0342ACA6C374ED4A4795A2CCB25BBEA
2016-01-14 17:07:14,621 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: INPUT, componentVertexName: D0342ACA6C374ED4A4795A2CCB25BBEA
2016-01-14 17:07:14,624 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:14,624 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=BAB29A0C0F47400BA934EABCD6936D13, physicalEdgeCount=1, outputClassName=org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput }
2016-01-14 17:07:14,625 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 17:07:14,626 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: BAB29A0C0F47400BA934EABCD6936D13
2016-01-14 17:07:14,627 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452791234308_0001_1_00_000000_0 sent events: (0-1)
2016-01-14 17:07:14,628 INFO input.MRInput (MRInput.java:initialize(440)) - Using New mapreduce API: false, split information via event: true
2016-01-14 17:07:14,629 INFO input.MRInput (MRInput.java:initializeInternal(493)) - Initialzed MRInput: D0342ACA6C374ED4A4795A2CCB25BBEA
2016-01-14 17:07:14,629 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: D0342ACA6C374ED4A4795A2CCB25BBEA
2016-01-14 17:07:14,631 INFO impl.ExternalSorter (ExternalSorter.java:getInitialMemoryRequirement(293)) - Requested SortBufferSize (tez.runtime.io.sort.mb): 100
2016-01-14 17:07:14,631 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 104857600, type: OUTPUT, componentVertexName: BAB29A0C0F47400BA934EABCD6936D13
2016-01-14 17:07:14,631 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: BAB29A0C0F47400BA934EABCD6936D13
2016-01-14 17:07:14,639 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 17:07:14,651 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: D368BDDE74DF427B9EB53272109643D9, ordinal: 0
2016-01-14 17:07:14,652 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D368BDDE74DF427B9EB53272109643D9, mem on start (mb), free: 251, total: 397, max: 672
2016-01-14 17:07:14,652 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:14,652 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 17:07:14,653 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 17:07:14,653 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 17:07:14,653 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 17:07:14,654 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.input.MRInput
2016-01-14 17:07:14,654 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:07:14,655 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_OUTPUT
2016-01-14 17:07:14,655 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 17:07:14,655 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-01-14 17:07:14,656 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, D0342ACA6C374ED4A4795A2CCB25BBEA, org.apache.tez.mapreduce.input.MRInput: requested=0, allocated=0
2016-01-14 17:07:14,656 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, BAB29A0C0F47400BA934EABCD6936D13, org.apache.tez.runtime.library.output.OrderedPartitionedKVOutput: requested=104857600, allocated=104857600
2016-01-14 17:07:14,656 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 17:07:14,656 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: D0342ACA6C374ED4A4795A2CCB25BBEA being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 17:07:14,657 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: D0342ACA6C374ED4A4795A2CCB25BBEA
2016-01-14 17:07:14,657 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:07:14,657 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: D0342ACA6C374ED4A4795A2CCB25BBEA
2016-01-14 17:07:14,658 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 17:07:14,658 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 17:07:14,659 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 17:07:14,659 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14,659 INFO input.MRInput (MRInput.java:initFromEventInternal(619)) - Initializing RecordReader from event
2016-01-14 17:07:14,660 INFO input.MRInput (MRInput.java:initFromEventInternal(630)) - Split Details -> SplitClass: org.apache.hadoop.mapred.split.TezGroupedSplit, OldSplit: org.apache.hadoop.mapred.split.TezGroupedSplit@5ffdf59f
2016-01-14 17:07:14,662 INFO lib.MRReaderMapred (MRReaderMapred.java:setIncrementalConfigParams(163)) - Processing split: org.apache.hadoop.mapred.split.TezGroupedSplit@5ffdf59f
2016-01-14 17:07:14,662 INFO input.MRInput (MRInput.java:initFromEventInternal(634)) - Initialized RecordReader from event
2016-01-14 17:07:14,662 INFO input.MRInput (MRInput.java:processSplitEvent(586)) - Notifying on RecordReader Initialized
2016-01-14 17:07:14,664 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:07:14,665 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"] streamed: true, id: D0342ACA6C374ED4A4795A2CCB25BBEA
2016-01-14 17:07:14,665 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: GroupBy(test)[by:[{1}:'ip']], id: 6BD010CE1014458D8EB483E26FDA0B10
2016-01-14 17:07:14,666 INFO element.TezGroupGate (TezGroupGate.java:prepare(96)) - calling OrderedPartitionedKVOutput#start() on: GroupBy(test)[by:[{1}:'ip']] 6BD010CE1014458D8EB483E26FDA0B10
2016-01-14 17:07:14,667 INFO impl.ExternalSorter (ExternalSorter.java:<init>(167)) - keySerializer=cascading.tuple.hadoop.io.TupleSerializer@dc3efb6; valueSerializer=cascading.tuple.hadoop.io.TupleSerializer@3aae9cc9; comparator=cascading.tuple.hadoop.util.TupleComparator@1db76e38; 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-01-14 17:07:14,668 INFO impl.ExternalSorter (ExternalSorter.java:<init>(224)) - Instantiating Partitioner: [cascading.tuple.tez.util.TuplePartitioner]
2016-01-14 17:07:14,668 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiatePartitioner(109)) - Using partitioner class: cascading.tuple.tez.util.TuplePartitioner
2016-01-14 17:07:14,668 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 17:07:14,683 INFO dflt.DefaultSorter (DefaultSorter.java:setEquator(328)) - (EQUATOR) 0 kvi 26214396(104857584)
2016-01-14 17:07:14,683 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(150)) - tez.runtime.io.sort.mb: 100
2016-01-14 17:07:14,684 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(151)) - soft limit at 83886080
2016-01-14 17:07:14,684 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(152)) - bufstart = 0; bufvoid = 104857600
2016-01-14 17:07:14,684 INFO dflt.DefaultSorter (DefaultSorter.java:<init>(153)) - kvstart = 26214396; length = 6553600
2016-01-14 17:07:14,686 INFO element.TezSourceStage (TezSourceStage.java:prepare(63)) - calling MRInput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/classes/test/data/apache.10.txt"]
2016-01-14 17:07:14,686 INFO input.MRInput (MRInput.java:start(450)) - MRInput setup to received events1
2016-01-14 17:07:14,686 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: D368BDDE74DF427B9EB53272109643D9, all 1 inputs ready in: 00:00:00.000
2016-01-14 17:07:14,690 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14,690 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: D368BDDE74DF427B9EB53272109643D9, mem on close (mb), free: 148, total: 397, max: 672
2016-01-14 17:07:14,690 INFO dflt.DefaultSorter (DefaultSorter.java:flush(589)) - Starting flush of map output
2016-01-14 17:07:14,691 INFO dflt.DefaultSorter (DefaultSorter.java:flush(607)) - Sorting & Spilling map output
2016-01-14 17:07:14,692 INFO dflt.DefaultSorter (DefaultSorter.java:flush(608)) - bufstart = 0; bufend = 210; bufvoid = 104857600
2016-01-14 17:07:14,692 INFO dflt.DefaultSorter (DefaultSorter.java:flush(610)) - kvstart = 26214396(104857584); kvend = 26214360(104857440); length = 37/6553600
2016-01-14 17:07:14,697 INFO dflt.DefaultSorter (DefaultSorter.java:spill(829)) - Finished spill 0
2016-01-14 17:07:14 Completed running task attempt: attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14,703 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452791234308_0001_1_00_000000_0, fatalErrorOccurred=false
2016-01-14 17:07:14,704 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=1452791234687, Process_Duration=3, Process_End_Time=1452791234690, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0][cascading.flow.StepCounters Tuples_Read=10]]
2016-01-14 17:07:14,704 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:VERTEX_DATA_MOVEMENT_EVENTS_GENERATED]: vertexId=vertex_1452791234308_0001_1_00, eventCount=1
2016-01-14 17:07:14,704 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 17:07:14,706 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:14,705 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 17:07:14,706 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=D368BDDE74DF427B9EB53272109643D9, taskAttemptId=attempt_1452791234308_0001_1_00_000000_0, startTime=1452791234609, finishTime=1452791234705, timeTaken=96, 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=1452791234687, Process_Duration=3, Process_End_Time=1452791234690, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 17:07:14,707 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791234308_0001_1_00_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 17:07:14,707 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452791234308_0001_1_00_000000_0
2016-01-14 17:07:14,707 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 17:07:14,706 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791234308_0001_00_000001
2016-01-14 17:07:14,709 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 17:07:14,708 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:TASK_FINISHED]: vertexName=D368BDDE74DF427B9EB53272109643D9, taskId=task_1452791234308_0001_1_00_000000, startTime=1452791234609, finishTime=1452791234707, timeTaken=98, status=SUCCEEDED, successfulAttemptID=attempt_1452791234308_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=1452791234687, Process_Duration=3, Process_End_Time=1452791234690, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10
2016-01-14 17:07:14,711 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791234308_0001_1_00_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 17:07:14,712 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] : 1
2016-01-14 17:07:14,713 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,715 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 17:07:14,716 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:VERTEX_FINISHED]: vertexName=D368BDDE74DF427B9EB53272109643D9, vertexId=vertex_1452791234308_0001_1_00, initRequestedTime=1452791234560, initedTime=1452791234583, startRequestedTime=1452791234585, startedTime=1452791234585, finishTime=1452791234713, timeTaken=128, 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=1452791234687, Process_Duration=3, Process_End_Time=1452791234690, Read_Duration=2, Tuples_Read=10, Tuples_Written=10, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, vertexStats=firstTaskStartTime=1452791234609, firstTasksToStart=[ task_1452791234308_0001_1_00_000000 ], lastTaskFinishTime=1452791234705, lastTasksToFinish=[ task_1452791234308_0001_1_00_000000 ], minTaskDuration=96, maxTaskDuration=96, avgTaskDuration=96.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452791234308_0001_1_00_000000 ], longestDurationTasks=[ task_1452791234308_0001_1_00_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 17:07:14,717 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 17:07:14,717 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000001 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 17:07:14,717 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452791234308_0001_00_000001, stoppedTime=1452791234717, exitStatus=0
2016-01-14 17:07:14,717 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000001 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 17:07:14,718 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 17:07:14,718 INFO impl.VertexImpl (VertexImpl.java:transition(3477)) - Source task attempt completed for vertex: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13] attempt: attempt_1452791234308_0001_1_00_000000_0 with state: SUCCEEDED vertexState: RUNNING
2016-01-14 17:07:14,718 INFO vertexmanager.ShuffleVertexManager (ShuffleVertexManager.java:schedulePendingTasks(608)) - All source tasks assigned. Ramping up 1 remaining tasks for vertex: BAB29A0C0F47400BA934EABCD6936D13
2016-01-14 17:07:14,718 INFO impl.VertexImpl (VertexImpl.java:scheduleTasks(1250)) - Routing pending task events for vertex: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,718 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9] completed., numCompletedVertices=1, numSuccessfulVertices=1, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-01-14 17:07:14,719 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(244)) - Ignoring stop request for containerId container_1452791234308_0001_00_000001. Relying on regular task shutdown for it to end
2016-01-14 17:07:14,719 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_STARTED to history file
2016-01-14 17:07:14,719 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:TASK_STARTED]: vertexName=BAB29A0C0F47400BA934EABCD6936D13, taskId=task_1452791234308_0001_1_01_000000, scheduledTime=1452791234719, launchTime=1452791234719
2016-01-14 17:07:14,719 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791234308_0001_1_01_000000 Task Transitioned from NEW to SCHEDULED due to event T_SCHEDULE
2016-01-14 17:07:14,720 INFO impl.DAGSchedulerNaturalOrderControlled (DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,720 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000001 transitioned from STOP_REQUESTED to STOPPING via event C_NM_STOP_SENT
2016-01-14 17:07:14,720 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1014)) - remoteTaskSpec:DAGName : [5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0] null/(1/1) ...testSimpleAssembly/simple, VertexName: BAB29A0C0F47400BA934EABCD6936D13, VertexParallelism: 1, TaskAttemptID:attempt_1452791234308_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D368BDDE74DF427B9EB53272109643D9, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=010EFFEA5FBC443D80CC9DCC3321187E, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:07:14,720 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791234308_0001_1_01_000000_0 TaskAttempt Transitioned from NEW to START_WAIT due to event TA_SCHEDULE
2016-01-14 17:07:14,721 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_LAUNCH_REQUEST
2016-01-14 17:07:14,722 INFO container.AMContainerImpl (AMContainerImpl.java:transition(521)) - Sending Launch Request for Container with id: container_1452791234308_0001_00_000002
2016-01-14 17:07:14,722 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452791234308_0001_00_000001 is valid, but no longer registered, and will be killed
2016-01-14 17:07:14,722 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000002 transitioned from ALLOCATED to LAUNCHING via event C_LAUNCH_REQUEST
2016-01-14 17:07:14,722 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791234308_0001_00_000001: 10 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 17:07:14,723 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452791234308_0001_00_000001, Exiting
2016-01-14 17:07:14,723 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452791234308_0001_00_000001
2016-01-14 17:07:14,723 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452791234308_0001_00_000001
2016-01-14 17:07:14,725 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452791234308_0001_00_000001 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 17:07:14,725 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452791234308_0001_00_000001 completed successfully
2016-01-14 17:07:14,725 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000001 transitioned from STOPPING to COMPLETED via event C_COMPLETED
2016-01-14 17:07:14,726 INFO task.TezChild (TezChild.java:newTezChild(432)) - PID, containerIdentifier: null, container_1452791234308_0001_00_000002
2016-01-14 17:07:14,727 WARN impl.MetricsConfig (MetricsConfig.java:loadFirst(124)) - Cannot locate configuration: tried hadoop-metrics2-teztask.properties,hadoop-metrics2.properties
2016-01-14 17:07:14,732 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000002 transitioned from LAUNCHING to IDLE via event C_LAUNCHED
2016-01-14 17:07:14,732 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:CONTAINER_LAUNCHED]: containerId=container_1452791234308_0001_00_000002, launchTime=1452791234731
2016-01-14 17:07:14,732 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_LAUNCHED to history file
2016-01-14 17:07:14,732 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791234308_0001_00_000002
2016-01-14 17:07:14,734 INFO container.AMContainerImpl (AMContainerImpl.java:transition(827)) - Assigned taskAttempt + [attempt_1452791234308_0001_1_01_000000_0] to container: [container_1452791234308_0001_00_000002]
2016-01-14 17:07:14,734 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000002 transitioned from IDLE to RUNNING via event C_PULL_TA
2016-01-14 17:07:14,735 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(240)) - Container with id: container_1452791234308_0001_00_000002 given task: attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,735 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791234308_0001_00_000002: 0 ms after starting to poll. TaskInfo: shouldDie: false, currentTaskAttemptId: attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,735 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1146)) - TaskAttempt: [attempt_1452791234308_0001_1_01_000000_0] started. Is using containerId: [container_1452791234308_0001_00_000002] on NM: [127.0.0.1:0]
2016-01-14 17:07:14 Starting to run new task attempt: attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,736 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:TASK_ATTEMPT_STARTED]: vertexName=BAB29A0C0F47400BA934EABCD6936D13, taskAttemptId=attempt_1452791234308_0001_1_01_000000_0, startTime=1452791234735, containerId=container_1452791234308_0001_00_000002, nodeId=127.0.0.1:0, inProgressLogs=127.0.0.1:0/node/containerlogs/container_1452791234308_0001_00_000002/teamcity, completedLogs=
2016-01-14 17:07:14,736 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,736 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_STARTED to history file
2016-01-14 17:07:14,736 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:14,736 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(273)) - Refreshing UGI since Credentials have changed
2016-01-14 17:07:14,736 INFO task.TezChild (TezChild.java:handleNewTaskCredentials(276)) - Credentials : #Tokens=1, #SecretKeys=0
2016-01-14 17:07:14,736 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(302)) - Localizing additional local resources for Task : {}
2016-01-14 17:07:14,736 INFO task.TezChild (TezChild.java:handleNewTaskLocalResources(312)) - Done localizing additional resources
2016-01-14 17:07:14,736 INFO metrics.TaskCounterUpdater (TaskCounterUpdater.java:initResourceCalculatorPlugin(148)) - Using ResourceCalculatorProcessTree : [ ]
2016-01-14 17:07:14,737 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:<init>(149)) - Initializing LogicalIOProcessorRuntimeTask with TaskSpec: DAGName : [5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0] null/(1/1) ...testSimpleAssembly/simple, VertexName: BAB29A0C0F47400BA934EABCD6936D13, VertexParallelism: 1, TaskAttemptID:attempt_1452791234308_0001_1_01_000000_0, processorName=cascading.flow.tez.FlowProcessor, inputSpecListSize=1, outputSpecListSize=1, inputSpecList=[{{ sourceVertexName=D368BDDE74DF427B9EB53272109643D9, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }}, ], outputSpecList=[{{ destinationVertexName=010EFFEA5FBC443D80CC9DCC3321187E, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }}, ]
2016-01-14 17:07:14,737 INFO resources.MemoryDistributor (MemoryDistributor.java:<init>(85)) - InitialMemoryDistributor (isEnabled=true) invoked with: numInputs=1, numOutputs=1, JVM.maxFree=704643072
2016-01-14 17:07:14,736 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791234308_0001_1_01_000000_0 TaskAttempt Transitioned from START_WAIT to RUNNING due to event TA_STARTED_REMOTELY
2016-01-14 17:07:14,738 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791234308_0001_1_01_000000 Task Transitioned from SCHEDULED to RUNNING due to event T_ATTEMPT_LAUNCHED
2016-01-14 17:07:14,739 INFO task.TezTaskRunner (TezTaskRunner.java:run(172)) - Initializing task, taskAttemptId=attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,740 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(191)) - Initializing LogicalProcessorIORuntimeTask
2016-01-14 17:07:14,742 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(195)) - Creating processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:14,743 INFO impl.TaskImpl (TaskImpl.java:getTaskAttemptTezEvents(481)) - TaskAttempt:attempt_1452791234308_0001_1_01_000000_0 sent events: (0-1)
2016-01-14 17:07:14,744 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(389)) - Initializing Input using InputSpec: { sourceVertexName=D368BDDE74DF427B9EB53272109643D9, physicalEdgeCount=1, inputClassName=org.apache.tez.runtime.library.input.OrderedGroupedKVInput }
2016-01-14 17:07:14,744 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(438)) - Initializing Output using OutputSpec: { destinationVertexName=010EFFEA5FBC443D80CC9DCC3321187E, physicalEdgeCount=0, outputClassName=org.apache.tez.mapreduce.output.MROutput }
2016-01-14 17:07:14,744 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(488)) - Initializing processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:14,745 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createInput(537)) - Creating Input
2016-01-14 17:07:14,745 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(397)) - Initializing Input with src edge: D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,750 INFO tez.FlowProcessor (FlowProcessor.java:initialize(88)) - cascading version: 3.0.4
2016-01-14 17:07:14,755 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(310)) - Initial Shuffle Memory Required: 634178752, based on INPUT_BUFFER_factor: 0.9
2016-01-14 17:07:14,755 INFO orderedgrouped.MergeManager (MergeManager.java:getInitialMemoryRequirement(320)) - Initial Memory required for final merged output: 0, using factor: 0.0
2016-01-14 17:07:14,756 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 634178752, type: INPUT, componentVertexName: D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,758 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(403)) - Initialized Input with src edge: D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,760 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:createOutput(565)) - Creating Output
2016-01-14 17:07:14,760 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(446)) - Initializing Output with dest edge: 010EFFEA5FBC443D80CC9DCC3321187E
2016-01-14 17:07:14,760 INFO output.MROutput (MROutput.java:initialize(347)) - Initializing Simple Output
2016-01-14 17:07:14,761 INFO resources.MemoryDistributor$RequestorInfo (MemoryDistributor.java:<init>(233)) - Received request: 0, type: OUTPUT, componentVertexName: 010EFFEA5FBC443D80CC9DCC3321187E
2016-01-14 17:07:14,772 INFO tez.FlowProcessor (FlowProcessor.java:initialize(94)) - flow node id: BAB29A0C0F47400BA934EABCD6936D13, ordinal: 1
2016-01-14 17:07:14,772 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: BAB29A0C0F47400BA934EABCD6936D13, mem on start (mb), free: 140, total: 397, max: 672
2016-01-14 17:07:14,772 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initializeLogicalIOProcessor(491)) - Initialized processor, processorClassName=cascading.flow.tez.FlowProcessor
2016-01-14 17:07:14,772 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 2 initializers to finish
2016-01-14 17:07:14,773 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(220)) - Waiting for 1 initializers to finish
2016-01-14 17:07:14,783 INFO output.MROutput (MROutput.java:initialize(418)) - Initialized Simple Output, using_new_api: false
2016-01-14 17:07:14,783 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(452)) - Initialized Output with dest edge: 010EFFEA5FBC443D80CC9DCC3321187E
2016-01-14 17:07:14,784 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(233)) - All initializers finished
2016-01-14 17:07:14,784 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(124)) - Using Allocator class: org.apache.tez.runtime.library.resources.WeightedScalingMemoryDistributor
2016-01-14 17:07:14,784 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 12, for type: SORTED_MERGED_INPUT
2016-01-14 17:07:14,784 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:getRequestTypeForClass(197)) - Falling back to RequestType.OTHER for class: org.apache.tez.mapreduce.output.MROutput
2016-01-14 17:07:14,784 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:initialProcessMemoryRequestContext(171)) - ScaleFactor: 1, for type: OTHER
2016-01-14 17:07:14,785 INFO resources.WeightedScalingMemoryDistributor (WeightedScalingMemoryDistributor.java:computeReservedFraction(262)) - InitialReservationFraction=0.3, AdditionalReservationFractionForIOs=0.03, finalReserveFractionUsed=0.32999999999999996
2016-01-14 17:07:14,785 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-01-14 17:07:14,785 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: INPUT, D368BDDE74DF427B9EB53272109643D9, org.apache.tez.runtime.library.input.OrderedGroupedKVInput: requested=634178752, allocated=472110858
2016-01-14 17:07:14,785 INFO resources.MemoryDistributor (MemoryDistributor.java:makeInitialAllocations(138)) - Informing: OUTPUT, 010EFFEA5FBC443D80CC9DCC3321187E, org.apache.tez.mapreduce.output.MROutput: requested=0, allocated=0
2016-01-14 17:07:14,785 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(255)) - Starting Inputs/Outputs
2016-01-14 17:07:14,785 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(268)) - Input: D368BDDE74DF427B9EB53272109643D9 being auto started by the framework. Subsequent instances will not be auto-started
2016-01-14 17:07:14,785 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(419)) - Starting Input with src edge: D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,785 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(289)) - Num IOs determined for AutoStart: 1
2016-01-14 17:07:14,786 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(291)) - Waiting for 1 IOs to start
2016-01-14 17:07:14,787 INFO common.TezRuntimeUtils (TezRuntimeUtils.java:instantiateCombiner(65)) - No combiner specified via tez.runtime.combiner.class. Combiner will not be used
2016-01-14 17:07:14,788 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(182)) - Shuffle assigned with 1 inputs, codec: NoneifileReadAhead: true
2016-01-14 17:07:14,788 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:<init>(158)) - ShuffleScheduler running for sourceVertex: D368BDDE74DF427B9EB53272109643D9 with configuration: maxFetchFailuresBeforeReporting=5, reportReadErrorImmediately=true, maxFailedUniqueFetches=1, abortFailureLimit=30, maxMapRuntime=0, maxTaskOutputAtOnce=20
2016-01-14 17:07:14,789 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(221)) - InitialRequest: ShuffleMem=634178752, postMergeMem=0, RuntimeTotalAvailable=472110858. Updated to: ShuffleMem=472110858, postMergeMem: 0
2016-01-14 17:07:14,789 INFO orderedgrouped.MergeManager (MergeManager.java:<init>(252)) - MergerManager: memoryLimit=472110858, maxSingleShuffleLimit=118027712, mergeThreshold=424899744, ioSortFactor=100, memToMemMergeOutputsThreshold=100
2016-01-14 17:07:14,789 INFO orderedgrouped.Shuffle (Shuffle.java:<init>(233)) - Num fetchers being started: 1
2016-01-14 17:07:14,791 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:call(421)) - Started Input with src edge: D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,795 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:initialize(304)) - AutoStartComplete
2016-01-14 17:07:14,796 INFO task.TezTaskRunner (TezTaskRunner.java:run(175)) - Running task, taskAttemptId=attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,796 INFO orderedgrouped.ShuffleInputEventHandlerOrderedGrouped (ShuffleInputEventHandlerOrderedGrouped.java:processDataMovementEvent(84)) - DME srcIdx: 0, targetIdx: 0, attemptNum: 0, payload: [host: ip-10-187-41-40, port: 0, pathComponent: attempt_1452791234308_0001_1_00_000000_0_10009, runDuration: 73993, ]
2016-01-14 17:07:14,800 INFO graph.Hadoop2TezStreamGraph (Hadoop2TezStreamGraph.java:buildGraph(151)) - using streamed source: GroupBy(test)[by:[{1}:'ip']]
2016-01-14 17:07:14,801 INFO tez.FlowProcessor (FlowProcessor.java:run(121)) - sourcing from: GroupBy(test)[by:[{1}:'ip']] streamed: true, id: 6BD010CE1014458D8EB483E26FDA0B10
2016-01-14 17:07:14,802 INFO tez.FlowProcessor (FlowProcessor.java:run(124)) - sinking to: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple"], id: 010EFFEA5FBC443D80CC9DCC3321187E
2016-01-14 17:07:14,802 INFO element.TezSinkStage (TezSinkStage.java:prepare(57)) - calling MROutput#start() on: Hfs["TextLine[['offset', 'line']->[ALL]]"]["/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output/hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple"]
2016-01-14 17:07:14,803 INFO element.TezGroupGate (TezGroupGate.java:prepare(88)) - calling OrderedGroupedKVInput#start() on: GroupBy(test)[by:[{1}:'ip']] 6BD010CE1014458D8EB483E26FDA0B10, for 1 inputs
2016-01-14 17:07:14,803 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logIndividualFetchComplete(250)) - Completed fetch for attempt: InputAttemptIdentifier [inputIdentifier=InputIdentifier [inputIndex=0], attemptNumber=0, pathComponent=attempt_1452791234308_0001_1_00_000000_0_10009] to DISK_DIRECT, CompressedSize=204, DecompressedSize=200,EndTime=1452791234803, TimeTaken=5, Rate=0.04 MB/s
2016-01-14 17:07:14,803 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:copySucceeded(213)) - All inputs fetched for input vertex : D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,804 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:logProgress(263)) - copy(1 of 1. Transfer rate (CumulativeDataFetched/TimeSinceInputStarted)) 0.00 MB/s)
2016-01-14 17:07:14,804 INFO orderedgrouped.ShuffleScheduler (ShuffleScheduler.java:freeHost(529)) - ip-10-187-41-40:0 freed by fetcher [D368BDDE74DF427B9EB53272109643D9] #2 in 6ms
2016-01-14 17:07:14,804 INFO orderedgrouped.Shuffle (Shuffle.java:cleanupFetchers(394)) - Shutdown..fetcher [D368BDDE74DF427B9EB53272109643D9] #2, status:false, isInterrupted:false
2016-01-14 17:07:14,805 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 1 on-disk map-outputs
2016-01-14 17:07:14,805 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 1 files, 204 bytes from disk
2016-01-14 17:07:14,806 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 17:07:14,806 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 1 sorted segments
2016-01-14 17:07:14,807 INFO impl.TezMerger (TezMerger.java:merge(665)) - Down to the last merge-pass, with 1 segments left of total size: 175 bytes
2016-01-14 17:07:14,807 INFO orderedgrouped.Shuffle (Shuffle.java:call(381)) - merge complete for input vertex : D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,807 INFO orderedgrouped.Shuffle (Shuffle.java:onSuccess(488)) - Shuffle Runner thread complete
2016-01-14 17:07:14,807 INFO tez.FlowProcessor (FlowProcessor.java:waitForInputsReady(202)) - flow node id: BAB29A0C0F47400BA934EABCD6936D13, all 1 inputs ready in: 00:00:00.004
2016-01-14 17:07:14,808 INFO common.ValuesIterator (ValuesIterator.java:<init>(83)) - keyDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@64e3f1e4; valueDeserializer=cascading.tuple.hadoop.io.TupleDeserializer@311de37b
2016-01-14 17:07:14,811 INFO output.MROutput (MROutput.java:flush(534)) - Flushing Simple Output
2016-01-14 17:07:14,812 INFO output.MROutput (MROutput.java:flush(544)) - Flushed Simple Output
2016-01-14 17:07:14,813 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:canCommit(353)) - Commit go/no-go request from attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,813 INFO impl.TaskImpl (TaskImpl.java:canCommit(750)) - attempt_1452791234308_0001_1_01_000000_0 given a go for committing the task output.
2016-01-14 17:07:14,815 INFO task.TezTaskRunner (TezTaskRunner.java:run(177)) - Closing task, taskAttemptId=attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,815 INFO tez.FlowProcessor (LogUtil.java:logMemory(59)) - flow node id: BAB29A0C0F47400BA934EABCD6936D13, mem on close (mb), free: 135, total: 397, max: 672
2016-01-14 17:07:14,815 INFO orderedgrouped.Shuffle (Shuffle.java:shutdown(320)) - Shutting down Shuffle for source: D368BDDE74DF427B9EB53272109643D9
2016-01-14 17:07:14,817 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(854)) - finalMerge called with 0 in-memory map-outputs and 0 on-disk map-outputs
2016-01-14 17:07:14,817 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(951)) - Merging 0 files, 0 bytes from disk
2016-01-14 17:07:14,817 INFO orderedgrouped.MergeManager (MergeManager.java:finalMerge(966)) - Merging 0 segments, 0 bytes from memory into reduce
2016-01-14 17:07:14,817 INFO impl.TezMerger (TezMerger.java:merge(560)) - Merging 0 sorted segments
2016-01-14 17:07:14,817 INFO impl.TezMerger (TezMerger.java:merge(562)) - Nothing to merge. Returning an empty iterator
2016-01-14 17:07:14 Completed running task attempt: attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,818 INFO task.TezTaskRunner (TezTaskRunner.java:run(181)) - Task completed, taskAttemptId=attempt_1452791234308_0001_1_01_000000_0, fatalErrorOccurred=false
2016-01-14 17:07:14,820 INFO runtime.LogicalIOProcessorRuntimeTask (LogicalIOProcessorRuntimeTask.java:cleanup(712)) - Final Counters : Counters: 46 [[File System Counters FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=298, 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=16, MERGE_PHASE_TIME=19, FIRST_EVENT_RECEIVED=9, LAST_EVENT_RECEIVED=9][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=1452791234807, Process_Duration=8, Process_End_Time=1452791234815, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0][cascading.flow.StepCounters Tuples_Written=8]]
2016-01-14 17:07:14,820 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_ATTEMPT_FINISHED to history file
2016-01-14 17:07:14,820 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend:
2016-01-14 17:07:14,821 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:14,822 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=BAB29A0C0F47400BA934EABCD6936D13, taskAttemptId=attempt_1452791234308_0001_1_01_000000_0, startTime=1452791234735, finishTime=1452791234820, timeTaken=85, status=SUCCEEDED, errorEnum=, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=298, 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=16, MERGE_PHASE_TIME=19, FIRST_EVENT_RECEIVED=9, LAST_EVENT_RECEIVED=9, 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=1452791234807, Process_Duration=8, Process_End_Time=1452791234815, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-01-14 17:07:14,823 INFO task.ContainerReporter (ContainerReporter.java:call(55)) - Attempting to fetch new task for container container_1452791234308_0001_00_000002
2016-01-14 17:07:14,823 INFO impl.TaskAttemptImpl (TaskAttemptImpl.java:handle(692)) - attempt_1452791234308_0001_1_01_000000_0 TaskAttempt Transitioned from RUNNING to SUCCEEDED due to event TA_DONE
2016-01-14 17:07:14,823 INFO impl.TaskImpl (TaskImpl.java:transition(1052)) - Task succeeded with attempt attempt_1452791234308_0001_1_01_000000_0
2016-01-14 17:07:14,824 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event TASK_FINISHED to history file
2016-01-14 17:07:14,825 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:handleEvent(149)) - Processing the event EventType: S_TA_ENDED
2016-01-14 17:07:14,826 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:TASK_FINISHED]: vertexName=BAB29A0C0F47400BA934EABCD6936D13, taskId=task_1452791234308_0001_1_01_000000, startTime=1452791234735, finishTime=1452791234823, timeTaken=88, status=SUCCEEDED, successfulAttemptID=attempt_1452791234308_0001_1_01_000000_0, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=298, 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=16, MERGE_PHASE_TIME=19, FIRST_EVENT_RECEIVED=9, LAST_EVENT_RECEIVED=9, 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=1452791234807, Process_Duration=8, Process_End_Time=1452791234815, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8
2016-01-14 17:07:14,826 INFO impl.TaskImpl (TaskImpl.java:handle(862)) - task_1452791234308_0001_1_01_000000 Task Transitioned from RUNNING to SUCCEEDED due to event T_ATTEMPT_SUCCEEDED
2016-01-14 17:07:14,827 INFO impl.VertexImpl (VertexImpl.java:transition(3536)) - Num completed Tasks for vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13] : 1
2016-01-14 17:07:14,827 INFO impl.VertexImpl (VertexImpl.java:checkVertexForCompletion(1674)) - Vertex succeeded: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,829 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event VERTEX_FINISHED to history file
2016-01-14 17:07:14,831 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:VERTEX_FINISHED]: vertexName=BAB29A0C0F47400BA934EABCD6936D13, vertexId=vertex_1452791234308_0001_1_01, initRequestedTime=1452791234562, initedTime=1452791234580, startRequestedTime=1452791234594, startedTime=1452791234594, finishTime=1452791234827, timeTaken=233, status=SUCCEEDED, diagnostics=, counters=Counters: 46, File System Counters, FILE_BYTES_READ=236, FILE_BYTES_WRITTEN=298, 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=16, MERGE_PHASE_TIME=19, FIRST_EVENT_RECEIVED=9, LAST_EVENT_RECEIVED=9, 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=1452791234807, Process_Duration=8, Process_End_Time=1452791234815, Read_Duration=1, Tuples_Read=10, Tuples_Written=8, Write_Duration=0, cascading.flow.StepCounters, Tuples_Written=8, vertexStats=firstTaskStartTime=1452791234735, firstTasksToStart=[ task_1452791234308_0001_1_01_000000 ], lastTaskFinishTime=1452791234820, lastTasksToFinish=[ task_1452791234308_0001_1_01_000000 ], minTaskDuration=85, maxTaskDuration=85, avgTaskDuration=85.0, numSuccessfulTasks=1, shortestDurationTasks=[ task_1452791234308_0001_1_01_000000 ], longestDurationTasks=[ task_1452791234308_0001_1_01_000000 ], vertexTaskStats={numFailedTasks=0, numSucceededTasks=1, numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0, numCompletedTasks=1}
2016-01-14 17:07:14,832 INFO impl.VertexImpl (VertexImpl.java:handle(1564)) - vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13] transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2016-01-14 17:07:14,833 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000002 transitioned from RUNNING to IDLE via event C_TA_SUCCEEDED
2016-01-14 17:07:14,833 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event CONTAINER_STOPPED to history file
2016-01-14 17:07:14,833 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:CONTAINER_STOPPED]: containerId=container_1452791234308_0001_00_000002, stoppedTime=1452791234833, exitStatus=0
2016-01-14 17:07:14,834 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000002 transitioned from IDLE to STOP_REQUESTED via event C_STOP_REQUEST
2016-01-14 17:07:14,835 INFO impl.DAGImpl (DAGImpl.java:transition(1747)) - Vertex vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13] completed., numCompletedVertices=2, numSuccessfulVertices=2, numFailedVertices=0, numKilledVertices=0, numVertices=2
2016-01-14 17:07:14,835 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(831)) - Calling DAG commit/abort for dag: dag_1452791234308_0001_1
2016-01-14 17:07:14,836 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:DAG_COMMIT_STARTED]: dagID=dag_1452791234308_0001_1
2016-01-14 17:07:14,837 INFO app.TaskAttemptListenerImpTezDag (TaskAttemptListenerImpTezDag.java:getTask(213)) - Container with id: container_1452791234308_0001_00_000002 is valid, but no longer registered, and will be killed
2016-01-14 17:07:14,837 INFO task.ContainerReporter (ContainerReporter.java:call(65)) - Got TaskUpdate for containerId= container_1452791234308_0001_00_000002: 14 ms after starting to poll. TaskInfo: shouldDie: true
2016-01-14 17:07:14,837 INFO task.TezChild (TezChild.java:run(207)) - ContainerTask returned shouldDie=true for container container_1452791234308_0001_00_000002, Exiting
2016-01-14 17:07:14,837 INFO task.TezChild (TezChild.java:shutdown(343)) - Shutdown invoked for container container_1452791234308_0001_00_000002
2016-01-14 17:07:14,838 INFO task.TezChild (TezChild.java:shutdown(345)) - Shutting down container container_1452791234308_0001_00_000002
2016-01-14 17:07:14,837 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(892)) - Committing output: 010EFFEA5FBC443D80CC9DCC3321187E for vertex: vertex_1452791234308_0001_1_01 [BAB29A0C0F47400BA934EABCD6936D13]
2016-01-14 17:07:14,838 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(270)) - ContainerExecutionResult for: container_1452791234308_0001_00_000002 = ContainerExecutionResult{exitStatus=SUCCESS, throwable=null, errorMessage='Asked to die by the AM'}
2016-01-14 17:07:14,839 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:onSuccess(274)) - Container: container_1452791234308_0001_00_000002 completed successfully
2016-01-14 17:07:14,854 INFO impl.DAGImpl (DAGImpl.java:commitOrAbortOutputs(871)) - No output committers for vertex: vertex_1452791234308_0001_1_00 [D368BDDE74DF427B9EB53272109643D9]
2016-01-14 17:07:14,856 INFO recovery.RecoveryService (RecoveryService.java:handle(306)) - DAG completed, dagId=dag_1452791234308_0001_1, queueSize=0
2016-01-14 17:07:14,857 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:handleEvent(151)) - Writing event DAG_FINISHED to history file
2016-01-14 17:07:14,857 INFO history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(110)) - [HISTORY][DAG:dag_1452791234308_0001_1][Event:DAG_FINISHED]: dagId=dag_1452791234308_0001_1, startTime=1452791234559, finishTime=1452791234854, timeTaken=295, 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=534, 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=16, MERGE_PHASE_TIME=19, FIRST_EVENT_RECEIVED=9, LAST_EVENT_RECEIVED=9, 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=2905582469494, Process_Duration=11, Process_End_Time=2905582469505, Read_Duration=3, Tuples_Read=20, Tuples_Written=18, Write_Duration=0, cascading.flow.StepCounters, Tuples_Read=10, Tuples_Written=8
2016-01-14 17:07:14,857 INFO impl.DAGImpl (DAGImpl.java:finished(1180)) - DAG: dag_1452791234308_0001_1 finished with state: SUCCEEDED
2016-01-14 17:07:14,858 INFO impl.DAGImpl (DAGImpl.java:handle(973)) - dag_1452791234308_0001_1 transitioned from RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2016-01-14 17:07:14,858 INFO launcher.LocalContainerLauncher (LocalContainerLauncher.java:stop(242)) - Ignoring stop request for containerId: container_1452791234308_0001_00_000002
2016-01-14 17:07:14,858 INFO container.AMContainerImpl (AMContainerImpl.java:handle(442)) - AMContainer container_1452791234308_0001_00_000002 transitioned from STOP_REQUESTED to COMPLETED via event C_COMPLETED
2016-01-14 17:07:14 Completed Dag: dag_1452791234308_0001_1
2016-01-14 17:07:14,860 INFO app.DAGAppMaster (DAGAppMaster.java:handle(579)) - DAG completed, dagId=dag_1452791234308_0001_1, dagState=SUCCEEDED
2016-01-14 17:07:14,860 INFO common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(164)) - Redirecting log file based on addend: dag_1452791234308_0001_1_post
2016-01-14 17:07:14,860 WARN common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(179)) - Not configured with appender named: CLA. Cannot reconfigure logger output
2016-01-14 17:07:14,860 INFO app.DAGAppMaster (DAGAppMaster.java:handle(625)) - Waiting for next DAG to be submitted.
2016-01-14 17:07:14,869 INFO client.TezClient (TezClient.java:stop(495)) - Shutting down Tez Session, sessionName=(1/1) ...testSimpleAssembly/simple, applicationId=application_1452791234308_0001
2016-01-14 17:07:14,872 INFO client.DAGClientHandler (DAGClientHandler.java:shutdownAM(117)) - Received message to shutdown AM
2016-01-14 17:07:14,872 INFO rm.TaskSchedulerEventHandler (TaskSchedulerEventHandler.java:setShouldUnregisterFlag(580)) - TaskScheduler notified that it should unregister from RM
2016-01-14 17:07:14,872 INFO app.DAGAppMaster (DAGAppMaster.java:shutdownTezAM(1088)) - No current running DAG, shutting down the AM
2016-01-14 17:07:14,873 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(692)) - DAGAppMasterShutdownHandler invoked
2016-01-14 17:07:14,873 INFO app.DAGAppMaster (DAGAppMaster.java:shutdown(701)) - Handling DAGAppMaster shutdown
2016-01-14 17:07:14,874 INFO app.DAGAppMaster (DAGAppMaster.java:run(721)) - Sleeping for 5 seconds before shutting down
2016-01-14 17:07:14,874 INFO history.HistoryEventHandler (HistoryEventHandler.java:serviceStop(79)) - Stopping HistoryEventHandler
2016-01-14 17:07:14,876 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(189)) - Stopping RecoveryService
2016-01-14 17:07:14,877 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(192)) - Handle the remaining events in queue, queue size=0
2016-01-14 17:07:14,877 INFO recovery.RecoveryService (RecoveryService.java:run(166)) - EventQueue take interrupted. Returning
2016-01-14 17:07:14,878 INFO recovery.RecoveryService (RecoveryService.java:serviceStop(214)) - Closing Summary Stream
2016-01-14 17:07:14,881 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:serviceStop(118)) - Stopping SimpleHistoryLoggingService, eventQueueBacklog=0
2016-01-14 17:07:14,881 INFO impl.SimpleHistoryLoggingService (SimpleHistoryLoggingService.java:run(105)) - EventQueue take interrupted. Returning
2016-01-14 17:07:14,888 INFO app.DAGAppMaster (DAGAppMaster.java:run(1773)) - Completed deletion of tez scratch data dir, path=file:/opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/tmp/.staging/5238BC6B90DE497A94232C1D198C780D/AD7870DE9C164999B43937FF5D1CB1B0/.tez/application_1452791234308_0001
2016-01-14 17:07:14,889 INFO flow.Flow (BaseFlow.java:logInfo(1433)) - [] completed in: 00:00.607
2016-01-14 17:07:14,941 INFO cascading.PlatformTestCase (PlatformTestCase.java:tearDown(189)) - copying to local /opt/buildAgent-8.0.3/work/ca57560bc31094a7/apache-2.5.x-tez-0.6.x/build/test/output//hadoop2-tez/assemblyplannerplatform/testSimpleAssembly/simple